Merge pull request microsoft#1232 from davidwrighton/runtimeops_v2

Runtime Loader advanced event view

Author: brianrob

src/PerfView/ClrStats.cs

@@ -1,4 +1,5 @@
 // Copyright (c) Microsoft Corporation.  All rights reserved
+using Microsoft.Diagnostics.Tracing;
 using Microsoft.Diagnostics.Tracing.Analysis;
 using Microsoft.Diagnostics.Utilities;
 using System.Collections.Generic;
@@ -9,9 +10,9 @@ namespace Stats
 {
     internal static class ClrStats
     {
-        public enum ReportType { JIT, GC };
+        public enum ReportType { JIT, GC, RuntimeLoader };
 
-        public static void ToHtml(TextWriter writer, List<TraceProcess> perProc, string fileName, string title, ReportType type, bool justBody = false, bool doServerGCReport = false)
+        public static void ToHtml(TextWriter writer, List<TraceProcess> perProc, string fileName, string title, ReportType type, bool justBody = false, bool doServerGCReport = false, RuntimeLoaderStatsData runtimeOpsStats = null)
         {
             if (!justBody)
             {
@@ -33,6 +34,10 @@ public static void ToHtml(TextWriter writer, List<TraceProcess> perProc, string
             {
                 sortedProcs.Sort((TraceProcess p1, TraceProcess p2) => { return -p1.LoadedDotNetRuntime().GC.Stats().MaxSizePeakMB.CompareTo(p2.LoadedDotNetRuntime().GC.Stats().MaxSizePeakMB); });
             }
+            else if (type == ReportType.RuntimeLoader)
+            {
+                sortedProcs.Sort((TraceProcess p1, TraceProcess p2) => { return -RuntimeLoaderStats.TotalCPUMSec(p1, runtimeOpsStats).CompareTo(RuntimeLoaderStats.TotalCPUMSec(p2, runtimeOpsStats)); });
+            }
 
             int count = sortedProcs.Count;
 
@@ -53,6 +58,11 @@ public static void ToHtml(TextWriter writer, List<TraceProcess> perProc, string
                         continue;
                     }
 
+                    if (type == ReportType.RuntimeLoader && !RuntimeLoaderStats.IsInteresting(data, runtimeOpsStats))
+                    {
+                        continue;
+                    }
+
                     var id = Shorten(data.CommandLine);
                     if (string.IsNullOrEmpty(id))
                     {
@@ -81,6 +91,11 @@ public static void ToHtml(TextWriter writer, List<TraceProcess> perProc, string
                 {
                     Stats.JitStats.ToHtml(writer, stats, mang, fileName);
                 }
+
+                if (type == ReportType.RuntimeLoader && RuntimeLoaderStats.IsInteresting(stats, runtimeOpsStats))
+                {
+                    Stats.RuntimeLoaderStats.ToHtml(writer, stats, fileName, runtimeOpsStats);
+                }
             }
 
             writer.WriteLine("<BR/><BR/><BR/><BR/><BR/><BR/><BR/><BR/><BR/><BR/>");

src/PerfView/CommandLineArgs.cs

@@ -129,6 +129,7 @@ public static string GetHelpString(int maxLineWidth)
         public bool NetworkCapture;         // Capture the full packets of every incoming and outgoing  packet
         public bool NetMonCapture;          // Capture a NetMon-only trace as well as a standard ETW trace (implies NetworkCapture)  
         public bool CCWRefCount;            // Capture CCW references count increasing and decreasing
+        public bool RuntimeLoading;         // Capture information about runtime loading such as R2R and type load events
 
         public bool Wpr;                    // Collect like WPR (no zip, puts NGEN pdbs in a .ngenpdbs directory).  
 
@@ -505,6 +506,7 @@ private void SetupCommandLine(CommandLineParser parser)
             parser.DefineOptionalQualifier("DisableInlining", ref DisableInlining, "Turns off inlining (but only affects processes that start after trace start.");
             parser.DefineOptionalQualifier("JITInlining", ref JITInlining, "Turns on logging of successful and failed JIT inlining attempts.");
             parser.DefineOptionalQualifier("CCWRefCount", ref CCWRefCount, "Turns on logging of information about .NET Native CCW reference counting.");
+            parser.DefineOptionalQualifier("RuntimeLoading", ref RuntimeLoading, "Turn on logging of runtime loading operations.");
             parser.DefineOptionalQualifier("OSHeapProcess", ref OSHeapProcess, "Turn on per-allocation profiling of allocation from the OS heap for the process with the given process ID.");
             parser.DefineOptionalQualifier("OSHeapExe", ref OSHeapExe, "Turn on per-allocation profiling of allocation from the OS heap for the process with the given EXE (only filename WITH extension).");
 

src/PerfView/CommandProcessor.cs

@@ -353,6 +353,13 @@ public void Start(CommandLineArgs parsedArgs)
                 profilerKeywords |= ETWClrProfilerTraceEventParser.Keywords.DisableInlining;
             }
 
+            if (parsedArgs.RuntimeLoading)
+            {
+                parsedArgs.ClrEvents |= ClrTraceEventParser.Keywords.CompilationDiagnostic;
+                parsedArgs.ClrEvents |= ClrTraceEventParser.Keywords.MethodDiagnostic;
+                parsedArgs.ClrEvents |= ClrTraceEventParser.Keywords.TypeDiagnostic;
+            }
+
             if (profilerKeywords != 0)
             {
                 InstallETWClrProfiler(LogFile, (int)profilerKeywords);
@@ -3021,6 +3028,11 @@ private static string ParsedArgsAsString(string command, CommandLineArgs parsedA
                 cmdLineArgs += " /CCWRefCount";
             }
 
+            if (parsedArgs.RuntimeLoading)
+            {
+                cmdLineArgs += " /RuntimeLoading";
+            }
+
             // TODO FIX NOW this is sort ugly fix is so that commands are an enum 
             if (command == null)
             {

src/PerfView/Dialogs/RunCommandDialog.xaml

@@ -320,7 +320,11 @@
                     </TextBlock>                    
                     <CheckBox Grid.Row="0" Grid.Column="11" Name="CCWRefCountCheckBox" VerticalAlignment="Center"/>
 
-                    <CheckBox Grid.Row="0" Grid.Column="13" Name="Unused2" Visibility="Hidden" VerticalAlignment="Center"/>
+                    <TextBlock Grid.Row="0" Grid.Column="12" VerticalAlignment="Center" HorizontalAlignment="Right" Margin="8,2,5,2" 
+                               ToolTip="Log extended information about .NET Runtime loading including R2R and type load events." >
+                    <Hyperlink Command="Help" CommandParameter="RuntimeLoadingCheckBox">.NET Loader:</Hyperlink>
+                    </TextBlock>
+                    <CheckBox Grid.Row="0" Grid.Column="13" Name="RuntimeLoadingCheckBox" VerticalAlignment="Center" />
                 </Grid>
 
                 <!-- Check boxes for more clr events (GC Heap related) -->

src/PerfView/Dialogs/RunCommandDialog.xaml.cs

@@ -202,6 +202,11 @@ public RunCommandDialog(CommandLineArgs args, MainWindow mainWindow, bool isColl
                 CCWRefCountCheckBox.IsChecked = true;
             }
 
+            if (args.RuntimeLoading)
+            {
+                RuntimeLoadingCheckBox.IsChecked = true;
+            }
+
             if (args.DumpHeap)
             {
                 HeapSnapshotCheckBox.IsChecked = true;
@@ -774,6 +779,8 @@ private void OKButtonClick(object sender, RoutedEventArgs e)
                 }
 
                 m_args.CCWRefCount = CCWRefCountCheckBox.IsChecked ?? false;
+                m_args.RuntimeLoading = RuntimeLoadingCheckBox.IsChecked ?? false;
+
                 m_args.DumpHeap = HeapSnapshotCheckBox.IsChecked ?? false;
 
                 if (providers.Length > 0)

src/PerfView/PerfViewData.cs

@@ -1061,6 +1061,11 @@ protected virtual string DoCommand(string command, StatusBar worker, out Action
             return DoCommand(command, worker);
         }
 
+        protected virtual string DoCommand(Uri commandUri, StatusBar worker, out Action continuation)
+        {
+            return DoCommand(commandUri.LocalPath, worker, out continuation);
+        }
+
         public override void Open(Window parentWindow, StatusBar worker, Action doAfter)
         {
             if (Viewer == null)
@@ -1087,7 +1092,7 @@ public override void Open(Window parentWindow, StatusBar worker, Action doAfter)
                                 Viewer.StatusBar.StartWork("Following Hyperlink", delegate ()
                                 {
                                     Action continuation;
-                                    var message = DoCommand(e.Uri.LocalPath, Viewer.StatusBar, out continuation);
+                                    var message = DoCommand(e.Uri, Viewer.StatusBar, out continuation);
                                     Viewer.StatusBar.EndWork(delegate ()
                                     {
                                         if (message != null)
@@ -3531,6 +3536,82 @@ protected override void WriteHtmlBody(TraceLog dataFile, TextWriter writer, stri
         private Dictionary<int/*pid*/, Microsoft.Diagnostics.Tracing.Analysis.TraceProcess> m_gcStats;
     }
 
+    public class PerfViewRuntimeLoaderStats : PerfViewHtmlReport
+    {
+        public PerfViewRuntimeLoaderStats(PerfViewFile dataFile) : base(dataFile, "Runtime Loader") { }
+        protected override string DoCommand(Uri commandUri, StatusBar worker, out Action continuation)
+        {
+            continuation = null;
+
+            string command = commandUri.LocalPath;
+            string textStr = "txt/";
+            string csvStr = "csv/";
+            bool text = command.StartsWith(textStr);
+            bool csv = command.StartsWith(csvStr);
+
+            if (text || csv)
+            {
+                var rest = command.Substring(textStr.Length);
+
+
+                bool tree = true;
+                List<string> filters = null;
+                if (!String.IsNullOrEmpty(commandUri.Query))
+                {
+                    filters = new List<string>();
+                    tree = commandUri.Query.Contains("TreeView");
+                    if (commandUri.Query.Contains("JIT"))
+                        filters.Add("JIT");
+                    if (commandUri.Query.Contains("R2R_Found"))
+                        filters.Add("R2R_Found");
+                    if (commandUri.Query.Contains("R2R_Failed"))
+                        filters.Add("R2R_Failed");
+                    if (commandUri.Query.Contains("TypeLoad"))
+                        filters.Add("TypeLoad");
+                    if (commandUri.Query.Contains("AssemblyLoad"))
+                        filters.Add("AssemblyLoad");
+                }
+                string identifier = $"{(tree?"Tree":"Flat")}_";
+                if (filters != null)
+                {
+                    foreach (var filter in filters)
+                    {
+                        identifier = identifier + "_" + filter;
+                    }
+                }
+
+                var startMSec = double.Parse(rest.Substring(rest.IndexOf(',') + 1));
+                var processId = int.Parse(rest.Substring(0, rest.IndexOf(',')));
+                var processData = m_runtimeData.GetProcessDataFromProcessIDAndTimestamp(processId, startMSec);
+
+                var txtFile = CacheFiles.FindFile(FilePath, ".runtimeLoaderstats." + processId.ToString() + "_" + ((long)startMSec).ToString() + "_" + identifier + (csv ? ".csv" : ".txt"));
+                if (!File.Exists(txtFile) || File.GetLastWriteTimeUtc(txtFile) < File.GetLastWriteTimeUtc(FilePath) ||
+                    File.GetLastWriteTimeUtc(txtFile) < File.GetLastWriteTimeUtc(SupportFiles.MainAssemblyPath))
+                {
+                    Stats.RuntimeLoaderStats.ToTxt(txtFile, processData, filters.ToArray(), tree);
+                }
+                Command.Run(Command.Quote(txtFile), new CommandOptions().AddStart().AddTimeout(CommandOptions.Infinite));
+                System.Threading.Thread.Sleep(500);     // Give it time to start a bit.  
+                return "Opening Txt " + txtFile;
+            }
+            return "Unknown command " + command;
+        }
+
+        protected override void WriteHtmlBody(TraceLog dataFile, TextWriter writer, string fileName, TextWriter log)
+        {
+            using (var source = dataFile.Events.GetSource())
+            {
+                Microsoft.Diagnostics.Tracing.Analysis.TraceLoadedDotNetRuntimeExtensions.NeedLoadedDotNetRuntimes(source);
+                CLRRuntimeActivityComputer runtimeLoaderComputer = new CLRRuntimeActivityComputer(source);
+                source.Process();
+                m_runtimeData = runtimeLoaderComputer.RuntimeLoaderData;
+                Stats.ClrStats.ToHtml(writer, Microsoft.Diagnostics.Tracing.Analysis.TraceProcessesExtensions.Processes(source).ToList(), fileName, "Runtime Loader", Stats.ClrStats.ReportType.RuntimeLoader, true, runtimeOpsStats : m_runtimeData);
+            }
+        }
+
+        private RuntimeLoaderStatsData m_runtimeData;
+    }
+
     public class PerfViewJitStats : PerfViewHtmlReport
     {
         public PerfViewJitStats(PerfViewFile dataFile) : base(dataFile, "JITStats") { }
@@ -6921,6 +7002,9 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
             bool hasGCEvents = false;
             bool hasProjectNExecutionTracingEvents = false;
             bool hasDefenderEvents = false;
+            bool hasTypeLoad = false;
+            bool hasAssemblyLoad = false;
+            bool hasJIT = false;
 
             var stackEvents = new List<TraceEventCounts>();
             foreach (var counts in tracelog.Stats)
@@ -6981,6 +7065,19 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
                     hasDefenderEvents = true;
                 }
 
+                if (name.StartsWith("Method/JittingStarted"))
+                {
+                    hasJIT = true;
+                }
+                if (name.StartsWith("TypeLoad/Start"))
+                {
+                    hasTypeLoad = true;
+                }
+                if (name.StartsWith("Loader/AssemblyLoad"))
+                {
+                    hasAssemblyLoad = true;
+                }
+
                 if (counts.StackCount > 0)
                 {
                     hasAnyStacks = true;
@@ -7288,6 +7385,11 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
 
             advanced.Children.Add(new PerfViewJitStats(this));
 
+            if (hasJIT || hasAssemblyLoad || hasTypeLoad)
+            {
+                advanced.Children.Add(new PerfViewRuntimeLoaderStats(this));
+            }
+
             advanced.Children.Add(new PerfViewEventStats(this));
 
             m_Children.Add(new PerfViewEventSource(this));
@@ -8420,6 +8522,8 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
 
             bool hasGC = false;
             bool hasJIT = false;
+            bool hasTypeLoad = false;
+            bool hasAssemblyLoad = false;
             if (m_traceLog != null)
             {
                 foreach (TraceEventCounts eventStats in m_traceLog.Stats)
@@ -8432,6 +8536,14 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
                     {
                         hasJIT = true;
                     }
+                    else if (eventStats.EventName.StartsWith("TypeLoad/Start"))
+                    {
+                        hasTypeLoad = true;
+                    }
+                    else if (eventStats.EventName.StartsWith("Loader/AssemblyLoad"))
+                    {
+                        hasAssemblyLoad = true;
+                    }
                 }
             }
 
@@ -8466,6 +8578,11 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
                 {
                     advanced.AddChild(new PerfViewJitStats(this));
                 }
+
+                if (hasJIT || hasTypeLoad || hasAssemblyLoad)
+                {
+                    advanced.AddChild(new PerfViewRuntimeLoaderStats(this));
+                }
             }
 
             if (memory.Children.Count > 0)
@@ -8633,6 +8750,8 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
             bool hasGCAllocationTicks = false;
             bool hasObjectUpdate = false;
             bool hasMemAllocStacks = false;
+            bool hasTypeLoad = false;
+            bool hasAssemblyLoad = false;
             if (m_traceLog != null)
             {
                 foreach (TraceEventCounts eventStats in m_traceLog.Stats)
@@ -8666,6 +8785,14 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
                     {
                         hasMemAllocStacks = true;
                     }
+                    else if (eventStats.EventName.StartsWith("TypeLoad/Start"))
+                    {
+                        hasTypeLoad = true;
+                    }
+                    else if (eventStats.EventName.StartsWith("Loader/AssemblyLoad"))
+                    {
+                        hasAssemblyLoad = true;
+                    }
                 }
             }
 
@@ -8712,6 +8839,11 @@ protected override Action<Action> OpenImpl(Window parentWindow, StatusBar worker
                 {
                     advanced.AddChild(new PerfViewJitStats(this));
                 }
+
+                if (hasJIT || hasTypeLoad || hasAssemblyLoad)
+                {
+                    advanced.AddChild(new PerfViewRuntimeLoaderStats(this));
+                }
             }
 
             if (memory.Children.Count > 0)