Does ProfileOptimization actually work?

Question

One of the new performance enhanchements for .NET 4.5 is the introduction of the 'MultiCode JIT'.

See here for more details.

I have tried this, but it seems to have no effect on my application.

The reason why I am interested is that my app (IronScheme) takes a good long time to startup if not NGEN'd, which implies a fair amount of JIT'ng is involved at startup. (1.4 sec vs 0.1 sec when NGEN'd).

I have followed the instructions on how to enable this, and I can see a 'small' (4-12KB) is created. But on subsequent startup, it seems to have absolutely no effect on improving the startup time. It is still 1.4 sec.

Has anyone actually seen (or made) this work in practice?

Also, are there any limitations on which code will be 'tracked'? Eg: assembly loading contexts, transient assemblies, etc. I ask this as the created file never seems to grow, but I am in fact generating a fair amount of code (in a transient assembly).

One bug that I did encounter was that SetProfileRoot does not seem to understand a / as a path separator, make sure to use \ .

Answer 1

The rule of thumb we use at Microsoft is that Multicore JIT gets you about half way towards NGEN startup performance. Thus if your app starts in 0.1 seconds with NGEN and 1.4 seconds without NGEN, we would expect Multicore JIT startup to take about 0.75 seconds.

That being said, we had to put some limitations in place to guarantee that program execution order is the same with and without MCJ. MCJ will sometimes pause the background thread waiting for modules to be loaded by the foreground thread, and will abort background compilation if there is an assembly resolve or module resolve event.

If you want to find out what's happening in your case, we have ETW (Event Tracing For Windows) instrumentation of the MCJ feature and we will be releasing a version of PerfView soon which will be able to collect these events by if you take a trace of your app startup.

Update: PerfView has been updated to be able to show background JIT information. Here are the steps to diagnosing with the latest version (1.2.2.0):

1. Collect a trace using PerfView of your application startup, either using Collect->Run or Collect->Collect from the main PerfView menu.
2. Assuming you used Collect-> Run, put the name of your .exe in the Command text box, pick a filename (i.e. IronScheme.etl), select Background JIT from Advanced Options, and click Run Command.
3. Close your application and double click on the IronScheme.etl file that gets generated.
4. Double click on the JIT Stats view in the list underneath IronScheme.etl, you should see something like this in the view that pops up:

This process uses Background JIT compilation (System.Runtime.ProfileOptimize) 
    Methods Background JITTed : 2,951 
    Percent # Methods Background JITTed : 52.9% 
    MSec Background JITTing : 3,901 
    Percent Time JITTing is Background : 50.9% 
    Background JIT Thread : 11308 

You can click on "View Raw Background Jit Diagnostics" to see all of the MCJ events in excel. One question I forgot to ask: are you running this on a multicore machine or multicore VM? It is a common mistake to test out MCJ in a VM that only has a single logical processor.

Answer 2

Calling Activator.CreateInstance during startup seems to kill MCJ?

Or rather that triggered an Assembly Resolve, which completely seems to stop MCJ. And never work after that. Maybe the MSDN docs should mention this.