Improve Crossgen2 compiler perf measurement (#37839)

Capture the full execution of Crossgen2 with ETW events by measuring command line parsing and moving the point we begin `Loading` measurement to the start of `Program.Run`. This accounts for about 300ms of time we were not measuring previously.

* Add ETW start/stop events around the command line parsing so we can time it and have a number to improve
* Fix up r2rtest `--measure-perf` switch which I broke when I renamed the graph provider and also add the new event.
* Move easily factorable pieces of `Run` into subroutines.

On small compile inputs such as a "Hello World" console app, a surprising amount of time is spent parsing the input arguments in the `System.CommandLine` library. Example perf of helloworld CG2 compilation:
```
Command line processing time: 192.46 ms
Total average compilation time: 594.46 ms
Phase breakdown (average):
    Loading time: 350.26 ms
    Graph processing time: 136.67 ms
        Added 108 nodes to mark stack
        Dependency analysis time: 57.38 ms
        Wall clock JIT time: 71.09 ms
        Total JIT time: 136.93 ms (sum of all threads)
        2 methods JITed
    Emitting time: 103.80 ms
```

diff --git a/src/coreclr/src/tools/crossgen2/ILCompiler.ReadyToRun/Compiler/PerfEventSource.cs b/src/coreclr/src/tools/crossgen2/ILCompiler.ReadyToRun/Compiler/PerfEventSource.cs
index 7f981a7..6bc188b 100644 (file)
--- a/src/coreclr/src/tools/crossgen2/ILCompiler.ReadyToRun/Compiler/PerfEventSource.cs
+++ b/src/coreclr/src/tools/crossgen2/ILCompiler.ReadyToRun/Compiler/PerfEventSource.cs
@@ -31,6 +31,22 @@ namespace ILCompiler
                 _stopAction?.Invoke();
             }
 
+            public static void CommandLineProcessingStart()
+            {
+                if (Log.IsEnabled())
+                {
+                    Log.CommandLineProcessingStart();
+                }
+            }
+
+            public static void CommandLineProcessingStop()
+            {
+                if (Log.IsEnabled())
+                {
+                    Log.CommandLineProcessingStop();
+                }
+            }
+
             public static StartStopEvents LoadingEvents()
             {
                 if (!Log.IsEnabled())
@@ -102,5 +118,9 @@ namespace ILCompiler
         private void JitMethodStart() { WriteEvent(9); }
         [Event(10, Level = EventLevel.Informational)]
         private void JitMethodStop() { WriteEvent(10); }
+        [Event(11, Level = EventLevel.Informational)]
+        private void CommandLineProcessingStart() { WriteEvent(11); }
+        [Event(12, Level = EventLevel.Informational)]
+        private void CommandLineProcessingStop() { WriteEvent(12); }
     }
 }

diff --git a/src/coreclr/src/tools/crossgen2/crossgen2/Program.cs b/src/coreclr/src/tools/crossgen2/crossgen2/Program.cs
index e54d804..5e77aea 100644 (file)
--- a/src/coreclr/src/tools/crossgen2/crossgen2/Program.cs
+++ b/src/coreclr/src/tools/crossgen2/crossgen2/Program.cs
@@ -110,32 +110,8 @@ namespace ILCompiler
                 Helpers.AppendExpandedPaths(_referenceFilePaths, reference, false);
         }
 
-        private int Run()
+        private void ConfigureTarget()
         {
-            InitializeDefaultOptions();
-
-            ProcessCommandLine();
-
-            if (_commandLineOptions.OutputFilePath == null)
-                throw new CommandLineException(SR.MissingOutputFile);
-
-            if (_commandLineOptions.CustomPESectionAlignment != null)
-            {
-                int alignment = _commandLineOptions.CustomPESectionAlignment.Value;
-                bool invalidArgument = false;
-                if (alignment <= 4096)
-                {
-                    invalidArgument = true;
-                }
-                if ((alignment & (alignment - 1)) != 0)
-                {
-                    invalidArgument = true; // Alignment not power of two
-                }
-
-                if (invalidArgument)
-                    throw new CommandLineException(SR.InvalidCustomPESectionAlignment);
-            }
-
             //
             // Set target Architecture and OS
             //
@@ -165,7 +141,10 @@ namespace ILCompiler
                 else
                     throw new CommandLineException(SR.TargetOSUnsupported);
             }
