What prevents my native images to get loaded?

While investigating a dependency resolution error the other day I came across an interesting situation. Fuslogvw logs indicated that even though the proper native image was present for a managed assembly, it wouldn't get loaded due to the actual load context being a so called LoadFrom context. This was not the main issue I started to investigate, but after figuring that out I decided to conduct some research on load contexts.

After that I felt ready to reproduce the issue with a small console application and a class library it tries to load. I find it very useful to abstract away from the production environment and reproduce issues in a very simple, controlled one, so that you can focus only on the problem being investigated.

ConsoleApplication1.exe =>

static void Main(string[] args) {     var asm = Assembly.LoadFrom(@"c:\temp\dllfolder\ClassLibrary1.dll"); }

ClassLibrary1.dll => Just an empty dll

After building the binaries for - let's say- Release x64, deploy them to separate folders and run the appropriate ngen.exe to generate the native image for the dll, i.e.

C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ngen.exe install c:\temp\dllfolder\ClassLibrary1.dll

After all these steps, the following relevant files / folders could be observed :

• c:\temp\exefolder\ConsoleApplication1.exe
• c:\temp\dllfolder\ClassLibrary1.dll 
• c:\Windows\assembly\NativeImages_v4.0.30319_64\ClassLibrary1\b1086c3d9614cbfd539aa5cfb53ae3c9\ClassLibrary1.ni.dll

Note: ClassLibrary1.dll was not present in the managed GAC

At this point I enabled fuslogvw logging then started ConsoleApplication1.exe. Understanding the logs takes some time, so don't be frustrated if you don't put all the pieces together within a few seconds. I highlighted the most important log entries.

LOG: This bind starts in LoadFrom load context.  WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().  LOG: Using application configuration file: c:\temp\exefolder\ConsoleApplication1.exe.Config  LOG: Using host configuration file:  LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.  LOG: Attempting download of new URL file:///c:/temp/dllfolder/ClassLibrary1.dll.  LOG: Assembly download was successful. Attempting setup of file: c:\temp\dllfolder\ClassLibrary1.dll  LOG: Entering run-from-source setup phase.  LOG: Assembly Name is: ClassLibrary1, Version=1.0.0.0, Culture=neutral, PublicKeyToken=b91bc0d0c196a74e LOG: Re-apply policy for where-ref bind.  LOG: Post-policy reference: ClassLibrary1, Version=1.0.0.0, Culture=neutral, PublicKeyToken=b91bc0d0c196a74e  LOG: GAC Lookup was unsuccessful.  LOG: Where-ref bind Codebase does not match what is found in default context. Keep the result in LoadFrom context.  LOG: Binding succeeds. Returns assembly from file:///c:/temp/dllfolder/ClassLibrary1.dll.  LOG: Assembly is loaded in LoadFrom load context. ... WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load(). LOG: IL assembly loaded from c:\temp\dllfolder\ClassLibrary1.dll.

See the warning about not probing the native image in case of a LoadFrom context? This can be a bit misleading, but first things first. As GAC lookup fails, the binder leaves the context as is and binds to the managed dll. However, things get changed as soon as you GAC your dll.

gacutil /i c:\temp\dllfolder\ClassLibrary1.dll

That deploys the dll to the following folder:
c:\Windows\Microsoft.NET\assembly\GAC_64\ClassLibrary1\v4.0_1.0.0.0__b91bc0d0c196a74e\ClassLibrary1.dll

LOG: This bind starts in LoadFrom load context.  WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().  LOG: Using application configuration file: c:\temp\exefolder\ConsoleApplication1.exe.Config  LOG: Using host configuration file:  LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.  LOG: Attempting download of new URL file:///c:/temp/dllfolder/ClassLibrary1.dll.  LOG: Assembly download was successful. Attempting setup of file: c:\temp\dllfolder\ClassLibrary1.dll  LOG: Entering run-from-source setup phase.  LOG: Assembly Name is: ClassLibrary1, Version=1.0.0.0, Culture=neutral, PublicKeyToken=b91bc0d0c196a74e  LOG: Re-apply policy for where-ref bind. LOG: Post-policy reference: ClassLibrary1, Version=1.0.0.0, Culture=neutral, PublicKeyToken=b91bc0d0c196a74e  LOG: Found assembly by looking in the GAC.  LOG: Switch from LoadFrom context to default context.  LOG: Binding succeeds. Returns assembly from C:\windows\Microsoft.Net\assembly\GAC_64\ClassLibrary1\v4.0_1.0.0.0__b91bc0d0c196a74e\ClassLibrary1.dll.  LOG: Assembly is loaded in default load context. ... WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().  LOG: Start validating all the dependencies.  LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089. Native image has correct version information.  LOG: Validation of dependencies succeeded.  LOG: Bind to native image succeeded. Attempting to use native image C:\windows\assembly\NativeImages_v4.0.30319_64\ClassLibrary1\b1086c3d9614cbfd539aa5cfb53ae3c9\ClassLibrary1.ni.dll. Native image successfully used.

As you can see the load context was "promoted" to default due to the assembly also residing in the GAC. This causes the binder to look for the native image counterpart of the dll even though several clear logs indicated otherwise. As a result, the native image gets loaded into the address space of the process.

Uninstalling the native image by

C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ngen.exe uninstall ClassLibrary1

of course once again results in only the managed dll being loaded.

... WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().  WRN: No matching native image found.  LOG: IL assembly loaded from C:\windows\Microsoft.Net\assembly\GAC_64\ClassLibrary1\v4.0_1.0.0.0__b91bc0d0c196a74e\ClassLibrary1.dll.

That speaks for itself.

