public static JITStatsEx Create(TraceLoadedDotNetRuntime mang)
{
JITStatsEx stats = new JITStatsEx();
if (mang.JIT.Stats().BackgroundJitThread != 0)
{
stats.TotalBGJITStats = new JITStats();
foreach (TraceJittedMethod _method in mang.JIT.Methods)
{
stats.TotalBGJITStats.AddMethodToStatistics(_method);
}
}
// Compute module level stats, we do it here because we may not have the IL method name until late.
stats.TotalModuleStats = new SortedDictionary <string, JITStats>(StringComparer.OrdinalIgnoreCase);
foreach (var _method in mang.JIT.Methods)
{
if (_method.ModuleILPath != null)
{
if (!stats.TotalModuleStats.ContainsKey(_method.ModuleILPath))
{
stats.TotalModuleStats.Add(_method.ModuleILPath, new JITStats());
}
JITStats moduleStats = stats.TotalModuleStats[_method.ModuleILPath];
moduleStats.AddMethodToStatistics(_method);
}
}
return(stats);
}
public static void ToXml(TextWriter writer, TraceProcess stats, TraceLoadedDotNetRuntime runtime, string indent)
{
JITStatsEx statsEx = JITStatsEx.Create(runtime);
// TODO pay attention to indent;
writer.Write(" <JitProcess Process=\"{0}\" ProcessID=\"{1}\" JitTimeMSec=\"{2:n3}\" Count=\"{3}\" ILSize=\"{4}\" NativeSize=\"{5}\"",
stats.Name, stats.ProcessID, runtime.JIT.Stats().TotalCpuTimeMSec, runtime.JIT.Stats().Count, runtime.JIT.Stats().TotalILSize, runtime.JIT.Stats().TotalNativeSize);
if (stats.CPUMSec != 0)
{
writer.Write(" ProcessCpuTimeMsec=\"{0}\"", stats.CPUMSec);
}
if (!string.IsNullOrEmpty(stats.CommandLine))
{
writer.Write(" CommandLine=\"{0}\"", XmlUtilities.XmlEscape(stats.CommandLine, false));
}
writer.WriteLine(">");
writer.WriteLine(" <JitEvents>");
foreach (TraceJittedMethod _event in runtime.JIT.Methods)
{
ToXml(writer, _event);
}
writer.WriteLine(" </JitEvents>");
writer.WriteLine(" <ModuleStats Count=\"{0}\" TotalCount=\"{1}\" TotalJitTimeMSec=\"{2:n3}\" TotalILSize=\"{3}\" TotalNativeSize=\"{4}\">",
statsEx.TotalModuleStats.Count, runtime.JIT.Stats().Count, runtime.JIT.Stats().TotalCpuTimeMSec, runtime.JIT.Stats().TotalILSize, runtime.JIT.Stats().TotalNativeSize);
// Sort the module list by Jit Time;
List <string> moduleNames = new List <string>(statsEx.TotalModuleStats.Keys);
moduleNames.Sort(delegate(string x, string y)
{
double diff = statsEx.TotalModuleStats[y].TotalCpuTimeMSec - statsEx.TotalModuleStats[x].TotalCpuTimeMSec;
if (diff > 0)
{
return(1);
}
else if (diff < 0)
{
return(-1);
}
return(0);
});
foreach (string moduleName in moduleNames)
{
JITStats info = statsEx.TotalModuleStats[moduleName];
writer.Write("<Module");
writer.Write(" JitTimeMSec={0}", StringUtilities.QuotePadLeft(info.TotalCpuTimeMSec.ToString("n3"), 11));
writer.Write(" Count={0}", StringUtilities.QuotePadLeft(info.Count.ToString(), 7));
writer.Write(" ILSize={0}", StringUtilities.QuotePadLeft(info.TotalILSize.ToString(), 9));
writer.Write(" NativeSize={0}", StringUtilities.QuotePadLeft(info.TotalNativeSize.ToString(), 9));
writer.Write(" Name=\"{0}\"", moduleName);
writer.WriteLine("/>");
}
writer.WriteLine(" </ModuleStats>");
writer.WriteLine(" </JitProcess>");
}
private void Clr_MethodJittingStarted(MethodJittingStartedTraceData obj)
{
IncompleteActionDesc incompleteDesc = new IncompleteActionDesc();
incompleteDesc.Start = new EventUID(obj);
incompleteDesc.Name = JITStats.GetMethodName(obj);
incompleteDesc.OperationType = "JIT";
IdOfIncompleteAction id = new IdOfIncompleteAction();
id.Identifier = obj.MethodID;
id.ThreadID = obj.ThreadID;
_incompleteJitEvents[id] = incompleteDesc;
}
public static void ToHtml(TextWriter writer, TraceProcess stats, TraceLoadedDotNetRuntime runtime, string fileName)
{
JITStatsEx statsEx = JITStatsEx.Create(runtime);
var usersGuideFile = ClrStatsUsersGuide.WriteUsersGuide(fileName);
bool hasInliningEvents = runtime.JIT.Stats().InliningSuccesses.Count > 0 || runtime.JIT.Stats().InliningFailures.Count > 0;
writer.WriteLine("<H3><A Name=\"Stats_{0}\"><font color=\"blue\">JIT Stats for for Process {1,5}: {2}</font><A></H3>", stats.ProcessID, stats.ProcessID, stats.Name);
writer.WriteLine("<UL>");
{
if (!string.IsNullOrEmpty(stats.CommandLine))
{
writer.WriteLine("<LI>CommandLine: {0}</LI>", stats.CommandLine);
}
writer.WriteLine("<LI>Process CPU Time: {0:n0} msec</LI>", stats.CPUMSec);
writer.WriteLine("<LI>Guidance on JIT data:");
writer.WriteLine("<UL>");
{
writer.WriteLine("<LI> <A HREF=\"{0}#UnderstandingJITPerf\">JIT Perf Users Guide</A></LI>", usersGuideFile);
if (runtime.JIT.Stats().BackgroundJitThread != 0 || runtime.JIT.Stats().BackgroundJitAbortedAtMSec != 0)
{
writer.WriteLine("<LI>Background JIT compilation (System.Runtime.ProfileOptimize) in use - <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide</A></LI>", usersGuideFile);
writer.WriteLine(" <UL>");
if (runtime.JIT.Stats().RecordedModules.Count == 0)
{
writer.WriteLine(" <LI><font color=\"red\">This trace is missing some background JIT events, which could result in incorrect information in the background JIT blocking reason column.</font></LI>");
writer.WriteLine(" <LI><font color=\"red\">Re-collect the trace enabling \"Background JIT\" events on the collection menu to fix this.</font></LI>");
}
if (runtime.JIT.Stats().BackgroundJitAbortedAtMSec != 0)
{
writer.WriteLine(" <LI><font color=\"red\">WARNING: Background JIT aborted at {0:n3} Msec</font></LI>", runtime.JIT.Stats().BackgroundJitAbortedAtMSec);
writer.WriteLine(" <LI>The last assembly before the abort was '{0}' loaded {1} at {2:n3}</LI>",
runtime.JIT.Stats().LastAssemblyLoadNameBeforeAbort, runtime.JIT.Stats().LastAssemblyLoadBeforeAbortSuccessful ? "successfully" : "unsuccessfully",
runtime.JIT.Stats().LastAssemblyLoadBeforeAbortMSec);
}
writer.WriteLine(" </UL>");
}
else if (runtime.JIT.Stats().BackgroundJitThread == 0)
{
if (runtime.JIT.Stats().BackgroundJITEventsOn)
{
writer.WriteLine("<LI>Background JIT compilation (System.Runtime.ProfileOptimize) not in use - <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide</A></LI>", usersGuideFile);
writer.WriteLine("<UL><LI>If there is a lot of JIT time enabling this may improve startup performance</LI></UL>");
}
else
{
writer.WriteLine("<LI>Background JIT compilation (System.Runtime.ProfileOptimize) events are not being collected - <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide</A></LI>", usersGuideFile);
writer.WriteLine("<UL><LI>If you are interested in seeing them enable the 'Background JIT' checkbox in the 'Advanced' section of the collection dialog when collecting the data.</LI></UL>");
}
}
if (!runtime.IsTieredCompilationEnabled)
{
writer.WriteLine("<LI>Tiered compilation not in use - <A HREF=\"{0}#UnderstandingTieredCompilation\">Guide</A></LI>", usersGuideFile);
writer.WriteLine("<UL><LI>On .Net Core, enabling this may improve application performance</LI></UL>");
}
else
{
writer.WriteLine("<LI>Tiered compilation in use - <A HREF=\"{0}#UnderstandingTieredCompilation\">Guide</A></LI>", usersGuideFile);
}
}
writer.WriteLine("</UL>");
writer.WriteLine("</LI>");
writer.WriteLine("<LI>Raw data:");
writer.WriteLine("<UL>");
{
writer.WriteLine("<LI>Individual JIT Events <A HREF=\"#Events_{0}\">Html</A> | <A HREF=\"command:excel/{0}\">Excel</A></LI>", stats.ProcessID);
if (hasInliningEvents)
{
writer.WriteLine("<LI>Inlining Decisions <A HREF=\"#Inlining_{0}\">Html</A> | <A HREF=\"command:excelInlining/{0}\">Excel</A></LI>", stats.ProcessID);
}
else
{
writer.WriteLine("<LI><I>No JIT Inlining data available. Consider enabling the JITInlining option.</I></LI>");
}
if (runtime.JIT.Stats().BackgroundJitThread != 0 || runtime.JIT.Stats().BackgroundJitAbortedAtMSec != 0)
{
writer.WriteLine("<LI>Background Jit Diagnostics <A HREF=\"command:excelBackgroundDiag/{0}\">Excel</A></LI>", stats.ProcessID);
}
}
writer.WriteLine("</UL>");
writer.WriteLine("</LI>");
//
// Summary table by trigger
//
writer.WriteLine("<LI> Summary of jitting time by trigger:");
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.WriteLine("<TR>" +
"<TH Title=\"The reason why the JIT was invoked.\">Jitting Trigger</TH>" +
"<TH Title=\"The number of times the JIT was invoked\">Num Compilations</TH>" +
"<TH Title=\"The % of all compilations that triggered by this trigger\">% of total jitted compilations</TH>" +
"<TH Title=\"The total time used by all compilations with the given trigger\">Jit Time msec</TH>" +
"<TH Title=\"The total time used by all compilations with the given trigger as a % of total CPU time used for the process\">Jit Time (% of total process CPU)</TH>" +
"</TR>");
writer.WriteLine(FormatThreadingModelTableRow("TOTAL", runtime.JIT.Stats().Count, runtime.JIT.Stats().TotalCpuTimeMSec, stats, runtime));
writer.WriteLine(FormatThreadingModelTableRow(CompilationThreadKind.Foreground, runtime.JIT.Stats().CountForeground, runtime.JIT.Stats().TotalForegroundCpuTimeMSec, stats, runtime));
writer.WriteLine(FormatThreadingModelTableRow(CompilationThreadKind.MulticoreJitBackground, runtime.JIT.Stats().CountBackgroundMultiCoreJit, runtime.JIT.Stats().TotalBackgroundMultiCoreJitCpuTimeMSec, stats, runtime));
writer.WriteLine(FormatThreadingModelTableRow(CompilationThreadKind.TieredCompilationBackground, runtime.JIT.Stats().CountBackgroundTieredCompilation, runtime.JIT.Stats().TotalBackgroundTieredCompilationCpuTimeMSec, stats, runtime));
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
writer.WriteLine("</LI>");
//
// Module table
//
// Sort the module list by Jit Time;
List <string> moduleNames = new List <string>(statsEx.TotalModuleStats.Keys);
moduleNames.Sort(delegate(string x, string y)
{
double diff = statsEx.TotalModuleStats[y].TotalCpuTimeMSec - statsEx.TotalModuleStats[x].TotalCpuTimeMSec;
if (diff > 0)
{
return(1);
}
else if (diff < 0)
{
return(-1);
}
return(0);
});
writer.WriteLine("<LI> Summary of jitting time by module:</P>");
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR>" +
"<TH Title=\"The name of the module\">Name</TH>" +
"<TH Title=\"The total CPU time spent jitting for all methods in this module\">JitTime<BR/>msec</TH>" +
"<TH Title=\"The number of times the JIT was invoked for methods in this module\">Num Compilations</TH>" +
"<TH Title=\"The total amount of IL processed by the JIT for all methods in this module\">IL Size</TH>" +
"<TH Title=\"The total amount of native code produced by the JIT for all methods in this module\">Native Size</TH>" +
"<TH Title=\"Time spent jitting synchronously to produce code for methods that were just invoked. These compilations often consume time at startup.\">" + GetLongNameForThreadClassification(CompilationThreadKind.Foreground) + "<BR/>msec</TH>" +
"<TH Title=\"Time spent jitting asynchronously to produce code for methods the runtime speculates will be invoked in the future.\">" + GetLongNameForThreadClassification(CompilationThreadKind.MulticoreJitBackground) + "<BR/>msec</TH>" +
"<TH Title=\"Time spent jitting asynchronously to produce code for methods that is more optimized than their initial code.\">" + GetLongNameForThreadClassification(CompilationThreadKind.TieredCompilationBackground) + "<BR/>msec</TH>");
if (runtime.JIT.Stats().IsJitAllocSizePresent)
{
writer.Write("<TH Title=\"The total amount of heap memory requested for the code produced by the JIT for all methods in this module. \">JIT Hotcode request size</TH>");
writer.Write("<TH Title=\"The total amount of heap memory requested for the read-only data of code produced by the JIT for all methods in this module. \">JIT RO-data request size</TH>");
writer.Write("<TH Title=\"The total amount of heap memory allocated for the code produced by the JIT for all methods in this module. \">Allocated size for JIT code</TH>");
}
writer.WriteLine("</TR>");
string moduleTableRow = "<TR>" +
"<TD Align=\"Left\">{0}</TD>" +
"<TD Align=\"Center\">{1:n1}</TD>" +
"<TD Align=\"Center\">{2:n0}</TD>" +
"<TD Align=\"Center\">{3:n0}</TD>" +
"<TD Align=\"Center\">{4:n0}</TD>" +
"<TD Align=\"Center\">{5:n1}</TD>" +
"<TD Align=\"Center\">{6:n1}</TD>" +
"<TD Align=\"Center\">{7:n1}</TD>";
writer.Write(moduleTableRow,
"TOTAL",
runtime.JIT.Stats().TotalCpuTimeMSec,
runtime.JIT.Stats().Count,
runtime.JIT.Stats().TotalILSize,
runtime.JIT.Stats().TotalNativeSize,
runtime.JIT.Stats().TotalForegroundCpuTimeMSec,
runtime.JIT.Stats().TotalBackgroundMultiCoreJitCpuTimeMSec,
runtime.JIT.Stats().TotalBackgroundTieredCompilationCpuTimeMSec);
string allocSizeColumns = "";
if (runtime.JIT.Stats().IsJitAllocSizePresent)
{
allocSizeColumns +=
"<TD Align=\"Center\">{0:n0}</TD>" +
"<TD Align=\"Center\">{1:n0}</TD>" +
"<TD Align=\"Center\">{2:n0}</TD>";
writer.Write(allocSizeColumns,
runtime.JIT.Stats().TotalHotCodeAllocSize,
runtime.JIT.Stats().TotalRODataAllocSize,
runtime.JIT.Stats().TotalAllocSizeForJitCode);
}
writer.WriteLine();
foreach (string moduleName in moduleNames)
{
JITStats info = statsEx.TotalModuleStats[moduleName];
writer.Write(moduleTableRow,
moduleName.Length == 0 ? "<UNKNOWN>" : moduleName,
info.TotalCpuTimeMSec,
info.Count,
info.TotalILSize,
info.TotalNativeSize,
info.TotalForegroundCpuTimeMSec,
info.TotalBackgroundMultiCoreJitCpuTimeMSec,
info.TotalBackgroundTieredCompilationCpuTimeMSec);
if (runtime.JIT.Stats().IsJitAllocSizePresent)
{
writer.Write(allocSizeColumns,
info.TotalHotCodeAllocSize,
info.TotalRODataAllocSize,
info.TotalAllocSizeForJitCode);
}
writer.WriteLine("</TR>");
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
writer.WriteLine("</LI>");
}
writer.WriteLine("</UL>");
bool backgroundJitEnabled = runtime.JIT.Stats().BackgroundJitThread != 0;
writer.WriteLine("<HR/>");
writer.WriteLine("<H4><A Name=\"Events_{0}\">Individual JIT Events for Process {1,5}: {2}<A></H4>", stats.ProcessID, stats.ProcessID, stats.Name);
// We limit the number of JIT events we ut on the page because it makes the user exerience really bad (browsers crash)
const int maxEvents = 1000;
if (runtime.JIT.Methods.Count >= maxEvents)
{
writer.WriteLine("<p><Font color=\"red\">Warning: Truncating JIT events to " + maxEvents + ". <A HREF=\"command:excel/{0}\">View in excel</A> to look all of them.</font></p>", stats.ProcessID);
}
bool showOptimizationTiers = ShouldShowOptimizationTiers(runtime);
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write(
"<TR>" +
"<TH>Start<BR/>(msec)</TH>" +
"<TH>Jit Time<BR/>(msec)</TH>" +
"<TH>IL<BR/>Size</TH>" +
"<TH>Native<BR/>Size</TH>");
if (runtime.JIT.Stats().IsJitAllocSizePresent)
{
writer.Write(
"<TH>JIT Hotcode<BR/>request size</TH>" +
"<TH>JIT RO-data<BR/>request size</TH>" +
"<TH>Allocated size<BR/>for JIT code</TH>" +
"<TH>JIT Allocation<BR/>Flags</TH>"
);
}
if (showOptimizationTiers)
{
writer.Write("<TH Title=\"The optimization tier at which the method was jitted.\">Optimization<BR/>Tier</TH>");
}
writer.Write(
"<TH>Method Name</TH>" +
"<TH Title=\"Is Jit compilation occurring in the background for Multicore JIT (MC), in the background for tiered compilation (TC), or in the foreground on first execution of a method (FG).\">Trigger</TH>" +
"<TH>Module</TH>");
if (backgroundJitEnabled)
{
writer.Write(
"<TH Title=\"How far ahead of the method usage was relative to the background JIT operation.\">Distance Ahead</TH>" +
"<TH Title=\"Why the method was not JITTed in the background.\">Background JIT Blocking Reason</TH>");
}
writer.WriteLine("</TR>");
int eventCount = 0;
foreach (TraceJittedMethod _event in runtime.JIT.Methods)
{
writer.Write(
"<TR>" +
"<TD Align=\"Center\">{0:n3}</TD>" +
"<TD Align=\"Center\">{1:n1}</TD>" +
"<TD Align=\"Center\">{2:n0}</TD>" +
"<TD Align=\"Center\">{3:n0}</TD>",
_event.StartTimeMSec,
_event.CompileCpuTimeMSec,
_event.ILSize,
_event.NativeSize);
if (_event.IsJitAllocSizePresent)
{
writer.Write(
"<TD Align=\"Center\">{0}</TD>" +
"<TD Align=\"Center\">{1}</TD>" +
"<TD Align=\"Center\">{2}</TD>" +
"<TD Align=\"Center\">{3}</TD>",
_event.JitHotCodeRequestSize,
_event.JitRODataRequestSize,
_event.AllocatedSizeForJitCode,
_event.JitAllocFlag
);
}
if (showOptimizationTiers)
{
writer.Write(
"<TD Align=\"Center\">{0}</TD>",
_event.OptimizationTier == OptimizationTier.Unknown ? string.Empty : _event.OptimizationTier.ToString());
}
writer.Write(
"<TD Align=Left>{0}</TD>" +
"<TD Align=\"Center\">{1}</TD>" +
"<TD Align=\"Center\">{2}</TD>",
_event.MethodName ?? " ",
GetShortNameForThreadClassification(_event.CompilationThreadKind),
_event.ModuleILPath.Length != 0 ? Path.GetFileName(_event.ModuleILPath) : "<UNKNOWN>");
if (backgroundJitEnabled)
{
writer.Write(
"<TD Align=\"Center\">{0:n3}</TD>" +
"<TD Align=\"Left\">{1}</TD>",
_event.DistanceAhead,
_event.CompilationThreadKind == CompilationThreadKind.MulticoreJitBackground ? "Not blocked" : _event.BlockedReason);
}
writer.WriteLine("</TR>");
eventCount++;
if (eventCount >= maxEvents)
{
break;
}
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
if (hasInliningEvents)
{
writer.WriteLine("<HR/>");
writer.WriteLine("<A Name=\"Inlining_{0}\">", stats.ProcessID);
writer.WriteLine("<H4>Successful Inlinings for Process {0,5}: {1}<A></H4>", stats.ProcessID, stats.Name);
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR><TH>Method Begin Compiled</TH><TH>Inliner</TH><TH>Inlinee</TH></TR>");
foreach (InliningSuccessResult success in runtime.JIT.Stats().InliningSuccesses)
{
writer.Write("<TR><TD>{0}</TD><TD>{1}</TD><TD>{2}</TD></TR>", success.MethodBeingCompiled, success.Inliner, success.Inlinee);
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
writer.WriteLine("<H4>Failed Inlinings for Process {0,5}: {1}<A></H4>", stats.ProcessID, stats.Name);
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR><TH>Method Begin Compiled</TH><TH>Inliner</TH><TH>Inlinee</TH><TH>Failure Reason</TH></TR>");
foreach (InliningFailureResult failure in runtime.JIT.Stats().InliningFailures)
{
writer.Write("<TR><TD>{0}</TD><TD>{1}</TD><TD>{2}</TD><TD>{3}</TD></TR>", failure.MethodBeingCompiled, failure.Inliner, failure.Inlinee, failure.Reason);
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
}
writer.WriteLine("<HR/><HR/><BR/><BR/>");
}
public static void ToHtml(TextWriter writer, TraceProcess stats, TraceLoadedDotNetRuntime runtime, string fileName)
{
JITStatsEx statsEx = JITStatsEx.Create(runtime);
var usersGuideFile = ClrStatsUsersGuide.WriteUsersGuide(fileName);
bool hasInliningEvents = runtime.JIT.Stats().InliningSuccesses.Count > 0 || runtime.JIT.Stats().InliningFailures.Count > 0;
writer.WriteLine("<H3><A Name=\"Stats_{0}\"><font color=\"blue\">JIT Stats for for Process {1,5}: {2}</font><A></H3>",stats.ProcessID, stats.ProcessID, stats.Name);
writer.WriteLine("<UL>");
if (!runtime.JIT.Stats().IsClr4)
writer.WriteLine("<LI><Font color=\"red\">Warning: Could not confirm that a V4.0 CLR was loaded. JitTime or ILSize can only be computed for V4.0 runtimes. Otherwise their value will appear as 0.</font></LI>");
if (!string.IsNullOrEmpty(stats.CommandLine))
writer.WriteLine("<LI>CommandLine: {0}</LI>", stats.CommandLine);
writer.WriteLine("<LI>Process CPU Time: {0:n0} msec</LI>", stats.CPUMSec);
if (runtime.JIT.Stats().BackgroundJitThread != 0 || runtime.JIT.Stats().BackgroundJitAbortedAtMSec != 0)
{
writer.WriteLine("<LI>This process uses Background JIT compilation (System.Runtime.ProfileOptimize)</LI>");
writer.WriteLine(" <UL>");
if (runtime.JIT.Stats().RecordedModules.Count == 0)
{
writer.WriteLine(" <LI><font color=\"red\">This trace is missing some background JIT events, which could result in incorrect information in the background JIT blocking reason column.</font></LI>");
writer.WriteLine(" <LI><font color=\"red\">Re-collect the trace enabling \"Background JIT\" events on the collection menu to fix this.</font></LI>");
}
if (runtime.JIT.Stats().BackgroundJitAbortedAtMSec != 0)
{
writer.WriteLine(" <LI><font color=\"red\">WARNING: Background JIT aborted at {0:n3} Msec</font></LI>", runtime.JIT.Stats().BackgroundJitAbortedAtMSec);
writer.WriteLine(" <LI>The last assembly before the abort was '{0}' loaded {1} at {2:n3}</LI>",
runtime.JIT.Stats().LastAssemblyLoadNameBeforeAbort, runtime.JIT.Stats().LastAssemblyLoadBeforeAbortSuccessful ? "successfully" : "unsuccessfully",
runtime.JIT.Stats().LastAssemblyLoadBeforeAbortMSec);
}
if (runtime.JIT.Stats().BackgroundJitThread != 0)
{
var foregroundJitTimeMSec = runtime.JIT.Stats().TotalCpuTimeMSec - statsEx.TotalBGJITStats.TotalCpuTimeMSec;
writer.WriteLine(" <LI><strong>JIT time NOT moved to background thread</strong> : {0:n0}</LI> ({1:n1}%)",
foregroundJitTimeMSec, foregroundJitTimeMSec * 100.0 / runtime.JIT.Stats().TotalCpuTimeMSec);
var foregroundCount = runtime.JIT.Stats().Count - statsEx.TotalBGJITStats.Count;
writer.WriteLine(" <LI>Methods Not moved to background thread: {0:n0} ({1:n1}%)</LI>",
foregroundCount, foregroundCount * 100.0 / runtime.JIT.Stats().Count);
writer.WriteLine(" <LI>Methods Background JITTed : {0:n0} ({1:n1}%)</LI>",
statsEx.TotalBGJITStats.Count, statsEx.TotalBGJITStats.Count * 100.0 / runtime.JIT.Stats().Count);
writer.WriteLine(" <LI>MSec Background JITTing : {0:n0}</LI>", statsEx.TotalBGJITStats.TotalCpuTimeMSec);
writer.WriteLine(" <LI>Background JIT Thread : {0}</LI>", runtime.JIT.Stats().BackgroundJitThread);
}
writer.WriteLine(" <LI> <A HREF=\"command:excelBackgroundDiag/{0}\">View Raw Background Jit Diagnostics</A></LI></UL>", stats.ProcessID);
writer.WriteLine(" <LI> See <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide to Background JIT</A></LI> for more on background JIT", usersGuideFile);
writer.WriteLine(" </UL>");
}
writer.WriteLine("<LI>Total Number of JIT compiled methods : {0:n0}</LI>", runtime.JIT.Stats().Count);
writer.WriteLine("<LI>Total MSec JIT compiling : {0:n0}</LI>", runtime.JIT.Stats().TotalCpuTimeMSec);
if (runtime.JIT.Stats().TotalCpuTimeMSec != 0)
writer.WriteLine("<LI>JIT compilation time as a percentage of total process CPU time : {0:f1}%</LI>", runtime.JIT.Stats().TotalCpuTimeMSec * 100.0 / stats.CPUMSec);
writer.WriteLine("<LI><A HREF=\"#Events_{0}\">Individual JIT Events</A></LI>", stats.ProcessID);
writer.WriteLine("<UL><LI> <A HREF=\"command:excel/{0}\">View in Excel</A></LI></UL>", stats.ProcessID);
if (hasInliningEvents)
{
writer.WriteLine("<LI><A HREF=\"#Inlining_{0}\">Inlining Decisions</A></LI>", stats.ProcessID);
writer.WriteLine("<UL><LI> <A HREF=\"command:excelInlining/{0}\">View in Excel</A></LI></UL>", stats.ProcessID);
}
else
{
writer.WriteLine("<LI><I>No JIT Inlining data available. Consider enabling the JITInlining option.</I></LI>", stats.ProcessID);
}
writer.WriteLine("<LI> <A HREF=\"{0}#UnderstandingJITPerf\">JIT Perf Users Guide</A></LI>", usersGuideFile);
writer.WriteLine("</UL>");
if (runtime.JIT.Stats().BackgroundJitThread == 0)
{
if (runtime.JIT.Stats().BackgroundJITEventsOn)
{
writer.WriteLine("<P>" +
"<b>This process does not use background JIT compilation.</b> If there is a lot of JIT time and NGEN is not an possible\r\n" +
"you should consider using Background JIT compilation.\r\n" +
"See <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide to Background JIT</A> for more." +
"</P>", usersGuideFile);
}
else
{
writer.WriteLine("<P>" +
"<b>Background JIT compilation events are not being collected.</b> If you are interested in seeing the operation of Background JIT\r\n" +
"Enabled the 'Background JIT' checkbox in the 'Advanced' section of the collection dialog when collecting the data." +
"See <A HREF=\"{0}#UnderstandingBackgroundJIT\">Guide to Background JIT</A> for more." +
"</P>", usersGuideFile);
}
}
writer.WriteLine("<P>" +
"Below is a table of the time taken to JIT compile the methods used in the program, broken down by module. \r\n" +
"If this time is significant you can eliminate it by <A href=\"http://msdn.microsoft.com/en-us/magazine/cc163808.aspx\">NGening</A> your application. \r\n" +
"This will improve the startup time for your app. \r\n" +
"</P>");
writer.WriteLine("<P>" +
"The list below is also useful for tuning the startup performance of your application in general. \r\n" +
"In general you want as little to be run during startup as possible. \r\n" +
"If you have 1000s of methods being compiled on startup " +
"you should try to defer some of that computation until absolutely necessary.\r\n" +
"</P>");
// Sort the module list by Jit Time;
List<string> moduleNames = new List<string>(statsEx.TotalModuleStats.Keys);
moduleNames.Sort(delegate (string x, string y)
{
double diff = statsEx.TotalModuleStats[y].TotalCpuTimeMSec - statsEx.TotalModuleStats[x].TotalCpuTimeMSec;
if (diff > 0)
return 1;
else if (diff < 0)
return -1;
return 0;
});
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.WriteLine("<TR><TH>Name</TH><TH>JitTime<BR/>msec</TH><TH>Num Methods</TH><TH>IL Size</TH><TH>Native Size</TH></TR>");
writer.WriteLine("<TR><TD Align=\"Left\">{0}</TD><TD Align=\"Center\">{1:n1}</TD><TD Align=\"Center\">{2:n0}</TD><TD Align=\"Center\">{3:n0}</TD><TD Align=\"Center\">{4:n0}</TD></TR>",
"TOTAL", runtime.JIT.Stats().TotalCpuTimeMSec, runtime.JIT.Stats().Count, runtime.JIT.Stats().TotalILSize, runtime.JIT.Stats().TotalNativeSize);
foreach (string moduleName in moduleNames)
{
JITStats info = statsEx.TotalModuleStats[moduleName];
writer.WriteLine("<TR><TD Align=\"Center\">{0}</TD><TD Align=\"Center\">{1:n1}</TD><TD Align=\"Center\">{2:n0}</TD><TD Align=\"Center\">{3:n0}</TD><TD Align=\"Center\">{4:n0}</TD></TR>",
moduleName.Length == 0 ? "<UNKNOWN>" : moduleName, info.TotalCpuTimeMSec, info.Count, info.TotalILSize, info.TotalNativeSize);
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
bool backgroundJitEnabled = runtime.JIT.Stats().BackgroundJitThread != 0;
writer.WriteLine("<HR/>");
writer.WriteLine("<H4><A Name=\"Events_{0}\">Individual JIT Events for Process {1,5}: {2}<A></H4>", stats.ProcessID, stats.ProcessID, stats.Name);
// We limit the number of JIT events we ut on the page because it makes the user exerience really bad (browsers crash)
const int maxEvents = 1000;
if (runtime.JIT.Methods.Count >= maxEvents)
writer.WriteLine("<p><Font color=\"red\">Warning: Truncating JIT events to " + maxEvents + ". Use 'View in Excel' link above to look all of them</font></p>");
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR><TH>Start (msec)</TH><TH>JitTime</BR>msec</TH><TH>IL Size</TH><TH>Native Size</TH><TH>Method Name</TH>" +
"<TH Title=\"Is Jit compilation occuring in the background (BG) or not (JIT).\">BG</TH><TH>Module</TH>");
if (backgroundJitEnabled)
{
writer.Write("<TH Title=\"How far ahead of the method usage was relative to the background JIT operation.\">Distance Ahead</TH><TH Title=\"Why the method was not JITTed in the background.\">Background JIT Blocking Reason</TH>");
}
writer.WriteLine("</TR>");
int eventCount = 0;
foreach (TraceJittedMethod _event in runtime.JIT.Methods)
{
writer.Write("<TR><TD Align=\"Center\">{0:n3}</TD><TD Align=\"Center\">{1:n1}</TD><TD Align=\"Center\">{2:n0}</TD><TD Align=\"Center\">{3:n0}</TD><TD Align=Left>{4}</TD><TD Align=\"Center\">{5}</TD><TD Align=\"Center\">{6}</TD>",
_event.StartTimeMSec, _event.CompileCpuTimeMSec, _event.ILSize, _event.NativeSize, _event.MethodName ?? " ", (_event.IsBackGround ? "BG" : "JIT"),
_event.ModuleILPath.Length != 0 ? Path.GetFileName(_event.ModuleILPath) : "<UNKNOWN>");
if (backgroundJitEnabled)
{
writer.Write("<TD Align=\"Center\">{0:n3}</TD><TD Align=\"Left\">{1}</TD>",
_event.DistanceAhead, _event.IsBackGround ? "Not blocked" : _event.BlockedReason);
}
writer.WriteLine("</TR>");
eventCount++;
if (eventCount >= maxEvents)
break;
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
if (hasInliningEvents)
{
writer.WriteLine("<HR/>");
writer.WriteLine("<A Name=\"Inlining_{0}\">", stats.ProcessID);
writer.WriteLine("<H4>Successful Inlinings for Process {0,5}: {1}<A></H4>", stats.ProcessID, stats.Name);
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR><TH>Method Begin Compiled</TH><TH>Inliner</TH><TH>Inlinee</TH></TR>");
foreach (InliningSuccessResult success in runtime.JIT.Stats().InliningSuccesses)
{
writer.Write("<TR><TD>{0}</TD><TD>{1}</TD><TD>{2}</TD></TR>", success.MethodBeingCompiled, success.Inliner, success.Inlinee);
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
writer.WriteLine("<H4>Failed Inlinings for Process {0,5}: {1}<A></H4>", stats.ProcessID, stats.Name);
writer.WriteLine("<Center>");
writer.WriteLine("<Table Border=\"1\">");
writer.Write("<TR><TH>Method Begin Compiled</TH><TH>Inliner</TH><TH>Inlinee</TH><TH>Failure Reason</TH></TR>");
foreach (InliningFailureResult failure in runtime.JIT.Stats().InliningFailures)
{
writer.Write("<TR><TD>{0}</TD><TD>{1}</TD><TD>{2}</TD><TD>{3}</TD></TR>", failure.MethodBeingCompiled, failure.Inliner, failure.Inlinee, failure.Reason);
}
writer.WriteLine("</Table>");
writer.WriteLine("</Center>");
}
writer.WriteLine("<HR/><HR/><BR/><BR/>");
}
private void Clr_MethodR2RGetEntryPoint(R2RGetEntryPointTraceData obj)
{
IdOfIncompleteAction id = new IdOfIncompleteAction();
id.Identifier = obj.MethodID;
id.ThreadID = obj.ThreadID;
// If we had a R2R start lookup event, capture that start time, otherwise, use the R2REntrypoint
// data as both start and stop
EventUID startUID = new EventUID(obj);
if (_incompleteR2REvents.TryGetValue(id, out IncompleteActionDesc r2rStartData))
{
startUID = r2rStartData.Start;
_incompleteR2REvents.Remove(id);
}
if (obj.EntryPoint == 0)
{
// If Entrypoint is null then the search failed.
AddStartStopData(obj.ProcessID, id.ThreadID, startUID, new EventUID(obj), "R2R_Failed" + "(" + JITStats.GetMethodName(obj) + ")");
}
else
{
AddStartStopData(obj.ProcessID, id.ThreadID, startUID, new EventUID(obj), "R2R_Found" + "(" + JITStats.GetMethodName(obj) + ")");
}
}
