MemoryAllocatedForJitCode ETW Event missing in trace, but CLRStackWalk still fires

vvuk commented 2 months ago

Description

When the ETW JIT keyword is enabled with Verbose along with the STACK keyword (at Info in this specific case, but I don't think that matters), it looks like MethodJittingStarted events are followed by two stack traces. The second one is coming from the MemoryAllocatedForJitCode event callout, but that event is not making it into the trace.

Reproduction Steps

xperf -start UserSession -on Microsoft-Windows-DotNETRuntime:0x40000000:4+Microsoft-Windows-DotNETRuntime:0x30:5, run some dotnet thing, xperf -stop -d foo.etl. Then probably xperf -i foo.etl -a dumper or similar and look at the events.

Expected behavior

MemoryAllocatedForJitCode event should be included in the trace. Obviously this is minor, but I did spend a bunch of time trying to figure out why stacks weren't lining up with events (other than no-stack events) :)

Actual behavior

The event is missing, but it looks like it at least tried to fire (FireEtw... was called), and its Stackwalk fires. See two stacks in the image below. The first little blue square on the timeline is the MethodJittingStarted event.

Regression?

No response

Known Workarounds

No response

Configuration

dotnet 8.0.204

Other information

No response

tommcdon commented 2 months ago

Adding @kunalspathak for thoughts. It seems this event was added on #44030.

tommcdon commented 2 months ago

@vvuk it's possible this is an issue specific to xperf. Would you mind trying with https://github.com/microsoft/perfview and reporting back if it correctly emits the event?

vvuk commented 2 months ago

Hmm, sure, but I'm not sure why xperf vs perfview would matter here -- it's the coreclr runtime that's doing the event emitting. With a profile captured by PerfView (after turning on a bunch of the .net etc flags), here's a sample of what I see in the .etl (via dump output) looking at one process, and DotNETRuntime provider events only:

Microsoft-Windows-DotNETRuntime/CLRMethod/MethodJittingStarted,     539043,         pwsh.exe (13680),      11312,   4, , , , , 0x00007fff0014cfa8, 0x00007ffefff34000, 0x06005400, 0x0000013e, "System.Reflection.CustomAttribute", "GetCustomAttributes", "class System.Object[]  (class System.Reflection.RuntimeMethodInfo,class System.RuntimeType,bool)", 6
Microsoft-Windows-DotNETRuntime/CLRStack/CLRStackWalk,     539045,         pwsh.exe (13680),      11312,   4, , , , , 6, 0, 0, 18, [0x00007fff5fd63edd : 0x00007fff5fd6588f]
Microsoft-Windows-DotNETRuntime/CLRStack/CLRStackWalk,     540635,         pwsh.exe (13680),      11312,   4, , , , , 6, 0, 0, 28, [0x00007fff5fd63edd : 0x00007fff5fd6588f]
Microsoft-Windows-DotNETRuntime/CLRMethod/MethodLoadVerbose,     540831,         pwsh.exe (13680),      11312,   4, , , , , 0x00007fff0014cfa8, 0x00007ffefff34000, 0x00007fff0125bb80, 0x000005a3, 0x06005400, 520, "System.Reflection.CustomAttribute", "GetCustomAttributes", "class System.Object[]  (class System.Reflection.RuntimeMethodInfo,class System.RuntimeType,bool)", 6, 0x0000000000000001
...
Microsoft-Windows-DotNETRuntime/CLRMethod/MethodJittingStarted,     540855,         pwsh.exe (13680),      11312,   4, , , , , 0x00007fff0014d378, 0x00007ffefff34000, 0x0600541a, 0x0000008c, "System.Reflection.PseudoCustomAttribute", "GetCustomAttributes", "void  (class System.Reflection.RuntimeMethodInfo,class System.RuntimeType,value class ListBuilder`1<class System.Attribute>&)", 6
Microsoft-Windows-DotNETRuntime/CLRStack/CLRStackWalk,     540858,         pwsh.exe (13680),      11312,   4, , , , , 6, 0, 0, 18, [0x00007fff5fd63edd : 0x00007fff5fd6588f]
Microsoft-Windows-DotNETRuntime/CLRStack/CLRStackWalk,     541108,         pwsh.exe (13680),      11312,   4, , , , , 6, 0, 0, 28, [0x00007fff5fd63edd : 0x00007fff5fd6588f]
Microsoft-Windows-DotNETRuntime/CLRMethod/MethodLoadVerbose,     541157,         pwsh.exe (13680),      11312,   4, , , , , 0x00007fff0014d378, 0x00007ffefff34000, 0x00007fff0125c160, 0x00000112, 0x0600541a, 520, "System.Reflection.PseudoCustomAttribute", "GetCustomAttributes", "void  (class System.Reflection.RuntimeMethodInfo,class System.RuntimeType,value class ListBuilder`1<class System.Attribute>&)", 6, 0x0000000000000001

There's the MethodJittingStarted for a method, followed by two CLRStackWalk events, then the MethodLoadVerbose for the method that was just jitted.

dotnet / runtime