In some cases however, the situation is not so obvious, i.e. some component may hide the details of assembly loading. A good example is MEF, as composing your CompositionContainer might lead to either the default or a LoadFrom load context. Typically, if the dll you're trying to load is not installed to GAC, then you'll have a LoadFrom load context resulting in the native images not getting loaded.

A nice tool to verify that your native images get loaded properly is VMMap from Sysinternals, but there are tons of others that can do the same.

Figure 1. VMMap showing the loaded images

You might want to look for such issues before your release.

References

https://blogs.msdn.microsoft.com/abhinaba/2014/02/18/net-ngen-explicit-loads-and-load-context-promotion/
https://blogs.msdn.microsoft.com/junfeng/2005/05/31/assemblies-in-loadfrom-context-cant-be-domain-neutral-and-cant-use-ngen/
Best Practices for Assembly Loading
How the Runtime Locates Assemblies

Common pitfalls of the Windows Performance Toolkit

I've been playing around with several versions of the Windows Performance Toolkit for some time now and decided to gather all those little annoying things that can make your life miserable. This way, all known issues (and hopefully their solutions) will be mentioned in one place and you don't need to spend hours of googling just to find the answer amongst the comments of some long abandoned forum.

I also find it important to highlight that for most (but not all) problems below it was not me who found the solution. I merely try to collect everything in one place and this will take some time. The credit shall mainly go to Alois Kraus and Bruce Dawson. These guys did an awesome job in documenting the various strange behavior of the tools involved, like wpr, wprui, xperf & wpa. I definitely recommend you to check out the blogs of these guys.

The issues:

- x64 ETW stackwalking is broken under Windows 7

- Data for CLR event providers are not decoded correctly in WPA (Generic Events)

- Data for custom event providers are not decoded correctly in WPA (Generic Events)

- Symbol decoding does not work for native images in WPA (?!?)

- Symbol decoding does not work for managed assemblies in WPA (?!?)

- .etl file taken on Windows 8(.1?) machine requires at least Win 8(.1) for analysis

- xperf / wpr won't start if NT Kernel Logger session is already runnning (procexp, procmon etc) under Windows 7

x64 ETW stackwalking is broken under Windows 7

I read a few articles mentioning this issue before actually bumping into it. The problem is that stack walking stops as soon as it detects being inside a JIT-ted method. The result is that you get broken call stacks for all your managed stuff. It's very easy to detect this error, as many methods hit in the problematic assembly are shown as a direct child of the [Root] element in the tree. Make no mistake, the resulting .etl file is corrupted here, so you can't fix the callstacks without taking the appr. corrective action and re-profiling.

<img placeholder>

<Figure x. No method call hierarchy, only a flat list>

However this works fine for x86 code. As you can see, canvas1_Loaded() is now deep within the call hierarchy. We should see the same for x64, should there be no bug in the ETW stack walker.

<img placeholder>

<Figure x. Expected method call hierarchy>

Solution: either switch to x86 for profiling or NGEN your x64 assemblies and repeat profiling.

Data for CLR event providers are not decoded correctly in WPA (Generic Events)

Now this is a real life ruiner. I was experimenting with the CLR Runtime / Rundown Provider(s) the other day and after spending hours to map hexadecimal values to CLR ETW keywords, levels and events in WPA that actually make sense I finally gave up and asked myself the question "Is this really worth it?". There had to be a way to actually see fields that make sense. Column names were also totally useless.

Values and column names missing or make no sense

Solution: reinstall the CLR manifest, by running the following commands:

wevtutil um c:\Windows\Microsoft.NET\Framework64\v4.0.30319\CLR-ETW.man

wevtutil im c:\Windows\Microsoft.NET\Framework64\v4.0.30319\CLR-ETW.man

Note: for a 32-bit OS, just use the "Framework" folder instead of "Framework64".

Unfortunately, you have to repeat your profiling scenario, because once again, it's the .etl file that contains invalid information. After fixing the issue, it takes some time to get used to the dynamic column headers, but that should be your biggest problem in life. :-)

All values / column names are shown correctly

Data for custom event providers are not decoded correctly in WPA (Generic Events)

My other favorite. If you happen to use System.Diagnostics.Tracing.EventSource to create your own ETW event provider you might bump into this. To keep it short, avoid APi names like Start or Stop. WPA (even the one in Creators Update SDK) seems to perform some arcane magic while reading / decoding the information in the .etl file and this unfortunately seems to conflict with certain (let's call 'em "reserved") names. I might write a separate article about this problem in the future.

Values and column names are not decoded properly

Perfview can decode everything properly

This is how it should be

Solution #1: just try to name your methods in your custom event provider in a standard way, like when you work with a manifest-based generated class, i.e. EventWrite* will do.

Solution #2: if you're targeting .NET 4.6+ you can opt-in to use a self describing event format for your events. Just make sure you new up EventSource with the appropriate constructor and then WPA will decode everything correctly.

Symbol decoding does not work for native images in WPA (?!?)

In this case, WPA can typically decode the module but not the function name in a callstack.

Comparing two WPA versions

Solution: make sure Visual Studio is closed during data collection, as it seems ngen createpdb fails while it is open.

Symbol decoding does not work for managed assemblies in WPA (?!?)

This problem can be recognized by the ?!? symbols in the callstacks:

Module and function symbols are not resolved

I guess there can be several reasons, the most obvious one for me was that Visual Studio (2013, 2015, don't know about the others) was running during data capture (with WPRUI). I did not dig deeper here as closing VS and recollecting data solved this. I wonder if collecting with xperf solves this too... I leave that exercise to you. :-)

Solution: make sure Visual Studio is closed while capturing traces.

There you go

To be continued...