Windows Shutdown ETW Recording for JITed stacks is not working.

Open
#113,412 4 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Assessment

Difficulty
5/5
Estimated time
Over a week
Newbie friendliness
28/100
Issue type
Bug
Clarity
Needs clarification
Activity status
Stale
Tech stack
csharp

Research direction

Start by reproducing the shutdown trace with the WPR and xperf commands in the issue, using the ShutdownTester example. Review MultiProfile.zip and the described CaptureStateOnDemand behavior, then investigate the TraceEvent relogging approach and the MethodUnloadVerbose versus MethodJittingStarted options. Done means JITed stack frames decode without ?!? during shutdown recording.

Written by the indexing model from the issue text.

Description

area-Tracing-coreclr enhancement
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 

Image

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?

MultiProfile.zip

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

Dominant language
C#
Stars
18.3k
Forks
5.6k
PR merge metrics
PR metrics pending

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from dotnet/runtime

All issues in dotnet/runtime

Similar issues

More C# issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.