/// <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);
}
