/// <summary> /// The JIT start event breaks a name into its pieces. Reform the name from the pieces. /// </summary> private static string GetName(MethodJittingStartedTraceData data) { // Prepare sig (strip return value) var sig = ""; var sigWithRet = data.MethodSignature; var parenIdx = sigWithRet.IndexOf('('); if (0 <= parenIdx) { sig = sigWithRet.Substring(parenIdx); } // prepare class name (strip namespace) var className = data.MethodNamespace; var lastDot = className.LastIndexOf('.'); if (0 <= lastDot) { className = className.Substring(lastDot + 1); } var sep = "."; if (className.Length == 0) { sep = ""; } return(className + sep + data.MethodName + sig); }
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 Main(string[] args) { string traceFile = args[0]; string benchmarkName = "dotnet"; int benchmarkPid = -2; Dictionary <string, uint> allEventCounts = new Dictionary <string, uint>(); Dictionary <string, uint> eventCounts = new Dictionary <string, uint>(); Dictionary <string, uint> processCounts = new Dictionary <string, uint>(); using (var source = new ETWTraceEventSource(traceFile)) { source.Kernel.All += delegate(TraceEvent data) { if (allEventCounts.ContainsKey(data.EventName)) { allEventCounts[data.EventName]++; } else { allEventCounts[data.EventName] = 1; } if (data.ProcessID == benchmarkPid) { if (eventCounts.ContainsKey(data.EventName)) { eventCounts[data.EventName]++; } else { eventCounts[data.EventName] = 1; } } switch (data.EventName) { case "Process/Start": case "Process/DCStart": { // Process was running when tracing started (DCStart) // or started when tracing was running (Start) ProcessTraceData pdata = (ProcessTraceData)data; if (String.Equals(pdata.ProcessName, benchmarkName, StringComparison.OrdinalIgnoreCase)) { Console.WriteLine("Found process [{0}] {1}: {2}", pdata.ProcessID, pdata.ProcessName, pdata.CommandLine); benchmarkPid = pdata.ProcessID; } else { // Console.WriteLine("Ignoring events from process {0}", pdata.ProcessName); } break; } case "Image/DCStart": { ImageLoadTraceData imageLoadTraceData = (ImageLoadTraceData)data; if (data.ProcessID == 0) { string fileName = imageLoadTraceData.FileName; ulong imageBase = imageLoadTraceData.ImageBase; int imageSize = imageLoadTraceData.ImageSize; string fullName = fileName + "@" + imageBase.ToString(); if (!ImageMap.ContainsKey(fullName)) { ImageInfo imageInfo = new ImageInfo(Path.GetFileName(fileName), imageBase, imageSize); ImageMap.Add(fullName, imageInfo); } } break; } case "Image/Load": { ImageLoadTraceData imageLoadTraceData = (ImageLoadTraceData)data; if (imageLoadTraceData.ProcessID == benchmarkPid) { string fileName = imageLoadTraceData.FileName; ulong imageBase = imageLoadTraceData.ImageBase; int imageSize = imageLoadTraceData.ImageSize; // Suppress ngen images here, otherwise we lose visibility // into ngen methods... if (fileName.Contains(".ni.")) { break; } string fullName = fileName + "@" + imageBase.ToString(); if (!ImageMap.ContainsKey(fullName)) { ImageInfo imageInfo = new ImageInfo(Path.GetFileName(fileName), imageBase, imageSize); ImageMap.Add(fullName, imageInfo); } } break; } case "PerfInfo/PMCSample": { PMCCounterProfTraceData traceData = (PMCCounterProfTraceData)data; if (traceData.ProcessID == benchmarkPid) { ulong instructionPointer = traceData.InstructionPointer; // Not sure how to find the PMC reload interval... sigh ulong count = 1; UpdateSampleCountMap(instructionPointer, count); UpdateThreadCountMap(traceData.ThreadID, count); } break; } } }; source.Clr.All += delegate(TraceEvent data) { if (allEventCounts.ContainsKey(data.EventName)) { allEventCounts[data.EventName]++; } else { allEventCounts[data.EventName] = 1; } if (data.ProcessID == benchmarkPid) { if (eventCounts.ContainsKey(data.EventName)) { eventCounts[data.EventName]++; } else { eventCounts[data.EventName] = 1; } switch (data.EventName) { case "Method/JittingStarted": { MethodJittingStartedTraceData jitStartData = (MethodJittingStartedTraceData)data; JitInvocation jitInvocation = new JitInvocation(); jitInvocation.ThreadId = jitStartData.ThreadID; jitInvocation.MethodId = jitStartData.MethodID; jitInvocation.InitialThreadCount = ThreadCountMap[jitInvocation.ThreadId]; ActiveJitInvocations.Add(jitInvocation.ThreadId, jitInvocation); AllJitInvocations.Add(jitInvocation); break; } case "Method/LoadVerbose": { MethodLoadUnloadVerboseTraceData loadUnloadData = (MethodLoadUnloadVerboseTraceData)data; if (ActiveJitInvocations.ContainsKey(loadUnloadData.ThreadID)) { JitInvocation j = ActiveJitInvocations[loadUnloadData.ThreadID]; ActiveJitInvocations.Remove(j.ThreadId); j.FinalThreadCount = ThreadCountMap[j.ThreadId]; if (j.FinalThreadCount < j.InitialThreadCount) { Console.WriteLine("eh? negative jit count..."); } else { JitSampleCount += j.FinalThreadCount - j.InitialThreadCount; } } else { // ? } break; } case "Method/UnloadVerbose": { // Pretend this is an "image" MethodLoadUnloadVerboseTraceData loadUnloadData = (MethodLoadUnloadVerboseTraceData)data; string fullName = GetName(loadUnloadData); string key = fullName + "@" + loadUnloadData.MethodID.ToString("X"); if (!ImageMap.ContainsKey(key)) { ImageInfo methodInfo = new ImageInfo(fullName, loadUnloadData.MethodStartAddress, loadUnloadData.MethodSize); ImageMap.Add(key, methodInfo); methodInfo.IsJitGeneratedCode = true; methodInfo.IsJittedCode = loadUnloadData.IsJitted; } //else //{ // Console.WriteLine("eh? see method {0} again in rundown", fullName); //} break; } } } }; source.Process(); } AttributeSampleCounts(); //foreach (var e in allEventCounts) //{ // Console.WriteLine("Event {0} occurred {1} times", e.Key, e.Value); //} //foreach (var e in processCounts) //{ // Console.WriteLine("Process {0} had {1} events", e.Key, e.Value); //} if (!eventCounts.ContainsKey("PerfInfo/PMCSample")) { Console.WriteLine("No PMC events seen, sorry."); } else { ulong InstrsPerEvent = 65536; ulong pmcEvents = eventCounts["PerfInfo/PMCSample"]; Console.WriteLine("InstRetired for {0}: {1} events, {2:E} instrs", benchmarkName, pmcEvents, pmcEvents * InstrsPerEvent); Console.WriteLine("Jitting : {0:00.00%} ({1} methods)", (double)JitSampleCount / TotalSampleCount, AllJitInvocations.Count); // Console.WriteLine(" JitInterface : {0:00.00%}", (double) JitSampleCount - JitDllSampleCount); Console.WriteLine("Jit-generated code: {0:00.00%}", (double)JitGeneratedCodeSampleCount / TotalSampleCount); Console.WriteLine(" Jitted code : {0:00.00%}", (double)JittedCodeSampleCount / TotalSampleCount); Console.WriteLine(); double ufrac = (double)UnknownImageCount / TotalSampleCount; if (ufrac > 0.002) { Console.WriteLine("{0:00.00%} {1,-8:G3} {2} {3}", ufrac, UnknownImageCount * InstrsPerEvent, "? ", "Unknown"); } // Collect up significant counts List <ImageInfo> significantInfos = new List <ImageInfo>(); foreach (var i in ImageMap) { double frac = (double)i.Value.SampleCount / TotalSampleCount; if (frac > 0.002) { significantInfos.Add(i.Value); } } significantInfos.Sort(ImageInfo.MoreSamples); foreach (var i in significantInfos) { Console.WriteLine("{0:00.00%} {1,-8:G3} {2} {3}", (double)i.SampleCount / TotalSampleCount, i.SampleCount * InstrsPerEvent, i.IsJitGeneratedCode ? (i.IsJittedCode ? "jit " : "prejit") : "native", i.Name); } } }