NetCF 3.5's Finalizer Log
The .NET Compact Framework has had several loggers (error, interop, loader, and networking) in previous versions. NetCF 3.5 introduces the finalizer logger, which is useful for performance tuning your app by identifying which objects are not being Dispose()'d before being discarded for the garbage collector. This post discusses this logger, how to enable it, use it, and it's file format.
Enable the logger
The finalizer logger is part of NetCF's logging infrastructure, and must be enabled in two places: once to enable the entire logging facility, and once more to enable the finalizer logger specifically. Why twice? Logging takes its toll on performance of all NetCF apps running on the system with logging enabled. By providing a master on/off switch for all NetCF logging as well as individual switches for the individual loggers you're interested in, we hope to make it easy for you to have your favorite set of loggers ready to go, but only activated when you want them.
The logger settings are kept in the registry of your device. Your device has no registry editor built in, so we use the Remote Registry Editor on your PC. Here are the steps:
- Start your ActiveSync connection between your development computer and your device.
- Click Start -> All Programs -> Microsoft Visual Studio 2005 -> Visual Studio Remote Tools -> Remote Registry Editor.
- In the "Select a Windows CE Device" dialog, select your device (or emulated device). Click OK.
- In the left pane, drill down through HKEY_LOCAL_MACHINE to the Software\Microsoft\.NETCompactFramework\Diagnostics\Logging key. If you have never used logging before on this device, you will probably have to create the last two keys. Remember keys are the folders on the left. Values are the key/value pairs on the right.
- Add or set the Enabled value name to the DWORD value of 1 within that key. This enables NETCF's logging facility.
- Create a ...\Diagnostics\Logging\Finalizer key and select it.
- Add or set the Enabled value name to the DWORD value of 1 within that key. These two Enabled values enable NETCF's finalizer logger.
- (Re)start your NetCF app on your device.
Analyzing the log file
Once your app starts, a file in your application's directory is created called netcf_Finalizer.log. You can read this file even while your app is running, both from the device and over your ActiveSync connection on your desktop in Notepad. Here is some sample output from the log:
[2006-09-22T10:11:04] [Microsoft.Win32.SafeHandles.SafeRegistryHandle] finalizer called.
[2006-09-22T10:11:04] [Microsoft.Win32.SafeHandles.SafeRegistryHandle] finalizer called.
[2006-09-22T10:11:04] [System.AppDomain] finalizer called.
What we have here is the timestamp of when the GC kicked in and ran the finalizer for an object. The second element is the class of object that was finalized.
Using the logger to tune your app
The GC works in the background to free memory that is no longer being used. If it finds a discarded object with a Dispose method that has not yet been called, that object gets put on the queue for the finalizer thread to Dispose of, and its memory is not freed until later. This delay takes its toll on memory and performance for your app. Best practice suggests that you explicitly call Dispose on any object that provides it before you discard it. (This is especially important for objects that tie up unmanaged resources, but that's another subject.) This log identifies where your trouble spots are so you can add Dispose calls to your code. In fact the log also includes where NetCF doesn't call Dispose, but you can't do anything about that.
In an ideal world, the log file would indicate where YourObject.Dispose() should have been called. In a nearly perfect world perhaps the log file would indicate where YourObject = new YourClass() was called for the object being finalized. Unfortunately that kind of information is not available to the CLR. But having the class name of the objects not being finalized will definitely be a huge step in the right direction to your search for what is slowing down your app.
Comments
- Anonymous
January 11, 2007
Once upon a midnight dreary, while I pondered, weak and weary, Over many a quaint and curious volume