EventPipe realtime symbolication broken: `MethodLoadVerbose` not called

[vaind]

A while ago I've added realtime EventPipe support to TraceLog. Recently, I've found out that after upgrading to net8 from net6, method resolution for methods loaded during runtime doesn't work anymore (context: I'm using the realtime EventPipe based TraceLog to run a continuous profiler that captures short spans - and because session startup&shutdown is so expensive, I need to have a session open for the whole duration of the app).
After a lot of to&fro, I've found we don't get MethodLoadVerbose from runtime when the method gets eventually loaded.

Steps to reproduce:

1. check out https://github.com/vaind/examples/tree/main/dotnet-eventpipe-method-missing
2. pwsh run.ps1

This is the result (running on Windows 11). Notice the missing Program FindPrimeNumber on net8+

Running app on net6.0...
MethodDCStopVerbose: Program CreateFromEventPipeSession
MethodDCStopVerbose: Program ProcessInitialRundown
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 .ctor
MethodDCStopVerbose: Program+<>c .cctor
MethodDCStopVerbose: Program+<>c .ctor
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 <ProcessInitialRundown>b__1
MethodDCStopVerbose: Program <Main>
MethodDCStopVerbose: Program Main
MethodDCStopVerbose: Program+<Main>d__1 MoveNext
MethodDCStopVerbose: Program+<>c__DisplayClass1_0 .ctor
MethodDCStopVerbose: Program .cctor
MethodLoadVerbose: Program+<>c__DisplayClass1_0 <Main>g__WaitForFirstEventAsync|0
MethodLoadVerbose: Program+<>c__DisplayClass1_0+<<Main>g__WaitForFirstEventAsync|0>d MoveNext
MethodLoadVerbose: Program+<>c__DisplayClass1_1 .ctor
MethodLoadVerbose: Program+<>c__DisplayClass1_1 <Main>b__4
computation result: 1299709
MethodLoadVerbose: Program+<>c <Main>b__1_3
MethodLoadVerbose: Program FindPrimeNumber
MethodLoadVerbose: Program+<>c <Main>b__1_1
computation result: 1299709
computation result: 1299709
MethodLoadVerbose: Program+<>c <Main>b__1_1
MethodLoadVerbose: Program LogIfRelevant
computation result: 1299709
stopping session...
waiting for the background processing to finish...
program finished
Done running on net6.0


Running app on net8.0...
MethodDCStopVerbose: Program <Main>
MethodDCStopVerbose: Program Main
MethodDCStopVerbose: Program+<Main>d__1 MoveNext
MethodDCStopVerbose: Program+<>c__DisplayClass1_0 .ctor
MethodDCStopVerbose: Program .cctor
MethodDCStopVerbose: Program CreateFromEventPipeSession
MethodDCStopVerbose: Program ProcessInitialRundown
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 .ctor
MethodDCStopVerbose: Program+<>c .cctor
MethodDCStopVerbose: Program+<>c .ctor
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 <ProcessInitialRundown>b__1
computation result: 1299709
computation result: 1299709
computation result: 1299709
computation result: 1299709
stopping session...
waiting for the background processing to finish...
program finished
Done running on net8.0


Running app on net9.0...
MethodDCStopVerbose: Program <Main>
MethodDCStopVerbose: Program Main
MethodDCStopVerbose: Program+<Main>d__1 MoveNext
MethodDCStopVerbose: Program+<>c__DisplayClass1_0 .ctor
MethodDCStopVerbose: Program .cctor
MethodDCStopVerbose: Program CreateFromEventPipeSession
MethodDCStopVerbose: Program ProcessInitialRundown
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 .ctor
MethodDCStopVerbose: Program+<>c .cctor
MethodDCStopVerbose: Program+<>c .ctor
MethodDCStopVerbose: Program+<>c__DisplayClass3_0 <ProcessInitialRundown>b__1
computation result: 1299709
computation result: 1299709
computation result: 1299709
computation result: 1299709
stopping session...
waiting for the background processing to finish...
program finished
Done running on net9.0

This is almost definitely due to some change in .net runtime, however I wasn't able to found out what changed and how to get around it. Any ideas what could be changed in TraceLog to restore the original behavior of getting loaded methods during execution? Or should I just move this issue to http://github.com/dotnet/runtime ?

[brianrob]

If you've confirmed that you have the right keyword on, then yes, I would move this to the dotnet/runtime repo. To confirm, the event that you want is:

                    <event value="143" version="2" level="win:Informational"  template="MethodLoadUnloadVerbose_V2"
                           keywords ="JitKeyword NGenKeyword" opcode="MethodLoadVerbose"
                           task="CLRMethod"
                           symbol="MethodLoadVerbose_V2" message="$(string.RuntimePublisher.MethodLoadVerbose_V2EventMessage)"/>

You would need to enable the Microsoft-Windows-DotNETRuntime provider withJit keyword at the Informational level.

[vaind]

I do have the JIT keyword enabled (as part of ClrTraceEventParser.Keywords.Default).

However, you mention MethodLoadVerbose_V2 but I don't actually see that used in the ClrTraceEventParser, there's only: MethodLoadVerbose:

perfview/src/TraceEvent/Parsers/ClrTraceEventParser.cs

Lines 1586 to 1599 in dbf41bd

	}
	public event Action<MethodLoadUnloadVerboseTraceData> MethodLoadVerbose
	{
	add
	{
	// action, eventid, taskid, taskName, taskGuid, opcode, opcodeName, providerGuid, providerName
	RegisterTemplate(new MethodLoadUnloadVerboseTraceData(value, 143, 9, "Method", MethodTaskGuid, 37, "LoadVerbose", ProviderGuid, ProviderName));
	}
	remove
	{
	source.UnregisterEventTemplate(value, 143, ProviderGuid);
	source.UnregisterEventTemplate(value, 37, MethodTaskGuid);
	}
	}

Is this maybe missing in the parser and thus also missing in TraceLog?

[brianrob]

That event will capture all versions of MethodLoadVerbose, both V1 and V2. The template itself is responsible for differentiating the payload - the event triggers for all versions. That's what drives the JITStats view in PerfView, so it's getting lots of exercise.

As a next step in diagnosis, if you capture a trace using dotnet-trace with the same configuration and open it in PerfView, do you see the MethodLoadVerbose events? They won't show up with the _V2 as part of the name - that's just how it's defined in the runtime.

[vaind]

Turns out .net8+ only emits these events when I change the level to Verbose...
Maybe these docs are wrong then? https://learn.microsoft.com/en-us/dotnet/fundamentals/diagnostics/runtime-method-events#methodloadverbose_v1-event

[brianrob]

I can't explain what you're seeing - looking at main this event is enabled at the Informational level:

https://github.com/dotnet/runtime/blob/main/src/coreclr/vm/ClrEtwAll.man#L3880-L3893