+        }
 
+        private InstructionSetSupport ConfigureInstructionSetSupport()
+        {
             InstructionSetSupportBuilder instructionSetSupportBuilder = new InstructionSetSupportBuilder(_targetArchitecture);
 
             // Ready to run images are built with certain instruction set baselines
@@ -258,17 +237,51 @@ namespace ILCompiler
             optimisticInstructionSet.Remove(unsupportedInstructionSet);
             optimisticInstructionSet.Add(supportedInstructionSet);
 
-            var instructionSetSupport = new InstructionSetSupport(supportedInstructionSet,
+            return new InstructionSetSupport(supportedInstructionSet,
                                                                   unsupportedInstructionSet,
                                                                   optimisticInstructionSet,
                                                                   InstructionSetSupportBuilder.GetNonSpecifiableInstructionSetsForArch(_targetArchitecture),
                                                                   _targetArchitecture);
+        }
 
+        private void CheckCustomPESectionAlignment()
+        {
+            if (_commandLineOptions.CustomPESectionAlignment != null)
+            {
+                int alignment = _commandLineOptions.CustomPESectionAlignment.Value;
+                bool invalidArgument = false;
+                if (alignment < 4096)
+                {
+                    invalidArgument = true;
+                }
+                if ((alignment & (alignment - 1)) != 0)
+                {
+                    invalidArgument = true; // Alignment not power of two
+                }
+
+                if (invalidArgument)
+                    throw new CommandLineException(SR.InvalidCustomPESectionAlignment);
+            }
+        }
+
+        private int Run()
+        {
             using (PerfEventSource.StartStopEvents.CompilationEvents())
             {
                 ICompilation compilation;
                 using (PerfEventSource.StartStopEvents.LoadingEvents())
                 {
+                    InitializeDefaultOptions();
+
+                    ProcessCommandLine();
+
+                    if (_commandLineOptions.OutputFilePath == null)
+                        throw new CommandLineException(SR.MissingOutputFile);
+
+                    CheckCustomPESectionAlignment();
+                    ConfigureTarget();
+                    InstructionSetSupport instructionSetSupport = ConfigureInstructionSetSupport();
+
                     //
                     // Initialize type system context
                     //
@@ -584,6 +597,7 @@ namespace ILCompiler
 
         public static async Task<int> Main(string[] args)
         {
+            PerfEventSource.StartStopEvents.CommandLineProcessingStart();
             var command = CommandLineOptions.RootCommand();
             command.Handler = CommandHandler.Create<CommandLineOptions>((CommandLineOptions options) => InnerMain(options));
             return await command.InvokeAsync(args);
@@ -591,6 +605,7 @@ namespace ILCompiler
 
         private static int InnerMain(CommandLineOptions buildOptions)
         {
+            PerfEventSource.StartStopEvents.CommandLineProcessingStop();
 #if DEBUG
             try
             {

diff --git a/src/coreclr/src/tools/r2rtest/PerfEventSourceListener.cs b/src/coreclr/src/tools/r2rtest/PerfEventSourceListener.cs
index e611359..0263176 100644 (file)
--- a/src/coreclr/src/tools/r2rtest/PerfEventSourceListener.cs
+++ b/src/coreclr/src/tools/r2rtest/PerfEventSourceListener.cs
@@ -17,9 +17,11 @@ public sealed class PerfEventSourceListener
     private ManualResetEvent _doneWarmup = new ManualResetEvent(false);
     private ManualResetEvent _doneCompilation = new ManualResetEvent(false);
     private const string providerName = "Microsoft-ILCompiler-Perf";
+    private const string graphProviderName = "Microsoft-ILCompiler-Graph-Perf";
     private readonly int _totalRealRuns;
     private int _doneCompilationCount = 0;
     private int _doneWarmupCount = 0;
+    private double _commandlineParseMsec = 0;
     private double _compilationMsec = 0;
     private double _loadingMsec = 0;
     private double _graphProcessingMsec = 0;
@@ -34,6 +36,7 @@ public sealed class PerfEventSourceListener
     {
         _totalRealRuns = totalRealRuns;
         traceEventSession.EnableProvider(providerName, TraceEventLevel.Verbose);
+        traceEventSession.EnableProvider(graphProviderName, TraceEventLevel.Verbose);
 
         traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "Compilation/Start", delegate (TraceEvent traceEvent)
         {
@@ -65,6 +68,16 @@ public sealed class PerfEventSourceListener
         // For all of the events below, we only want to process them after the warmup is complete. We can't just start this listener after
         // we have started the warmup because those runs might take some time, and we don't want to erroneously process warmup events when
         // trying to measure the real runs.
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "CommandLineProcessing/Start", delegate (TraceEvent traceEvent)
+        {
+            if (_doneWarmup.WaitOne(0))
+                _commandlineParseMsec -= traceEvent.TimeStampRelativeMSec;
+        });
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "CommandLineProcessing/Stop", delegate (TraceEvent traceEvent)
+        {
+            if (_doneWarmup.WaitOne(0))
+                _commandlineParseMsec += traceEvent.TimeStampRelativeMSec;
+        });
         traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "Loading/Start", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
@@ -76,12 +89,12 @@ public sealed class PerfEventSourceListener
                 _loadingMsec += traceEvent.TimeStampRelativeMSec;
         });
 
-        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "GraphProcessing/Start", delegate (TraceEvent traceEvent)
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(graphProviderName, "GraphProcessing/Start", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
                 _graphProcessingMsec -= traceEvent.TimeStampRelativeMSec;
         });
-        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "GraphProcessing/Stop", delegate (TraceEvent traceEvent)
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(graphProviderName, "GraphProcessing/Stop", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
                 _graphProcessingMsec += traceEvent.TimeStampRelativeMSec;
@@ -124,18 +137,18 @@ public sealed class PerfEventSourceListener
         });
 
 
-        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "DependencyAnalysis/Start", delegate (TraceEvent traceEvent)
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(graphProviderName, "DependencyAnalysis/Start", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
                 _dependencyAnalysisMsec -= traceEvent.TimeStampRelativeMSec;
         });
-        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "DependencyAnalysis/Stop", delegate (TraceEvent traceEvent)
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(graphProviderName, "DependencyAnalysis/Stop", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
                 _dependencyAnalysisMsec += traceEvent.TimeStampRelativeMSec;
         });
 
-        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(providerName, "AddedNodeToMarkStack", delegate (TraceEvent traceEvent)
+        traceEventSession.Source.Dynamic.AddCallbackForProviderEvent(graphProviderName, "AddedNodeToMarkStack", delegate (TraceEvent traceEvent)
         {
             if (_doneWarmup.WaitOne(0))
                 nodesAddedToMarkStack++;
@@ -149,6 +162,7 @@ public sealed class PerfEventSourceListener
     {
         _doneCompilation.WaitOne();
         IndentedTextWriter writer = new IndentedTextWriter(Console.Out);
+        writer.WriteLine($"Command line processing time: {_commandlineParseMsec / _totalRealRuns:F2} ms");
         writer.WriteLine($"Total average compilation time: {_compilationMsec / _totalRealRuns:F2} ms");
         writer.WriteLine($"Phase breakdown (average):");
         writer.Indent++;