Description
Description
Currently it is not possible to record ETW Shutdown traces for JITed code (.NET and .NET Core). I am mainly interested also for a solution for .NET Framework classic but the behavior is the same for .NET Core.
Windows Shutdown recording is unique in the sense that at the end of the shutdown no ETW Rundown can be performed to emit the JIT events MethodUnloadVerbose and friends which are needed to decode JITed stacks for which the initial JIT event could not be recorded.
Reproduction Steps
Lets suppose that little application
using System.Diagnostics;
namespace ShutdownTester
{
internal class Program
{
static void Main(string[] args)
{
while(true)
{
Console.WriteLine("Press any key to call into some methods");
Console.ReadKey();
new Program().Run();
Console.WriteLine("Run completed");
}
}
private void Run()
{
var sw = Stopwatch.StartNew();
while(sw.Elapsed.TotalSeconds < 1)
{
}
}
}
}
ShutdownTester.exe
Press any key to call into some methods
Run completed
Press any key to call into some methods
Run completed
Press any key to call into some methods
Run completed
Press any key to call into some methods
Run completed
Press any key to call into some methods
- Start Test application and press a the key once to JIT all methods.
- Start ETW recording
- Press any in tester application to consume CPU
- Stop ETW recording without the usual Rundown to simulate shutdown recording.
wpr -start cpu -filemode -recordtempto c:\temp
Press key in tester once or more.
xperf -stop "WPR_initiated_WprApp_WPR System Collector" -stop "WPR_initiated_WprApp_WPR Event Collector"
xperf -merge "c:\temp\WPR_initiated_WprApp_WPR System Collector.etl" "c:\temp\WPR_initiated_WprApp_WPR Event Collector.etl" c:\temp\testMerge.etl
you find missing stack frames with ?!? as method name.
As workaround I have tried to emit the Rundown events before tracing was stopped with a CaptureStateOnDemand call which will emit the ETW CLR rundown events just like during regular stop with my custom profile:
wpr -start MultiProfile.wprp -filemode -recordtempto c:\temp
Press any key before Capture State will lead to resolved stacks
wpr -capturestateondemand
Press any key after Capture State will lead to unresolved ?!? stacks because the ETW stack parsers treat this method as already unloaded.
xperf -stop "WPR_initiated_WprApp_WPR System Collector" -stop "WPR_initiated_WprApp_WPR Rundown Event Collector" -stop "WPR_initiated_WprApp_WPR User Event Collector"
xperf -merge "c:\temp\WPR_initiated_WprApp_WPR System Collector.etl" "c:\temp\WPR_initiated_WprApp_WPR Rundown Event Collector.etl" "c:\temp\WPR_initiated_WprApp_WPR User Event Collector.etl" c:\temp\TestCaptureStateComamnd.etl
That does only work partially because all current ETW parsers do not decode the stack frames which were seen the first time after the MethodUnloadVerbose event. The semantics of unload the MethodUnloadVerbose is that after that time if this method is called again it cannot be used to decode the stack frame because it has been unloaded.
I am left with two options:
- Rewrite the ETL to shift the MethodUnloadVerbose at the end of the ETW session. I have tried TraceEvent which supports relogging but so far my attempts have failed to reemit the events with a different time stamp. Any example would be nice.
- The ability to emit not MethodUnloadVerbose but MethodJittingStarted events
Expected behavior
Abitility to record JITed stack frames during shutdown trace.
What are the options here?
Actual behavior
JITed stacks are decoded with ?!?
Regression?
No
Known Workarounds
No
Configuration
.NET Core all versions and .NET Framework classic. The behavior is the same.
Other information
No response