Better Diagnostics in Whidbey: Loader Logging

  • Articolo

If you’ve spent much time developing applications with version 1 of the .Net Compact Framework, you’ve likely been frustrated at times by the lack of tools to help you diagnose problems in your applications. Even common errors, like the failure to find an assembly are hard to diagnose, much less more complex problems like memory leaks or performance issues. Admittedly, the lack of a good diagnostics infrastructure in version 1 of our product has been one of the greatest sources of customer frustration and support cost. Fortunately, we’ve listened to the feedback and have invested a significant amount of time and resources in version 2 to help the situation. Some of the new features you’ll find in version 2 that make it easier to understand what’s going on in a running application include:

In this post, I’m going to focus on how the new loader logging feature can help you diagnose failures encountered by the CLR’s class loader. As we’ll see, loader logging helps you determine why assemblies couldn’t be loaded, why types couldn’t be found and so on. It also provides information about the version of .Net CF used to run your application and whether or not your application is being run in “compatibility mode” (see https://blogs.msdn.com/stevenpr/archive/2004/12/30/344540.aspx for background on our approach to application compatibility).

Enabling the Loader Log

Loader logging is enabled and configured by setting a series of registry keys. At a minimum, you must set two keys: one to enable the CLR’s overall logging feature and one to specifically enable loader logging.

To enable CLR logging, set the following DWORD value to 1:

HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Enabled

To specifically enable loader logging, the following DWORD value must be set to 1:

HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Loader\Enabled

When these two keys are set, the CLR will create a file named netcf_loader.log in the same directory as your application.

There are a few other values you can set to customize how the log file is named and how eagerly it is written to. These values (all DWORDs) are:

· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\UseApp

The UseApp value causes the name of the application to be included in the name of the log file. For example, if I’m running an application called VW.exe, setting the UseApp value to 1 will cause the log file to be named netcf_VW_loader.log. The UseApp value is useful if you enable loader logging and have several applications installed in the same directory.

· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\UsePid

The UsePid value causes the process’s ID to be included in the name of the log file. As with UseApp, the UsePid value is useful if you enable loader logging and have several applications installed in the same directory.

· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Flush

Setting the Flush value to 1 will cause the CLR to write log events to the log file as they occur instead of buffering them up. Flushing eagerly negatively affects performance, but it can be useful in case you’re not getting the data you need in the log file because of application crashes or other errors.

What’s in the Loader Log?

Now that we’ve seen how to enable loader logging, let’s take a look at the type of information the CLR’s class loader writes to the log files. Loader logs consist of two sections: a header and a body.

The header of the log file contains the following data:

  • The name of the application’s main executable
  • The process ID as assigned by the operating system
  • The date and time the log file was created
  • The version of .Net CF used to run the application
  • Information about the platform on which your application is running

The data in the body of the log file includes descriptive information about each assembly as it is loaded, as well as diagnostic data to help you find errors encountered by the class loader as your application is executed. Specifically, the body of the log file contains:

· The “coercion” state. That is, whether or not your application was run in backwards compatibility mode.

· Tracing for each assembly load, including where the assembly was loaded from and which version was loaded.

· The trust level assigned to each module as it is loaded

· Whether or not the CLR found a configuration file associated with your application

· Failures to find methods, types, assemblies and modules.

· Failures to find a PInvoke DLL or a function within a PInvoke DLL

 

Here’s a sample log file from the run of an application that encountered no errors (I’ve added the line numbers for the line-by-line summary that follows the sample). This sample gives us a good chance to get a general idea of the type of information logged by the CLR class loader:

  ========================================

1 | Process [\Program Files\VW\VW.exe]

2 | ProcessID [0x4d9585d2]

3 | Date [2005/02/25] (yyyy/mm/dd)

4 | Time [18:33:14] (hh:mm:ss)

5 | NETCF [2.0.5035.00]

6 | Platform [Windows CE v4.20.1081 (PocketPC) WinCE4ARMV4 release Beta2 ARMV4 IJITv2]

  ========================================

7 | Compatibility mode [0.0.0.0]

8 | Loading module [\Windows\GAC_mscorlib_v2_0_0_0_cneutral_1.dll]

9 | Loaded [mscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] from [\Windows\GAC_mscorlib_v2_0_0_0_cneutral_1.dll]

10 | Loading module [\Program Files\VW\VW.exe]

11 | Policy file not present. [\Program Files\VW\VW.exe.config]

12 | Loading module [\Windows\GAC_System.Windows.Forms_v2_0_0_0_cneutral_1.dll]

13 | Loaded [System.Windows.Forms, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] from [\Windows\GAC_System.Windows.Forms_v2_0_0_0_cneutral_1.dll]

14 | Loading module [\Windows\GAC_System_v2_0_0_0_cneutral_1.dll]

15 | Loaded [System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] from [\Windows\GAC_System_v2_0_0_0_cneutral_1.dll]

16 | Loading module [\Windows\GAC_System.Drawing_v2_0_0_0_cneutral_1.dll]

17 | Loaded [System.Drawing, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] from [\Windows\GAC_System.Drawing_v2_0_0_0_cneutral_1.dll]

18 | Loading module [\Program Files\VW\Cars.dll]

19 | Failed to load [Cars, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null] from GAC

20 | Loaded [Cars, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null] from [\Program Files\VW\Cars.dll]

21 | Loading module [\Windows\GAC_SUVs_v10_0_0_0_cneutral_1.dll]

22 | Loaded [SUVs, Version=10.0.0.0, Culture=neutral, PublicKeyToken=1EF9E65A8D4F2CD6] from [\Windows\GAC_SUVs_v10_0_0_0_cneutral_1.dll]

==================(end)=================

 

Lines 1-6 are the header of the loader log.

Line 7 states that the application is not being run in compatibility mode. If this application were built with .Net CF version 1.0 and was run by .Net CF version 2.0, the version number displayed in line 7 would be 1.0.0.0. Again, refer to https://blogs.msdn.com/stevenpr/archive/2004/12/30/344540.aspx for a description of how compatibility mode works in .Net CF 2.0.

Lines 8 and 9 show the CLR loading the mscorlib assembly. As you can infer from this trace, the CLR loads mscorlib before loading any other assemblies. The loader log has (at least) two lines for every assembly that is loaded while the application is running. These two lines describe identity of the assembly the CLR is looking for and the location from which that assembly was loaded.

Line 10 shows the name of the module containing the application’s main executable.

Line 11 states that the CLR could not find a configuration file for this application.

Lines 12 and 13 show the CLR loading the System.Windows.Forms assembly from the GAC.

Lines 14 and 15 show the CLR loading the System assembly from the GAC.

Lines 16 and 17 show the CLR loading the System.Drawing assembly from the GAC.

Lines 18, 19 and 20 show the CLR loading an application assembly called Cars. In this case, the log shows that the CLR loaded Cars out of the application directory after failing to find it in the GAC. By the way, searching the GAC is extraneous in this case because Cars is not strongly named.

Lines 21 and 22 show the CLR loading an application assembly called SUVs. As the log shows, the CLR found SUVs in the GAC.

 

As described, the primary goal of the loader log is to help you diagnose failures that occur while running your application. The following two examples show how the loader log makes it easy for you to figure out what’s happening when errors are encountered. This first example shows the log entries that are written when the loader fails to find an assembly:

Loading module [\Program Files\VW\Golf.dll]

Attempt to load [\Program Files\VW\Golf.dll] has failed (err 0x80001000).

Loading module [\Program Files\VW\Golf.exe]

Attempt to load [\Program Files\VW\Golf.exe] has failed (err 0x80001000).

Failed to load [Golf, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null]

As you can see, the loader logs the identity of the assembly it is looking for, along with the names of the files and locations it probed while looking for the assembly.

This example shows the log entries that are written when the loader fails to find a specific type:

Missing Type. Type [Cars.Jetta], Assembly [Cars].

Missing Type. Class [Cars.Jetta], Assembly [Cars, Version=5.0.0.0, Culture=neutral, PublicKeyToken=null].

As expected, the CLR logs the name of the type it couldn’t find along with the assembly in which it expected the type to be found.

 

We hope that the data provided in the loader log will make it much easier to help debug applications running on .Net CF 2.0. As described, the loader log is just one of the many new debugging tools we’re providing in Whidbey. As always, feedback is appreciated. If there are specific loader-related errors you repeatedly see that we’re not logging, be sure and let us know.

Thanks,

Steven

This posting is provided "AS IS" with no warranties, and confers no rights.

Comments

  • Anonymous
    June 22, 2005
    In a previous post I described how the Loader Log can be used to help diagnose problems such as assembly...

  • Anonymous
    March 18, 2006
    Have you ever encountered a MissingMethodException or TypeLoadException when starting a .NET Compact...

  • Anonymous
    April 17, 2006
    Service Pack 1 of the .Net Compact Framework version 2 (Beta available in a few days on MSDN) includes...

  • Anonymous
    August 06, 2006
    Hace ya algún tiempo mencioné en este mismo blog que con la llegada del Path SP1 para CF 2.0 ívamos...

  • Anonymous
    February 23, 2007
    Esta es una de las preguntas más comunes que me suelen hacer siempre en sesiones de rendimiento y optimización

  • Anonymous
    December 29, 2007
    PingBack from http://cars.oneadayvitamin.info/?p=59

  • Anonymous
    May 13, 2008
    The .Net Compact Framework 3.5 Power Toys include a new utility called the NetCF Configuration Tool.

  • Anonymous
    June 15, 2009
    PingBack from http://mydebtconsolidator.info/story.php?id=6085