// Method copied from https://github.com/dotnet/diagnostics/blob/2c23d3265dd8f642a8d6cf4bb8a135a5ff8b00c2/src/Tools/dotnet-trace/TraceFileFormatConverter.cs#L64 private static void ConvertToSpeedscope(string fileToConvert, string outputFilename, bool continueOnError = false) { var etlxFilePath = TraceLog.CreateFromEventPipeDataFile(fileToConvert, null, new TraceLogOptions() { ContinueOnError = continueOnError }); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(etlxFilePath)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true // EventPipe currently only has managed code stacks. }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader) { IncludeEventSourceEvents = false // SpeedScope handles only CPU samples, events are not supported }; computer.GenerateThreadTimeStacks(stackSource); SpeedScopeStackSourceWriter.WriteStackViewAsJson(stackSource, outputFilename); } if (File.Exists(etlxFilePath)) { File.Delete(etlxFilePath); } }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } TraceLog log = events.Log; var stackSource = new MutableTraceEventStackSource(log) { ShowUnknownAddresses = true }; var eventSource = events.GetSource(); var sample = new StackSourceSample(stackSource); var kernelTraceEventParser = new KernelTraceEventParser(eventSource); kernelTraceEventParser.PerfInfoSample += delegate(SampledProfileTraceData data) { sample.Metric = events.Log.SampleProfileInterval.Milliseconds; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; sample.StackIndex = stackSource.GetCallStack(data.CallStackIndex(), data); stackSource.AddSample(sample); }; eventSource.Process(); return(stackSource); }
internal FileScanOperationCollection(TraceLog traceLog, MutableTraceEventStackSource stackSource) { _traceLog = traceLog; _stackSource = stackSource; _sample = new StackSourceSample(_stackSource); _engineThreadToScanMap = new FileScanOperation[_traceLog.Threads.Count]; }
private static void ConvertToSpeedscope(string fileToConvert, string outputFilename) { var etlxFilePath = TraceLog.CreateFromEventPipeDataFile(fileToConvert); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(etlxFilePath)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true // EventPipe currently only has managed code stacks. }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); SpeedScopeStackSourceWriter.WriteStackViewAsJson(stackSource, outputFilename); } if (File.Exists(etlxFilePath)) { File.Delete(etlxFilePath); } }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } var stackSource = new MutableTraceEventStackSource(events.Log) { ShowUnknownAddresses = true }; var eventSource = events.GetSource(); var sample = new StackSourceSample(stackSource); var clrTraceEventParser = new ClrTraceEventParser(eventSource); clrTraceEventParser.ContentionStart += delegate(ContentionTraceData data) { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; string nodeName = data.ContentionFlags == ContentionFlags.Native ? "Native Contention" : "Managed Contention"; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Process(); return(stackSource); }
public static StackSource AnyStacks(this TraceLog eventLog, TraceProcess process = null, bool showUnknownAddresses = false, Predicate <TraceEvent> predicate = null) { var stackSource = new MutableTraceEventStackSource(eventLog); var sample = new StackSourceSample(stackSource); TraceEvents events = process == null?eventLog.Events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID != 0) : process.EventsInProcess.Filter(x => predicate == null || predicate(x)); var eventSource = events.GetSource(); eventSource.AllEvents += data => { var callStackIdx = data.CallStackIndex(); StackSourceCallStackIndex stackIndex = callStackIdx != CallStackIndex.Invalid ? stackSource.GetCallStack(callStackIdx, data) : StackSourceCallStackIndex.Invalid; var eventNodeName = "Event " + data.ProviderName + "/" + data.EventName; stackIndex = stackSource.Interner.CallStackIntern(stackSource.Interner.FrameIntern(eventNodeName), stackIndex); sample.StackIndex = stackIndex; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; sample.Metric = 1; stackSource.AddSample(sample); }; eventSource.Process(); stackSource.DoneAddingSamples(); return(stackSource); }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } var stackSource = new MutableTraceEventStackSource(events.Log) { ShowUnknownAddresses = true }; var eventSource = events.GetSource(); var sample = new StackSourceSample(stackSource); var clrTraceEventParser = new ClrTraceEventParser(eventSource); clrTraceEventParser.ExceptionStart += delegate(ExceptionTraceData data) { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; // Create a call stack that ends with the 'throw' var nodeName = "Throw(" + data.ExceptionType + ") " + data.ExceptionMessage; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Process(); return(stackSource); }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } var stackSource = new MutableTraceEventStackSource(events.Log); var eventSource = events.GetSource(); var sample = new StackSourceSample(stackSource); var clrTraceEventParser = new ClrTraceEventParser(eventSource); clrTraceEventParser.GCAllocationTick += delegate(GCAllocationTickTraceData data) { var size = data.AllocationAmount64; sample.Metric = size; sample.Count = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; sample.StackIndex = stackSource.Interner.CallStackIntern(stackSource.Interner.FrameIntern("Type " + data.TypeName), stackSource.GetCallStack(data.CallStackIndex(), data)); if (data.AllocationKind == GCAllocationKind.Large) { sample.StackIndex = stackSource.Interner.CallStackIntern(stackSource.Interner.FrameIntern("LargeObject"), sample.StackIndex); } stackSource.AddSample(sample); }; eventSource.Process(); return(stackSource); }
private static void ConvertToSpeedscope(string fileToConvert) { var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }; var etlxFilePath = TraceLog.CreateFromEventPipeDataFile(fileToConvert); var eventLog = new TraceLog(etlxFilePath); try { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true // EventPipe currently only has managed code stacks. }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var speedScopeFilePath = Path.ChangeExtension(fileToConvert, "speedscope.json"); SpeedScopeStackSourceWriter.WriteStackViewAsJson(stackSource, speedScopeFilePath); } finally { eventLog.Dispose(); if (File.Exists(etlxFilePath)) { File.Delete(etlxFilePath); } } }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } TraceLog log = events.Log; var stackSource = new MutableTraceEventStackSource(log) /* ShowUnknownAddresses = true */ }
/// <summary> /// Get the 'logcal' call stack from PROCESS ROOT (the root of all stacks) to (but not including) the frame for the /// thread. By default (if you can't attribute it to anything else) it will just be attributed to the process, however /// it is likley that you want to insert pseudo-frames for the request and other logical groupings here. /// /// The actual method frames within a thread, as well as any resource specific pseduo-frames (e.g. BLOCKING, ...) /// are added by the ComputingResourceMachine itself. ///</summary> public virtual StackSourceCallStackIndex GetCallStackIndex(MutableTraceEventStackSource stackSource, TraceThread thread, TraceEvent data) { var callStackIndex = stackSource.GetCallStackForProcess(thread.Process); // There is no request, so add this stack as an unattributed sample. string frameName = "Unattributed"; StackSourceFrameIndex requestsFrameIndex = stackSource.Interner.FrameIntern(frameName); callStackIndex = stackSource.Interner.CallStackIntern(requestsFrameIndex, callStackIndex); return(callStackIndex); }
public ComputingResourceStateMachine(MutableTraceEventStackSource outputStackSource, ScenarioConfiguration configuration, ComputingResourceViewType viewType) { m_OutputStackSource = outputStackSource; m_Sample = new StackSourceSample(outputStackSource); m_Configuration = configuration; m_ViewType = viewType; m_ThreadState = new ComputingResourceThreadState[configuration.TraceLog.Threads.Count]; for (int i = 0; i < m_ThreadState.Length; ++i) { m_ThreadState[i] = new ComputingResourceThreadState(i); } }
public static StackSource Exceptions(this TraceEvents events, TraceProcess process = null, Predicate <TraceEvent> predicate = null) { // optimization only if (process != null) { var start = Math.Max(events.StartTimeRelativeMSec, process.StartTimeRelativeMsec); var end = Math.Min(events.EndTimeRelativeMSec, process.EndTimeRelativeMsec); events = events.FilterByTime(start, end); events = events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID == process.ProcessID); } else { events = events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID != 0); // TODO: Is it really correc that x.ProcessID != 0 should be there? What if we want see these? } var eventSource = events.GetSource(); var stackSource = new MutableTraceEventStackSource(events.Log) { ShowUnknownAddresses = true }; var sample = new StackSourceSample(stackSource); eventSource.Clr.ExceptionStart += data => { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; // Create a call stack that ends with the 'throw' var nodeName = "Throw(" + data.ExceptionType + ") " + data.ExceptionMessage; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Kernel.MemoryAccessViolation += data => { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; // Create a call stack that ends with the 'throw' var nodeName = "AccessViolation(ADDR=" + data.VirtualAddress.ToString("x") + ")"; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Process(); stackSource.DoneAddingSamples(); return(stackSource); }
internal GCPinnedObjectAnalyzer( string etlFilePath, TraceLog traceLog, MutableTraceEventStackSource stackSource, StackSourceSample sample, TextWriter log) { _HeapSnapshotFilePath = GetHeapSnapshotPath(etlFilePath); _TraceLog = traceLog; _StackSource = stackSource; _Sample = sample; _Log = log; }
public GCHeapSimulators(TraceLog traceLog, TraceEventDispatcher source, MutableTraceEventStackSource stackSource, TextWriter log) { m_simulators = new GCHeapSimulator[traceLog.Processes.Count]; m_source = source; m_stackSource = stackSource; m_log = log; // Save a symbol resolver for this trace log. s_typeNameSymbolResolvers[traceLog.FilePath] = new TypeNameSymbolResolver(traceLog.FilePath, log); var etwClrProfileTraceEventParser = new ETWClrProfilerTraceEventParser(source); etwClrProfileTraceEventParser.ClassIDDefintion += CheckForNewProcess; source.Clr.GCSampledObjectAllocation += CheckForNewProcess; source.Clr.GCAllocationTick += CheckForNewProcessForTick; }
/// <summary> /// Get the call stack index for the current thread in its current state. /// </summary> /// <remarks> /// The return value will be used to append the actual call stack. This is how real call stacks get stitched together with grouping mechanisms. /// </remarks> public virtual StackSourceCallStackIndex GetCallStackIndex( MutableTraceEventStackSource stackSource, TraceThread thread) { if (null == stackSource) { throw new ArgumentNullException("stackSource"); } if (null == thread) { throw new ArgumentNullException("thread"); } // By default, return the call stack for the process. return(stackSource.GetCallStackForProcess(thread.Process)); }
/// <summary> /// Mark the thread as unblocked. /// </summary> public void LogBlockingStop( ComputingResourceStateMachine stateMachine, TraceThread thread, TraceEvent data) { if ((null == stateMachine) || (null == thread) || (null == data)) { return; } // Only add a sample if the thread was blocked. if (ThreadBlocked) { StackSourceSample sample = stateMachine.Sample; MutableTraceEventStackSource stackSource = stateMachine.StackSource; // Set the time and metric. sample.TimeRelativeMSec = this.BlockTimeStartRelativeMSec; sample.Metric = (float)(data.TimeStampRelativeMSec - this.BlockTimeStartRelativeMSec); /* Generate the stack trace. */ CallStackIndex traceLogCallStackIndex = data.CallStackIndex(); ScenarioThreadState scenarioThreadState = stateMachine.Configuration.ScenarioThreadState[ThreadIndex]; StackSourceCallStackIndex callStackIndex = scenarioThreadState.GetCallStackIndex(stateMachine.StackSource, thread, data); // Add the thread. StackSourceFrameIndex threadFrameIndex = stackSource.Interner.FrameIntern(thread.VerboseThreadName); callStackIndex = stackSource.Interner.CallStackIntern(threadFrameIndex, callStackIndex); // Add the full call stack. callStackIndex = stackSource.GetCallStack(traceLogCallStackIndex, callStackIndex, null); // Add Pseud-frames representing the kind of resource. StackSourceFrameIndex frameIndex = stackSource.Interner.FrameIntern("BLOCKED TIME"); callStackIndex = stackSource.Interner.CallStackIntern(frameIndex, callStackIndex); // Add the call stack to the sample. sample.StackIndex = callStackIndex; // Add the sample. stackSource.AddSample(sample); // Mark the thread as executing. BlockTimeStartRelativeMSec = -1; } }
private static void Convert(TraceFileFormat format, string fileToConvert, string outputFilename, bool continueOnError = false) { var etlxFilePath = TraceLog.CreateFromEventPipeDataFile(fileToConvert, null, new TraceLogOptions() { ContinueOnError = continueOnError }); using (var symbolReader = new SymbolReader(TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(etlxFilePath)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true // EventPipe currently only has managed code stacks. }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader) { IncludeEventSourceEvents = false // SpeedScope handles only CPU samples, events are not supported }; computer.GenerateThreadTimeStacks(stackSource); switch (format) { case TraceFileFormat.Speedscope: SpeedScopeStackSourceWriter.WriteStackViewAsJson(stackSource, outputFilename); break; case TraceFileFormat.Chromium: ChromiumStackSourceWriter.WriteStackViewAsJson(stackSource, outputFilename, compress: false); break; default: // we should never get here throw new ArgumentException($"Invalid TraceFileFormat \"{format}\""); } } if (File.Exists(etlxFilePath)) { File.Delete(etlxFilePath); } }
public static StackSource AnyStacks(this TraceEvents events, TraceProcess process = null, Predicate <TraceEvent> predicate = null) { // optimization only if (process != null) { var start = Math.Max(events.StartTimeRelativeMSec, process.StartTimeRelativeMsec); var end = Math.Min(events.EndTimeRelativeMSec, process.EndTimeRelativeMsec); events = events.FilterByTime(start, end); events = events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID == process.ProcessID); } else { events = events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID != 0); // TODO: Is it really correc that x.ProcessID != 0 should be there? What if we want see these? } var stackSource = new MutableTraceEventStackSource(events.Log) { ShowUnknownAddresses = true }; var sample = new StackSourceSample(stackSource); var eventSource = events.GetSource(); eventSource.AllEvents += data => { var callStackIdx = data.CallStackIndex(); StackSourceCallStackIndex stackIndex = callStackIdx != CallStackIndex.Invalid ? stackSource.GetCallStack(callStackIdx, data) : StackSourceCallStackIndex.Invalid; var eventNodeName = "Event " + data.ProviderName + "/" + data.EventName; stackIndex = stackSource.Interner.CallStackIntern(stackSource.Interner.FrameIntern(eventNodeName), stackIndex); sample.StackIndex = stackIndex; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; sample.Metric = 1; stackSource.AddSample(sample); }; eventSource.Process(); stackSource.DoneAddingSamples(); return(stackSource); }
/// <summary> /// Log a CPU sample on this thread. /// </summary> public void LogCPUSample( ComputingResourceStateMachine stateMachine, TraceThread thread, TraceEvent data) { if ((null == stateMachine) || (null == thread) || (null == data)) { return; } StackSourceSample sample = stateMachine.Sample; sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; MutableTraceEventStackSource stackSource = stateMachine.StackSource; // Attempt to charge the CPU to a request. CallStackIndex traceLogCallStackIndex = data.CallStackIndex(); ScenarioThreadState scenarioThreadState = stateMachine.Configuration.ScenarioThreadState[ThreadIndex]; StackSourceCallStackIndex callStackIndex = scenarioThreadState.GetCallStackIndex(stackSource, thread, data); // Add the thread. StackSourceFrameIndex threadFrameIndex = stackSource.Interner.FrameIntern(thread.VerboseThreadName); callStackIndex = stackSource.Interner.CallStackIntern(threadFrameIndex, callStackIndex); // Rest of the stack. // NOTE: Do not pass a call stack map into this method, as it will skew results. callStackIndex = stackSource.GetCallStack(traceLogCallStackIndex, callStackIndex, null); // Add the CPU frame. StackSourceFrameIndex cpuFrameIndex = stackSource.Interner.FrameIntern("CPU"); callStackIndex = stackSource.Interner.CallStackIntern(cpuFrameIndex, callStackIndex); // Add the sample. sample.StackIndex = callStackIndex; stackSource.AddSample(sample); }
public static StackSource Exceptions(this TraceLog eventLog, TraceProcess process = null, bool showUnknownAddresses = false, Predicate <TraceEvent> predicate = null) { var stackSource = new MutableTraceEventStackSource(eventLog); var sample = new StackSourceSample(stackSource); TraceEvents events = process == null?eventLog.Events.Filter(x => (predicate == null || predicate(x)) && x.ProcessID != 0) : process.EventsInProcess.Filter(x => predicate == null || predicate(x)); var eventSource = events.GetSource(); eventSource.Clr.ExceptionStart += data => { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; // Create a call stack that ends with the 'throw' var nodeName = "Throw(" + data.ExceptionType + ") " + data.ExceptionMessage; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Kernel.MemoryAccessViolation += data => { sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; // Create a call stack that ends with the 'throw' var nodeName = "AccessViolation(ADDR=" + data.VirtualAddress.ToString("x") + ")"; var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); }; eventSource.Process(); stackSource.DoneAddingSamples(); return(stackSource); }
/// <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); }
/// <summary> /// Generate the thread time stacks, outputting to 'stackSource'. /// </summary> /// <param name="outputStackSource"></param> /// <param name="traceEvents">Optional filtered trace events.</param> public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSource, TraceEvents traceEvents = null) { m_outputStackSource = outputStackSource; m_sample = new StackSourceSample(outputStackSource); m_nodeNameInternTable = new Dictionary <double, StackSourceFrameIndex>(10); m_ExternalFrameIndex = outputStackSource.Interner.FrameIntern("UNMANAGED_CODE_TIME"); m_cpuFrameIndex = outputStackSource.Interner.FrameIntern("CPU_TIME"); TraceLogEventSource eventSource = traceEvents == null?m_eventLog.Events.GetSource() : traceEvents.GetSource(); if (GroupByStartStopActivity) { UseTasks = true; } if (UseTasks) { m_activityComputer = new ActivityComputer(eventSource, m_symbolReader); m_activityComputer.AwaitUnblocks += delegate(TraceActivity activity, TraceEvent data) { var sample = m_sample; sample.Metric = (float)(activity.StartTimeRelativeMSec - activity.CreationTimeRelativeMSec); sample.TimeRelativeMSec = activity.CreationTimeRelativeMSec; // The stack at the Unblock, is the stack at the time the task was created (when blocking started). sample.StackIndex = m_activityComputer.GetCallStackForActivity(m_outputStackSource, activity, GetTopFramesForActivityComputerCase(data, data.Thread(), true)); StackSourceFrameIndex awaitFrame = m_outputStackSource.Interner.FrameIntern("AWAIT_TIME"); sample.StackIndex = m_outputStackSource.Interner.CallStackIntern(awaitFrame, sample.StackIndex); m_outputStackSource.AddSample(sample); if (m_threadToStartStopActivity != null) { UpdateStartStopActivityOnAwaitComplete(activity, data); } }; // We can provide a bit of extra value (and it is useful for debugging) if we immediately log a CPU // sample when we schedule or start a task. That we we get the very instant it starts. var tplProvider = new TplEtwProviderTraceEventParser(eventSource); tplProvider.AwaitTaskContinuationScheduledSend += OnSampledProfile; tplProvider.TaskScheduledSend += OnSampledProfile; tplProvider.TaskExecuteStart += OnSampledProfile; tplProvider.TaskWaitSend += OnSampledProfile; tplProvider.TaskWaitStop += OnTaskUnblock; // Log the activity stack even if you don't have a stack. } if (GroupByStartStopActivity) { m_startStopActivities = new StartStopActivityComputer(eventSource, m_activityComputer, IgnoreApplicationInsightsRequestsWithRelatedActivityId); // Maps thread Indexes to the start-stop activity that they are executing. m_threadToStartStopActivity = new StartStopActivity[m_eventLog.Threads.Count]; /********* Start Unknown Async State machine for StartStop activities ******/ // The delegates below along with the AddUnkownAsyncDurationIfNeeded have one purpose: // To inject UNKNOWN_ASYNC stacks when there is an active start-stop activity that is // 'missing' time. It has the effect of insuring that Start-Stop tasks always have // a metric that is not unrealistically small. m_activityComputer.Start += delegate(TraceActivity activity, TraceEvent data) { StartStopActivity newStartStopActivityForThread = m_startStopActivities.GetCurrentStartStopActivity(activity.Thread, data); UpdateThreadToWorkOnStartStopActivity(activity.Thread, newStartStopActivityForThread, data); }; m_activityComputer.AfterStop += delegate(TraceActivity activity, TraceEvent data, TraceThread thread) { StartStopActivity newStartStopActivityForThread = m_startStopActivities.GetCurrentStartStopActivity(thread, data); UpdateThreadToWorkOnStartStopActivity(thread, newStartStopActivityForThread, data); }; m_startStopActivities.Start += delegate(StartStopActivity startStopActivity, TraceEvent data) { // We only care about the top-most activities since unknown async time is defined as time // where a top most activity is running but no thread (or await time) is associated with it // fast out otherwise (we just insure that we mark the thread as doing this activity) if (startStopActivity.Creator != null) { UpdateThreadToWorkOnStartStopActivity(data.Thread(), startStopActivity, data); return; } // Then we have a refcount of exactly one Debug.Assert(m_unknownTimeStartMsec.Get((int)startStopActivity.Index) >= 0); // There was nothing running before. m_unknownTimeStartMsec.Set((int)startStopActivity.Index, -1); // Set it so just we are running. m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] = startStopActivity; }; m_startStopActivities.Stop += delegate(StartStopActivity startStopActivity, TraceEvent data) { // We only care about the top-most activities since unknown async time is defined as time // where a top most activity is running but no thread (or await time) is associated with it // fast out otherwise if (startStopActivity.Creator != null) { return; } double unknownStartTime = m_unknownTimeStartMsec.Get((int)startStopActivity.Index); if (0 < unknownStartTime) { AddUnkownAsyncDurationIfNeeded(startStopActivity, unknownStartTime, data); } // Actually emit all the async unknown events. List <StackSourceSample> samples = m_startStopActivityToAsyncUnknownSamples.Get((int)startStopActivity.Index); if (samples != null) { foreach (var sample in samples) { m_outputStackSource.AddSample(sample); // Adding Unknown ASync } m_startStopActivityToAsyncUnknownSamples.Set((int)startStopActivity.Index, null); } m_unknownTimeStartMsec.Set((int)startStopActivity.Index, 0); Debug.Assert(m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] == startStopActivity || m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] == null); m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] = null; }; } eventSource.Clr.GCAllocationTick += OnSampledProfile; eventSource.Clr.GCSampledObjectAllocation += OnSampledProfile; var eventPipeTraceEventPraser = new SampleProfilerTraceEventParser(eventSource); eventPipeTraceEventPraser.ThreadSample += OnSampledProfile; if (IncludeEventSourceEvents) { eventSource.Dynamic.All += delegate(TraceEvent data) { // TODO decide what the correct heuristic is. // Currently I only do this for things that might be an EventSoruce (uses the name->Guid hashing) // Most importantly, it excludes the high volume CLR providers. if (!TraceEventProviders.MaybeAnEventSource(data.ProviderGuid)) { return; } // We don't want most of the FrameworkEventSource events either. if (data.ProviderGuid == FrameworkEventSourceTraceEventParser.ProviderGuid) { if (!((TraceEventID)140 <= data.ID && data.ID <= (TraceEventID)143)) // These are the GetResponce and GetResestStream events { return; } } // We don't care about EventPipe sample profiler events. if (data.ProviderGuid == SampleProfilerTraceEventParser.ProviderGuid) { return; } // We don't care about the TPL provider. Too many events. if (data.ProviderGuid == TplEtwProviderTraceEventParser.ProviderGuid) { return; } // We don't care about ManifestData events. if (data.ID == (TraceEventID)0xFFFE) { return; } TraceThread thread = data.Thread(); if (thread == null) { return; } StackSourceCallStackIndex stackIndex = GetCallStack(data, thread); // Tack on additional info about the event. var fieldNames = data.PayloadNames; for (int i = 0; i < fieldNames.Length; i++) { var fieldName = fieldNames[i]; var value = data.PayloadString(i); var fieldNodeName = "EventData: " + fieldName + "=" + value; var fieldNodeIndex = m_outputStackSource.Interner.FrameIntern(fieldNodeName); stackIndex = m_outputStackSource.Interner.CallStackIntern(fieldNodeIndex, stackIndex); } stackIndex = m_outputStackSource.Interner.CallStackIntern(m_outputStackSource.Interner.FrameIntern("EventName: " + data.ProviderName + "/" + data.EventName), stackIndex); m_threadState[(int)thread.ThreadIndex].LogThreadStack(data.TimeStampRelativeMSec, stackIndex, thread, this, false); }; } eventSource.Process(); m_outputStackSource.DoneAddingSamples(); m_threadState = null; }
public RealtimeAntimalwareComputer(TraceLogEventSource eventSource, MutableTraceEventStackSource stackSource) { _eventSource = eventSource; _stackSource = stackSource; }
internal static IDictionary<int, GCProcess> Collect( TraceEventSource source, float sampleIntervalMSec, IDictionary<int, GCProcess> perProc = null, MutableTraceEventStackSource stackSource = null, Predicate<TraceEvent> filterFunc = null) { if (perProc == null) { perProc = new Dictionary<int, GCProcess>(); } source.Kernel.AddCallbackForEvents(delegate (ProcessCtrTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); stats.PeakVirtualMB = ((double)data.PeakVirtualSize) / 1000000.0; stats.PeakWorkingSetMB = ((double)data.PeakWorkingSetSize) / 1000000.0; }); Action<RuntimeInformationTraceData> doAtRuntimeStart = delegate (RuntimeInformationTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); stats.RuntimeVersion = "V " + data.VMMajorVersion.ToString() + "." + data.VMMinorVersion + "." + data.VMBuildNumber + "." + data.VMQfeNumber; stats.StartupFlags = data.StartupFlags; stats.Bitness = (data.RuntimeDllPath.ToLower().Contains("framework64") ? 64 : 32); if (stats.CommandLine == null) stats.CommandLine = data.CommandLine; }; // log at both startup and rundown //var clrRundown = new ClrRundownTraceEventParser(source); //clrRundown.RuntimeStart += doAtRuntimeStart; source.Clr.AddCallbackForEvent("Runtime/Start", doAtRuntimeStart); Action<ProcessTraceData> processStartCallback = data => { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); if (!string.IsNullOrEmpty(data.KernelImageFileName)) { // When we just have an EventSource (eg, the source was created by // ETWTraceEventSource), we don't necessarily have the process names // decoded - it all depends on whether we have seen a ProcessStartGroup // event or not. When the trace was taken after the process started we // know we didn't see such an event. string name = GetImageName(data.KernelImageFileName); // Strictly speaking, this is not really fixing it 'cause // it doesn't handle when a process with the same name starts // with the same pid. The chance of that happening is really small. if (stats.isDead == true) { stats = new GCProcess(); stats.Init(data); perProc[data.ProcessID] = stats; } } var commandLine = data.CommandLine; if (!string.IsNullOrEmpty(commandLine)) stats.CommandLine = commandLine; }; source.Kernel.AddCallbackForEvent("Process/Start", processStartCallback); source.Kernel.AddCallbackForEvent("Process/DCStart", processStartCallback); Action<ProcessTraceData> processEndCallback = delegate (ProcessTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); if (string.IsNullOrEmpty(stats.ProcessName)) { stats.ProcessName = GetImageName(data.KernelImageFileName); } if (data.OpcodeName == "Stop") { stats.isDead = true; } }; source.Kernel.AddCallbackForEvent("Process/Stop", processEndCallback); source.Kernel.AddCallbackForEvent("Process/DCStop", processEndCallback); #if (!CAP) CircularBuffer<ThreadWorkSpan> RecentThreadSwitches = new CircularBuffer<ThreadWorkSpan>(10000); source.Kernel.AddCallbackForEvent("Thread/CSwitch", delegate (CSwitchTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } RecentThreadSwitches.Add(new ThreadWorkSpan(data)); GCProcess stats; if (perProc.TryGetValue(data.ProcessID, out stats)) { stats.ThreadId2Priority[data.NewThreadID] = data.NewThreadPriority; if (stats.IsServerGCThread(data.ThreadID) > -1) { stats.ServerGcHeap2ThreadId[data.ProcessorNumber] = data.ThreadID; } } foreach (var gcProcess in perProc.Values) { GCEvent _event = gcProcess.GetCurrentGC(); // If we are in the middle of a GC. if (_event != null) { if ((_event.Type != GCType.BackgroundGC) && (gcProcess.isServerGCUsed == 1)) { _event.AddServerGcThreadSwitch(new ThreadWorkSpan(data)); } } } }); CircularBuffer<ThreadWorkSpan> RecentCpuSamples = new CircularBuffer<ThreadWorkSpan>(1000); StackSourceSample sample = new StackSourceSample(stackSource); source.Kernel.AddCallbackForEvent("PerfInfo/Sample", delegate (SampledProfileTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } RecentCpuSamples.Add(new ThreadWorkSpan(data)); GCProcess processWithGc = null; foreach (var gcProcess in perProc.Values) { GCEvent e = gcProcess.GetCurrentGC(); // If we are in the middle of a GC. if (e != null) { if ((e.Type != GCType.BackgroundGC) && (gcProcess.isServerGCUsed == 1)) { e.AddServerGcSample(new ThreadWorkSpan(data)); processWithGc = gcProcess; } } } if (stackSource != null && processWithGc != null) { GCEvent e = processWithGc.GetCurrentGC(); sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; var nodeName = string.Format("Server GCs #{0} in {1} (PID:{2})", e.GCNumber, processWithGc.ProcessName, processWithGc.ProcessID); var nodeIndex = stackSource.Interner.FrameIntern(nodeName); sample.StackIndex = stackSource.Interner.CallStackIntern(nodeIndex, stackSource.GetCallStack(data.CallStackIndex(), data)); stackSource.AddSample(sample); } GCProcess stats; if (perProc.TryGetValue(data.ProcessID, out stats)) { if (stats.IsServerGCThread(data.ThreadID) > -1) { stats.ServerGcHeap2ThreadId[data.ProcessorNumber] = data.ThreadID; } var cpuIncrement = sampleIntervalMSec; stats.ProcessCpuMSec += cpuIncrement; GCEvent _event = stats.GetCurrentGC(); // If we are in the middle of a GC. if (_event != null) { bool isThreadDoingGC = false; if ((_event.Type != GCType.BackgroundGC) && (stats.isServerGCUsed == 1)) { int heapIndex = stats.IsServerGCThread(data.ThreadID); if (heapIndex != -1) { _event.AddServerGCThreadTime(heapIndex, cpuIncrement); isThreadDoingGC = true; } } else if (data.ThreadID == stats.suspendThreadIDGC) { _event.GCCpuMSec += cpuIncrement; isThreadDoingGC = true; } else if (stats.IsBGCThread(data.ThreadID)) { Debug.Assert(stats.currentBGC != null); if (stats.currentBGC != null) stats.currentBGC.GCCpuMSec += cpuIncrement; isThreadDoingGC = true; } if (isThreadDoingGC) { stats.GCCpuMSec += cpuIncrement; } } } }); #endif source.Clr.AddCallbackForEvent("GC/SuspendEEStart", delegate (GCSuspendEETraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } var stats = perProc.GetOrCreate(data.ProcessID); switch (data.Reason) { case GCSuspendEEReason.SuspendForGC: stats.suspendThreadIDGC = data.ThreadID; break; case GCSuspendEEReason.SuspendForGCPrep: stats.suspendThreadIDBGC = data.ThreadID; break; default: stats.suspendThreadIDOther = data.ThreadID; break; } stats.suspendTimeRelativeMSec = data.TimeStampRelativeMSec; }); // In 2.0 we didn't have this event. source.Clr.AddCallbackForEvent("GC/SuspendEEStop", delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if ((stats.suspendThreadIDBGC > 0) && (stats.currentBGC != null)) { stats.currentBGC._SuspendDurationMSec += data.TimeStampRelativeMSec - stats.suspendTimeRelativeMSec; } stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec; }); source.Clr.AddCallbackForEvent("GC/RestartEEStop", delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.Type == GCType.BackgroundGC) { stats.AddConcurrentPauseTime(_event, data.TimeStampRelativeMSec); } else { Debug.Assert(_event.PauseStartRelativeMSec != 0); // In 2.0 Concurrent GC, since we don't know the GC's type we can't tell if it's concurrent // or not. But we know we don't have nested GCs there so simply check if we have received the // GCStop event; if we have it means it's a blocking GC; otherwise it's a concurrent GC so // simply add the pause time to the GC without making the GC complete. if (_event.GCDurationMSec == 0) { Debug.Assert(_event.is20Event); _event.isConcurrentGC = true; stats.AddConcurrentPauseTime(_event, data.TimeStampRelativeMSec); } else { _event.PauseDurationMSec = data.TimeStampRelativeMSec - _event.PauseStartRelativeMSec; if (_event.HeapStats != null) { _event.isComplete = true; stats.lastCompletedGC = _event; } } } } // We don't change between a GC end and the pause resume. //Debug.Assert(stats.allocTickAtLastGC == stats.allocTickCurrentMB); // Mark that we are not in suspension anymore. stats.suspendTimeRelativeMSec = -1; stats.suspendThreadIDOther = -1; stats.suspendThreadIDBGC = -1; stats.suspendThreadIDGC = -1; }); source.Clr.AddCallbackForEvent("GC/AllocationTick", delegate (GCAllocationTickTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if (stats.HasAllocTickEvents == false) { stats.HasAllocTickEvents = true; } double valueMB = data.GetAllocAmount(ref stats.SeenBadAllocTick) / 1000000.0; if (data.AllocationKind == GCAllocationKind.Small) { // Would this do the right thing or is it always 0 for SOH since AllocationAmount // is an int??? stats.allocTickCurrentMB[0] += valueMB; } else { stats.allocTickCurrentMB[1] += valueMB; } }); source.Clr.AddCallbackForEvent("GC/Start", delegate (GCStartTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); // We need to filter the scenario where we get 2 GCStart events for each GC. if ((stats.suspendThreadIDGC > 0) && !((stats.events.Count > 0) && stats.events[stats.events.Count - 1].GCNumber == data.Count)) { GCEvent _event = new GCEvent(stats); Debug.Assert(0 <= data.Depth && data.Depth <= 2); // _event.GCGeneration = data.Depth; Old style events only have this in the GCStop event. _event.Reason = data.Reason; _event.GCNumber = data.Count; _event.Type = data.Type; _event.Index = stats.events.Count; _event.is20Event = data.IsClassicProvider; bool isEphemeralGCAtBGCStart = false; // Detecting the ephemeral GC that happens at the beginning of a BGC. if (stats.events.Count > 0) { GCEvent lastGCEvent = stats.events[stats.events.Count - 1]; if ((lastGCEvent.Type == GCType.BackgroundGC) && (!lastGCEvent.isComplete) && (data.Type == GCType.NonConcurrentGC)) { isEphemeralGCAtBGCStart = true; } } Debug.Assert(stats.suspendTimeRelativeMSec != -1); if (isEphemeralGCAtBGCStart) { _event.PauseStartRelativeMSec = data.TimeStampRelativeMSec; } else { _event.PauseStartRelativeMSec = stats.suspendTimeRelativeMSec; if (stats.suspendEndTimeRelativeMSec == -1) { stats.suspendEndTimeRelativeMSec = data.TimeStampRelativeMSec; } _event._SuspendDurationMSec = stats.suspendEndTimeRelativeMSec - stats.suspendTimeRelativeMSec; } _event.GCStartRelativeMSec = data.TimeStampRelativeMSec; stats.events.Add(_event); if (_event.Type == GCType.BackgroundGC) { stats.currentBGC = _event; _event.ProcessCpuAtLastGC = stats.ProcessCpuAtLastGC; } #if (!CAP) if ((_event.Type != GCType.BackgroundGC) && (stats.isServerGCUsed == 1)) { _event.SetUpServerGcHistory(); foreach (var s in RecentCpuSamples) _event.AddServerGcSample(s); foreach (var s in RecentThreadSwitches) _event.AddServerGcThreadSwitch(s); } #endif } }); source.Clr.AddCallbackForEvent("GC/PinObjectAtGCTime", delegate (PinObjectAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (!_event.PinnedObjects.ContainsKey(data.ObjectID)) { _event.PinnedObjects.Add(data.ObjectID, data.ObjectSize); } else { _event.duplicatedPinningReports++; } } }); // Some builds have this as a public event, and some have it as a private event. // All will move to the private event, so we'll remove this code afterwards. source.Clr.AddCallbackForEvent("GC/PinPlugAtGCTime", delegate (PinPlugAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { // ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in // TraceEvent. _event.PinnedPlugs.Add(new GCEvent.PinnedPlug(data.PlugStart, data.PlugEnd)); } }); source.Clr.AddCallbackForEvent("GC/Mark", delegate (GCMarkWithTypeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.PerHeapMarkTimes == null) { _event.PerHeapMarkTimes = new Dictionary<int, GCEvent.MarkInfo>(); } if (!_event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes.Add(data.HeapNum, new GCEvent.MarkInfo()); } _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)data.Type] = data.TimeStampRelativeMSec; _event.PerHeapMarkTimes[data.HeapNum].MarkPromoted[(int)data.Type] = data.Promoted; } }); source.Clr.AddCallbackForEvent("GC/GlobalHeapHistory", delegate (GCGlobalHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.ProcessGlobalHistory(data); }); source.Clr.AddCallbackForEvent("GC/PerHeapHistory", delegate (GCPerHeapHistoryTraceData3 data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); stats.ProcessPerHeapHistory(data); }); #if HAS_PRIVATE_GC_EVENTS // See if the source knows about the CLR Private provider, if it does, then var gcPrivate = new ClrPrivateTraceEventParser(source); gcPrivate.GCPinPlugAtGCTime += delegate (PinPlugAtGCTimeTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { // ObjectID is supposed to be an IntPtr. But "Address" is defined as UInt64 in // TraceEvent. _event.PinnedPlugs.Add(new GCEvent.PinnedPlug(data.PlugStart, data.PlugEnd)); } }; // Sometimes at the end of a trace I see only some mark events are included in the trace and they // are not in order, so need to anticipate that scenario. gcPrivate.GCMarkStackRoots += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.AddServerGCThreadFromMark(data.ThreadID, data.HeapNum); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if (_event.PerHeapMarkTimes == null) { _event.PerHeapMarkTimes = new Dictionary<int, GCEvent.MarkInfo>(); } if (!_event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes.Add(data.HeapNum, new GCEvent.MarkInfo(false)); } _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkStack] = data.TimeStampRelativeMSec; } }; gcPrivate.GCMarkFinalizeQueueRoots += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkFQ] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCMarkHandles += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkHandles] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCMarkCards += delegate (GCMarkTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetCurrentGC(); if (_event != null) { if ((_event.PerHeapMarkTimes != null) && _event.PerHeapMarkTimes.ContainsKey(data.HeapNum)) { _event.PerHeapMarkTimes[data.HeapNum].MarkTimes[(int)MarkRootType.MarkOlder] = data.TimeStampRelativeMSec; } } }; gcPrivate.GCGlobalHeapHistory += delegate (GCGlobalHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.ProcessGlobalHistory(data); }; gcPrivate.GCPerHeapHistory += delegate (GCPerHeapHistoryTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; stats.ProcessPerHeapHistory(data); }; gcPrivate.GCBGCStart += delegate (GCNoUserDataTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; if (stats.currentBGC != null) { if (stats.backgroundGCThreads == null) { stats.backgroundGCThreads = new Dictionary<int, object>(16); } stats.backgroundGCThreads[data.ThreadID] = null; } }; #endif source.Clr.AddCallbackForEvent("GC/Stop", delegate (GCEndTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); if (_event != null) { _event.GCDurationMSec = data.TimeStampRelativeMSec - _event.GCStartRelativeMSec; _event.GCGeneration = data.Depth; _event.GCEnd(); } }); source.Clr.AddCallbackForEvent("GC/HeapStats", delegate (GCHeapStatsTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); GCEvent _event = stats.GetCurrentGC(); var sizeAfterMB = (data.GenerationSize1 + data.GenerationSize2 + data.GenerationSize3) / 1000000.0; if (_event != null) { _event.HeapStats = (GCHeapStatsTraceData)data.Clone(); if (_event.Type == GCType.BackgroundGC) { _event.ProcessCpuMSec = stats.ProcessCpuMSec - _event.ProcessCpuAtLastGC; _event.DurationSinceLastRestartMSec = data.TimeStampRelativeMSec - stats.lastRestartEndTimeRelativeMSec; } else { _event.ProcessCpuMSec = stats.ProcessCpuMSec - stats.ProcessCpuAtLastGC; _event.DurationSinceLastRestartMSec = _event.PauseStartRelativeMSec - stats.lastRestartEndTimeRelativeMSec; } if (stats.HasAllocTickEvents) { _event.HasAllocTickEvents = true; _event.AllocedSinceLastGCBasedOnAllocTickMB[0] = stats.allocTickCurrentMB[0] - stats.allocTickAtLastGC[0]; _event.AllocedSinceLastGCBasedOnAllocTickMB[1] = stats.allocTickCurrentMB[1] - stats.allocTickAtLastGC[1]; } // This is where a background GC ends. if ((_event.Type == GCType.BackgroundGC) && (stats.currentBGC != null)) { stats.currentBGC.isComplete = true; stats.lastCompletedGC = stats.currentBGC; stats.currentBGC = null; } if (_event.isConcurrentGC) { Debug.Assert(_event.is20Event); _event.isComplete = true; stats.lastCompletedGC = _event; } } stats.ProcessCpuAtLastGC = stats.ProcessCpuMSec; stats.allocTickAtLastGC[0] = stats.allocTickCurrentMB[0]; stats.allocTickAtLastGC[1] = stats.allocTickCurrentMB[1]; stats.lastRestartEndTimeRelativeMSec = data.TimeStampRelativeMSec; }); source.Clr.AddCallbackForEvent("GC/TerminateConcurrentThread", delegate (GCTerminateConcurrentThreadTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc.GetOrCreate(data.ProcessID); if (stats.backgroundGCThreads != null) { stats.backgroundGCThreads = null; } }); #if HAS_PRIVATE_GC_EVENTS gcPrivate.GCBGCAllocWaitStart += delegate (BGCAllocWaitTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; Debug.Assert(stats.currentBGC != null); if (stats.currentBGC != null) { stats.currentBGC.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, true); } }; gcPrivate.GCBGCAllocWaitStop += delegate (BGCAllocWaitTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess stats = perProc[data]; GCEvent _event = stats.GetLastBGC(); if (_event != null) { _event.AddLOHWaitThreadInfo(data.ThreadID, data.TimeStampRelativeMSec, data.Reason, false); } }; gcPrivate.GCJoin += delegate (GCJoinTraceData data) { if (filterFunc != null && !filterFunc.Invoke(data)) { return; } GCProcess gcProcess = perProc[data]; GCEvent _event = gcProcess.GetCurrentGC(); if (_event != null) { _event.AddGcJoin(data); } }; source.Process(); #endif return perProc; }
/// <summary> /// Create a GC simulation using the events from 'source' for the process with process ID 'processID'. /// The stacks associated with allocation are added to 'stackSource' (and a pseudo-frame with the type /// is added to the stacks for each allocation. If useOnlyAllocationTicks, it will not use /// either the etwClrProfiler or GCSampledObjectAllocation as allocation events (so you can reliably /// get a coarse sampled simulation independent of what other events are in the trace). /// </summary> public GCHeapSimulator(TraceEventDispatcher source, TraceProcess process, MutableTraceEventStackSource stackSource, TextWriter log, bool useOnlyAllocationTicks = false) { m_processID = process.ProcessID; m_process = process; m_pointerSize = 4; // We guess this, It is OK for this to be wrong. m_typeNameSymbolResolver = GCHeapSimulators.TypeNameSymbolResolvers[process.Log.FilePath]; if (m_typeNameSymbolResolver == null) { m_typeNameSymbolResolver = GCHeapSimulators.TypeNameSymbolResolvers[process.Log.FilePath] = new TypeNameSymbolResolver(process.Log.FilePath, log); } m_ObjsInGen = new Dictionary <Address, GCHeapSimulatorObject> [4]; // generation 0-2 + 1 for gen 2 for (int i = 0; i < m_ObjsInGen.Length; i++) { m_ObjsInGen[i] = new Dictionary <Address, GCHeapSimulatorObject>(10000); // Stays in small object heap } m_classNamesAsFrames = new Dictionary <ulong, TypeInfo>(500); m_stackSource = stackSource; AllocateObject = () => new GCHeapSimulatorObject(); // Register all the callbacks. if (!useOnlyAllocationTicks) { var etwClrProfilerTraceEventParser = new ETWClrProfilerTraceEventParser(source); etwClrProfilerTraceEventParser.GCStart += delegate(Microsoft.Diagnostics.Tracing.Parsers.ETWClrProfiler.GCStartArgs data) { m_useEtlClrProfilerEvents = true; OnGCStart(data, data.GCID, data.Generation); }; etwClrProfilerTraceEventParser.ObjectAllocated += delegate(ObjectAllocatedArgs data) { m_useEtlClrProfilerEvents = true; OnObjectAllocated(data, data.ObjectID, data.ClassID, data.Size, data.RepresentativeSize); }; etwClrProfilerTraceEventParser.ObjectsMoved += OnObjectMoved; etwClrProfilerTraceEventParser.ObjectsSurvived += OnObjectSurvived; etwClrProfilerTraceEventParser.GCStop += delegate(GCStopArgs data) { OnGCStop(data, data.GCID); }; etwClrProfilerTraceEventParser.ClassIDDefintion += OnClassIDDefintion; // TODO do we need module info? // etwClrProfileTraceEventParser.ModuleIDDefintion += OnModuleIDDefintion; } source.Clr.GCStart += delegate(Microsoft.Diagnostics.Tracing.Parsers.Clr.GCStartTraceData data) { if (m_useEtlClrProfilerEvents) { return; } OnGCStart(data, data.Count, data.Depth); }; source.Clr.GCStop += delegate(GCEndTraceData data) { if (m_useEtlClrProfilerEvents) { return; } OnGCStop(data, data.Count); }; source.Clr.GCBulkMovedObjectRanges += OnEtwObjectMoved; source.Clr.GCBulkSurvivingObjectRanges += OnEtwObjectSurvived; source.Clr.TypeBulkType += OnEtwClassIDDefintion; if (!useOnlyAllocationTicks) { source.Clr.GCSampledObjectAllocation += delegate(GCSampledObjectAllocationTraceData data) { // Compute size per object, Projecting against divide by zero. long representativeSize = data.TotalSizeForTypeSample; var objectCount = data.ObjectCountForTypeSample; if (objectCount > 1) { representativeSize = representativeSize / objectCount; } OnObjectAllocated(data, data.Address, data.TypeID, data.TotalSizeForTypeSample, representativeSize); }; } else { source.Clr.GCAllocationTick += OnEtwGCAllocationTick; } }
/// <summary> /// If you place a file called PerfViewExtensions\PerfViewStartup next to the PerfView.exe it will /// run execute commands in that file. If you put /// /// DeclareFileView .etl "Demo View In Etl File" DemoDeclareFileView /// /// It will create a child node for all .etl files called 'Demo View In Etl File' If you click /// on this node it will execute this user command. It is passed the name of the file that was /// opened and the name of the view that was opened (in this case 'Demo View In Etl File'). /// </summary> public void DemoDeclareFileView(string fileName, string viewName) { // This demo creates a view that shows you all the START events in a stack view. LogFile.WriteLine("************ In DemoDeclareFileView file = {0} view = {1}", fileName, viewName); // This is an example of opening an ETL file. ETLDataFile etlFile = OpenETLFile(fileName); // An ETLData file is a high level construct that knows about high level 'views' of the data (CPU stacks, thread time Stacks ...) // However if you want to create a new view, you probably want a TraceLog which is the underlying ETW data. TraceLog traceLog = etlFile.TraceLog; // A tracelog represent the whole ETL file (which has process, images, threads etc), we want events, and we want callbacks // for each event which is what GetSource() does. THus we get a source (which we can add callbacks to) var eventSource = traceLog.Events.GetSource(); // At this point create the 'output' of our routine. Our goal is to produce stacks that we will view in the // stack viewer. Thus we create an 'empty' one fo these. var stackSource = new MutableTraceEventStackSource(traceLog); // A stack source is list of samples. We create a sample structure, mutate it and then call AddSample() repeatedly to add samples. var sample = new StackSourceSample(stackSource); // Setup the callbacks, In this case we are going to watch for stacks where GCs happen eventSource.Clr.GCStart += delegate(GCStartTraceData data) { // An TraceLog should have a callstack associated with this event; CallStackIndex callStackIdx = data.CallStackIndex(); if (callStackIdx != CallStackIndex.Invalid) { // Convert the TraceLog call stack to a MutableTraceEventStackSource call stack StackSourceCallStackIndex stackCallStackIndex = stackSource.GetCallStack(callStackIdx, data); // Add a pseudo frame on the bottom of the stack StackSourceFrameIndex frameIdxForName = stackSource.Interner.FrameIntern("GC Gen " + data.Depth + "Reason " + data.Reason); stackCallStackIndex = stackSource.Interner.CallStackIntern(frameIdxForName, stackCallStackIndex); // create a sample with that stack and add it to the stack source (list of samples) sample.Metric = 1; sample.TimeRelativeMSec = data.TimeStampRelativeMSec; sample.StackIndex = stackCallStackIndex; stackSource.AddSample(sample); } }; // You can set up other callback for other events. // This causes the TraceLog source to actually spin through all the events calling our callbacks as requested. eventSource.Process(); // We are done adding sample to our stack Source, so we tell the MutableTraceEventStackSource that. // after that is becomes viewable (and read-only). stackSource.DoneAddingSamples(); // Take the stack source (raw data) and make it into a 'Stacks' allows you to add filtering to and send to 'OpendStackViewer' Stacks stacksForViewer = new Stacks(stackSource, viewName, etlFile); // Set any filtering options here. // Now we can display the viewer. OpenStackViewer(stacksForViewer); }
public PinningStackAnalysis(TraceEventDispatcher source, TraceProcess process, MutableTraceEventStackSource stackSource, TextWriter log) : base(source, process, stackSource, log) { var clrPrivateParser = new ClrPrivateTraceEventParser(source); clrPrivateParser.GCSetGCHandle += OnSetGCHandle; source.Clr.GCSetGCHandle += OnSetGCHandle; AllocateObject = () => new PinningStackAnalysisObject(); }
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); } } }
public void CanConvertProvidedTraceFiles(string zippedTraceFileName) { var debugListenersCopy = new TraceListener[Debug.Listeners.Count]; Debug.Listeners.CopyTo(debugListenersCopy, index: 0); Debug.Listeners.Clear(); string fileToUnzip = Path.Combine("inputs", "speedscope", zippedTraceFileName); string unzippedFile = Path.ChangeExtension(fileToUnzip, string.Empty); if (File.Exists(unzippedFile)) { File.Delete(unzippedFile); } ZipFile.ExtractToDirectory(fileToUnzip, Path.GetDirectoryName(fileToUnzip)); var etlxFilePath = TraceLog.CreateFromEventPipeDataFile(unzippedFile, null, new TraceLogOptions() { ContinueOnError = true }); try { using (var symbolReader = new SymbolReader(TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(etlxFilePath)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true // EventPipe currently only has managed code stacks. }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader) { IncludeEventSourceEvents = false // SpeedScope handles only CPU samples, events are not supported }; computer.GenerateThreadTimeStacks(stackSource); var samplesPerThread = GetSortedSamplesPerThread(stackSource); var exportedFrameNameToExportedFrameId = new Dictionary <string, int>(); var exportedFrameIdToFrameTuple = new Dictionary <int, FrameInfo>(); var profileEventsPerThread = new Dictionary <string, IReadOnlyList <ProfileEvent> >(); foreach (var pair in samplesPerThread) { var sortedProfileEvents = GetProfileEvents(stackSource, pair.Value, exportedFrameNameToExportedFrameId, exportedFrameIdToFrameTuple); Assert.True(Validate(sortedProfileEvents), "The output should be always valid"); profileEventsPerThread.Add(pair.Key.Name, sortedProfileEvents); } ; } } finally { if (File.Exists(etlxFilePath)) { File.Delete(etlxFilePath); } if (File.Exists(unzippedFile)) { File.Delete(unzippedFile); } if (debugListenersCopy.Length > 0) { Debug.Listeners.AddRange(debugListenersCopy); } } }
private static async Task <int> TopNReport(CancellationToken ct, IConsole console, string traceFile, int number, bool inclusive, bool verbose) { try { string tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(traceFile); int count = 0; int index = 0; List <CallTreeNodeBase> nodesToReport = new List <CallTreeNodeBase>(); 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); FilterParams filterParams = new FilterParams() { FoldRegExs = "CPU_TIME;UNMANAGED_CODE_TIME;{Thread (}", }; FilterStackSource filterStack = new FilterStackSource(filterParams, stackSource, ScalingPolicyKind.ScaleToData); CallTree callTree = new(ScalingPolicyKind.ScaleToData); callTree.StackSource = filterStack; List <CallTreeNodeBase> callTreeNodes = null; if (!inclusive) { callTreeNodes = callTree.ByIDSortedExclusiveMetric(); } else { callTreeNodes = callTree.ByIDSortedInclusiveMetric(); } int totalElements = callTreeNodes.Count; while (count < number && index < totalElements) { CallTreeNodeBase node = callTreeNodes[index]; index++; if (!unwantedMethodNames.Any(node.Name.Contains)) { nodesToReport.Add(node); count++; } } PrintReportHelper.TopNWriteToStdOut(nodesToReport, inclusive, verbose); } return(await Task.FromResult(0)); } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); } return(await Task.FromResult(0)); }