/// <summary> /// Reports a stack trace /// </summary> /// <param name="ct">The cancellation token</param> /// <param name="console"></param> /// <param name="processId">The process to report the stack from.</param> /// <param name="name">The name of process to report the stack from.</param> /// <param name="output">The output path for the collected trace data.</param> /// <param name="duration">The duration of to trace the target for. </param> /// <returns></returns> private static async Task <int> Report(CancellationToken ct, IConsole console, int processId, string name, TimeSpan duration) { string tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace"; string tempEtlxFilename = ""; try { // Either processName or processId has to be specified. if (!string.IsNullOrEmpty(name)) { if (processId != 0) { Console.WriteLine("Can only specify either --name or --process-id option."); return(-1); } processId = CommandUtils.FindProcessIdWithName(name); if (processId < 0) { return(-1); } } if (processId < 0) { console.Error.WriteLine("Process ID should not be negative."); return(-1); } else if (processId == 0) { console.Error.WriteLine("--process-id is required"); return(-1); } var client = new DiagnosticsClient(processId); var providers = new List <EventPipeProvider>() { new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational) }; // collect a *short* trace with stack samples // the hidden '--duration' flag can increase the time of this trace in case 10ms // is too short in a given environment, e.g., resource constrained systems // N.B. - This trace INCLUDES rundown. For sufficiently large applications, it may take non-trivial time to collect // the symbol data in rundown. using (EventPipeSession session = client.StartEventPipeSession(providers)) using (FileStream fs = File.OpenWrite(tempNetTraceFilename)) { Task copyTask = session.EventStream.CopyToAsync(fs); await Task.Delay(duration); session.Stop(); // check if rundown is taking more than 5 seconds and add comment to report Task timeoutTask = Task.Delay(TimeSpan.FromSeconds(5)); Task completedTask = await Task.WhenAny(copyTask, timeoutTask); if (completedTask == timeoutTask) { console.Out.WriteLine($"# Sufficiently large applications can cause this command to take non-trivial amounts of time"); } await copyTask; } // using the generated trace file, symbolocate and compute stacks. tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(tempEtlxFilename)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var samplesForThread = new Dictionary <int, List <StackSourceSample> >(); stackSource.ForEach((sample) => { var stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread (")) { stackIndex = stackSource.GetCallerIndex(stackIndex); } // long form for: int.Parse(threadFrame["Thread (".Length..^1)]) // Thread id is in the frame name as "Thread (<ID>)" string template = "Thread ("; string threadFrame = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false); int threadId = int.Parse(threadFrame.Substring(template.Length, threadFrame.Length - (template.Length + 1))); if (samplesForThread.TryGetValue(threadId, out var samples)) { samples.Add(sample); } else { samplesForThread[threadId] = new List <StackSourceSample>() { sample }; } }); // For every thread recorded in our trace, print the first stack foreach (var(threadId, samples) in samplesForThread) { #if DEBUG console.Out.WriteLine($"Found {samples.Count} stacks for thread 0x{threadId:X}"); #endif PrintStack(console, threadId, samples[0], stackSource); } } } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); return(-1); } finally { if (File.Exists(tempNetTraceFilename)) { File.Delete(tempNetTraceFilename); } if (File.Exists(tempEtlxFilename)) { File.Delete(tempEtlxFilename); } } return(0); }
//Code is inspired by https://github.com/Microsoft/perfview/blob/master/src/PerfView/PerfViewData.cs#L5719-L5944 public IEnumerable <Metric> Parse() { using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath))) { var stackSource = new MutableTraceEventStackSource(traceLog); var eventSource = traceLog.Events.GetSource(); var bdnEventsParser = new EngineEventLogParser(eventSource); var start = false; var isFirstActualStartEnd = false; long totalOperation = 0; long countOfAllocatedObject = 0; bdnEventsParser.WorkloadActualStart += data => { if (!isFirstActualStartEnd) { start = true; } totalOperation = data.TotalOperations; }; bdnEventsParser.WorkloadActualStop += data => { start = false; isFirstActualStartEnd = true; }; var heapParser = new HeapTraceProviderTraceEventParser(eventSource); // We index by heap address and then within the heap we remember the allocation stack var heaps = new Dictionary <Address, Dictionary <Address, long> >(); Dictionary <Address, long> lastHeapAllocs = null; Address lastHeapHandle = 0; long nativeLeakSize = 0; long totalAllocation = 0; heapParser.HeapTraceAlloc += delegate(HeapAllocTraceData data) { if (!start) { return; } var call = data.CallStackIndex(); var frameIndex = stackSource.GetCallStack(call, data); if (!IsCallStackIn(frameIndex)) { return; } var allocs = lastHeapAllocs; if (data.HeapHandle != lastHeapHandle) { allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle); } allocs[data.AllocAddress] = data.AllocSize; checked { countOfAllocatedObject++; nativeLeakSize += data.AllocSize; totalAllocation += data.AllocSize; } bool IsCallStackIn(StackSourceCallStackIndex index) { while (index != StackSourceCallStackIndex.Invalid) { var frame = stackSource.GetFrameIndex(index); var name = stackSource.GetFrameName(frame, false); if (name.StartsWith(moduleName, StringComparison.Ordinal) && name.IndexOf(functionName, StringComparison.Ordinal) > 0) { return(true); } index = stackSource.GetCallerIndex(index); } return(false); } }; heapParser.HeapTraceFree += delegate(HeapFreeTraceData data) { if (!start) { return; } var allocs = lastHeapAllocs; if (data.HeapHandle != lastHeapHandle) { allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle); } if (allocs.TryGetValue(data.FreeAddress, out long alloc)) { nativeLeakSize -= alloc; allocs.Remove(data.FreeAddress); } }; heapParser.HeapTraceReAlloc += delegate(HeapReallocTraceData data) { if (!start) { return; } // Reallocs that actually move stuff will cause a Alloc and delete event // so there is nothing to do for those events. But when the address is // the same we need to resize. if (data.OldAllocAddress != data.NewAllocAddress) { return; } var allocs = lastHeapAllocs; if (data.HeapHandle != lastHeapHandle) { allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle); } if (allocs.TryGetValue(data.OldAllocAddress, out long alloc)) { // Free nativeLeakSize -= alloc; allocs.Remove(data.OldAllocAddress); // Alloc allocs[data.NewAllocAddress] = data.NewAllocSize; checked { nativeLeakSize += data.NewAllocSize; } } }; heapParser.HeapTraceDestroy += delegate(HeapTraceData data) { if (!start) { return; } // Heap is dieing, kill all objects in it. var allocs = lastHeapAllocs; if (data.HeapHandle != lastHeapHandle) { allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle); } foreach (var alloc in allocs.Values) { nativeLeakSize -= alloc; } }; eventSource.Process(); logger.WriteLine(); logger.WriteLineHeader(LogSeparator); logger.WriteLineInfo($"{benchmarkCase.DisplayInfo}"); logger.WriteLineHeader(LogSeparator); if (totalOperation == 0) { logger.WriteLine($"Something went wrong. The trace file {etlFilePath} does not contain BenchmarkDotNet engine events."); yield break; } var memoryAllocatedPerOperation = totalAllocation / totalOperation; var memoryLeakPerOperation = nativeLeakSize / totalOperation; logger.WriteLine($"Native memory allocated per single operation: {SizeValue.FromBytes(memoryAllocatedPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}"); logger.WriteLine($"Count of allocated object: {countOfAllocatedObject / totalOperation}"); if (nativeLeakSize != 0) { logger.WriteLine($"Native memory leak per single operation: {SizeValue.FromBytes(memoryLeakPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}"); } var heapInfoList = heaps.Select(h => new { Address = h.Key, h.Value.Count, types = h.Value.Values }); foreach (var item in heapInfoList.Where(p => p.Count > 0)) { logger.WriteLine($"Count of not deallocated object: {item.Count / totalOperation}"); } yield return(new Metric(new AllocatedNativeMemoryDescriptor(), memoryAllocatedPerOperation)); yield return(new Metric(new NativeMemoryLeakDescriptor(), memoryLeakPerOperation)); } }
static async Task <int> Main(string[] args) { if (args.Length == 0 || args.Length > 1 || (args.Length == 1 && _helpFlags.Contains(args[0]))) { PrintUsage(); return(-1); } var pid = int.Parse(args[0]); var tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace"; var tempEtlxFilename = ""; try { var client = new DiagnosticsClient(pid); var providers = new List <EventPipeProvider>() { new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational) }; using (EventPipeSession session = client.StartEventPipeSession(providers)) using (FileStream fs = File.OpenWrite(tempNetTraceFilename)) { Task copyTask = session.EventStream.CopyToAsync(fs); await Task.Delay(10); session.Stop(); await copyTask; } tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(tempEtlxFilename)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var samplesForThread = new Dictionary <string, List <StackSourceSample> >(); stackSource.ForEach((sample) => { var stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread (")) { stackIndex = stackSource.GetCallerIndex(stackIndex); } var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false); if (samplesForThread.TryGetValue(threadName, out var samples)) { samples.Add(sample); } else { samplesForThread[threadName] = new List <StackSourceSample>() { sample }; } }); foreach (var(threadName, samples) in samplesForThread) { #if DEBUG Console.WriteLine($"Found {samples.Count} stacks for thread {threadName}"); #endif PrintStack(threadName, samples[0], stackSource); } } return(0); } catch (System.Exception e) { Console.WriteLine(e); return(-1); } finally { if (File.Exists(tempNetTraceFilename)) { File.Delete(tempNetTraceFilename); } if (File.Exists(tempEtlxFilename)) { File.Delete(tempEtlxFilename); } } }
/// <summary> /// Reads trace and prints managed stacks /// </summary> /// <param name="console"></param> /// <param name="traceFile"></param> /// <returns>Returns 0 for success and 1 for failure</returns> /// <remarks>This code is adopted from josalem code https://github.com/josalem/DotStack </remarks> public static int Analyze(IConsole console, FileInfo traceFile) { if (string.IsNullOrEmpty(traceFile.FullName)) { Console.ForegroundColor = ConsoleColor.Red; console.Error.WriteLine("-f [process-id] Process ID is required."); Console.ResetColor(); return(1); } Console.WriteLine("[Trace analysis started...]\n"); // Both the namespaces have TraceLog, here we use Microsoft.Diagnostics.Tracing.Etlx.TraceLog; // The following line creates a etlx file and then does analysis using that. string tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(traceFile.FullName); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(tempEtlxFilename)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var samplesForThread = new Dictionary <string, List <StackSourceSample> >(); stackSource.ForEach((sample) => { var stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread (")) { stackIndex = stackSource.GetCallerIndex(stackIndex); } var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false); if (samplesForThread.TryGetValue(threadName, out var samples)) { samples.Add(sample); } else { samplesForThread[threadName] = new List <StackSourceSample>() { sample }; } }); foreach (var(threadName, samples) in samplesForThread) { PrintStack(threadName, samples[0], stackSource); } } Console.WriteLine("\n[Trace analysis completed...]"); return(0); }