Slow AssemblyLoadContext.StartAssemblyLoad() at startup

[iSazonov]

Description

Related #44598
I measured PowerShell startup scenario with pwsh -c exit (really start-stop scenario).
One delay in the scenario is in AssemblyLoadContext.StartAssemblyLoad() called from hostpolicy - 59 ms (10%).

The StartAssemblyLoad() initializes tracing

runtime/src/coreclr/src/System.Private.CoreLib/src/System/Runtime/Loader/AssemblyLoadContext.CoreCLR.cs

Lines 199 to 206 in 191ea06

	private static void StartAssemblyLoad(ref Guid activityId, ref Guid relatedActivityId)
	{
	// Make sure ActivityTracker is enabled
	ActivityTracker.Instance.Enable();
	// Don't use trace to TPL event source in ActivityTracker - that event source is a singleton and its instantiation may have triggered the load.
	ActivityTracker.Instance.OnStart(NativeRuntimeEventSource.Log.Name, AssemblyLoadName, 0, ref activityId, ref relatedActivityId, EventActivityOptions.Recursive, useTplSource: false);
	}

Especially the slow System.Threading.Tasks.TplEventSource..cctor () - 49 ms (8.5%).
(And System.Diagnostics.Tracing.NativeRuntimeEventSource..cctor() too)

We can't seem to improve this in PowerShell and I hope it will be improved in .Net in some way. Perhaps it is possible to postpone the initialization or make it async.

Configuration

Used PowerShell 7.2 Preview.1 based on .Net 5.0.

[ghost]

Tagging subscribers to this area: @vitek-karas, @agocke, @CoffeeFlux
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

Related #44598
I measured PowerShell startup scenario with pwsh -c exit (really start-stop scenario).
One delay in the scenario is in AssemblyLoadContext.StartAssemblyLoad() called from hostpolicy - 59 ms (10%).

The StartAssemblyLoad() initializes tracing

runtime/src/coreclr/src/System.Private.CoreLib/src/System/Runtime/Loader/AssemblyLoadContext.CoreCLR.cs

Lines 199 to 206 in 191ea06

	private static void StartAssemblyLoad(ref Guid activityId, ref Guid relatedActivityId)
	{
	// Make sure ActivityTracker is enabled
	ActivityTracker.Instance.Enable();
	// Don't use trace to TPL event source in ActivityTracker - that event source is a singleton and its instantiation may have triggered the load.
	ActivityTracker.Instance.OnStart(NativeRuntimeEventSource.Log.Name, AssemblyLoadName, 0, ref activityId, ref relatedActivityId, EventActivityOptions.Recursive, useTplSource: false);
	}

Especially the slow System.Threading.Tasks.TplEventSource..cctor () - 49 ms (8.5%).
(And System.Diagnostics.Tracing.NativeRuntimeEventSource..cctor() too)

We can't seem to improve this in PowerShell and I hope it will be improved in .Net in some way. Perhaps it is possible to postpone the initialization or make it async.

Configuration

Used PowerShell 7.2 Preview.1 based on .Net 5.0.

Author:	iSazonov
Assignees:	-
Labels:	area-AssemblyLoader-coreclr, tenet-performance, untriaged
Milestone:	-

[jkotas]

EventSource construction is relatively expensive reflection heavy operation today.

The ultimate way to fix this overhead is to replace the reflection with source generators: #43390

[iSazonov]

EventSource construction is relatively expensive reflection heavy operation today.

The ultimate way to fix this overhead is to replace the reflection with source generators: #43390

In the my trace for startup scenario it seems a reflection calls take <0.8% but System.Resources.ResourceManager.GetString() 1.2%.
I doubt that generators will help in this scenario.
If this initialization cannot be postponed, then most likely it is necessary to improve a little bit of all parts
/cc @adamsitnik

[tommcdon]

@josalem

[benaadams]

In the my trace for startup scenario it seems a reflection calls take <0.8% but System.Resources.ResourceManager.GetString() 1.2%.

Looking at the stacktrace It's the manifest generation; System.Resources.ResourceManager.GetString is being called as the TplEventSource has a translatable manifest.

Source generators should still help here.

[tommcdon]

Related to #45518