Ngen compiled .net visual plugin. Iinconsistent load times

Stephenson_Martin · June 10, 2021, 12:52pm

Hi.
We have a .net WPF .dll which is being loaded into a Delphi Hydra host in hcdNewAppDomain.

In an attempt to improve the performance of the plugin load we have used ngen to pre-compile the IL.

ngen display

shows the assemblies we expect to see in the cache.

When profiling the load of the plugin using dotTrace we see the JIT reduced when the first instance of the plugin is loaded

Closing the plugin and re-opening we see a large JIT time as the compile is being performed, the same as before the ngen cache was built

I believe this can be accounted for by the statement from the MSDN article

“When an assembly with an NGen image is loaded into an AppDomain as domain-specific, the NGen image can only be used the first time the assembly is loaded. Subsequent attempts to load the same assembly into different AppDomains will result in code being JIT-compiled. This happens because when the NGen image is loaded as domain-specific, the loader initializes data structures in the NGen image resulting in the image being hardwired to that AppDomain. Once that happens, the code essentially becomes nonshareable.”

The odd thing is that if the plugin is closed and re-opened again for a third time we see the load time back to that of the first load, and the JIT time back down to milliseconds in dotTrace.

Repeating the open/close/open/close of the plugin sees the timings reliably flip between fast/slow/fast/slow and the dotTrace profiler shows ngen/JIT/ngen/JIT

Have you any ideas why are seeing this behaviour

antonk · June 10, 2021, 6:02pm

Hello

When the AddDomain.Unload method returns the AppDomain unloading might not be fully completed yet. There might be stale data structures that will be completely removed only after next full Garbage Collection run.
We need to check/discuss internally if it is possible and feasible to invoke Garbage Collection somewhere during plugin load operation.

Regards

Stephenson_Martin · June 11, 2021, 12:56pm

Some simple logs from the Delphi showing plugin load times.
Logs 1-10 are with the plugin installed in Ngen cache
Logs 11- are after a called to Ngen uninstall

LoadModule is prior to issuing the call to Hydra ModuleManager.LoadManagedPlugin
Loaded is immedately after that returns.
Execute_dn is when the plugin identifies to the launcher that it has initialised

The unload was just to make sure that the UnloadModule was being called.

LoadModule #1
 ==================
12:46:11.600 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:46:12.040 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:46:18.563 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #2
 ==================
12:46:51.608 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:46:52.206 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:47:10.440 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #3
 ==================
12:47:27.638 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:47:27.908 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:47:33.308 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #4
 ==================
12:48:10.624 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:48:11.391 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:48:29.337 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #5
 ==================
12:48:43.702 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:48:44.024 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
12:48:49.637 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #6
 ==================
13:08:25.644 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:08:26.240 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:08:49.037 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #7
 ==================
13:35:46.542 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:35:46.899 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:35:53.711 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #8
 ==================
13:36:26.261 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:36:27.072 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:36:51.826 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #9
 ==================
13:37:17.095 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:37:17.408 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:37:24.353 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

 LoadModule #10
 ==================
13:37:38.367 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:37:39.292 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:38:04.350 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll

      LoadModule #11
 ==================
13:45:28.069 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:45:28.292 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:45:46.488 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
 LoadModule #12
 ==================
13:46:03.262 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:46:03.944 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:46:27.439 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
 LoadModule #13
 ==================
13:47:12.478 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:47:12.678 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:47:29.872 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
 LoadModule #14
 ==================
13:47:48.535 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:47:49.229 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:48:13.061 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
 LoadModule #15
 ==================
13:48:34.852 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:48:35.059 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:48:51.877 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
 LoadModule #16
 ==================
13:49:08.867 LoadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:49:09.436 Loaded C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll
13:49:33.878 Execute_dn 
UnloadModule C:\Program Files (x86)\Savant Enterprises\Pulse Program Launcher - Copy\\PULR07\Savant.Pulse.Client.Plugin.PULR07.dll