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); }
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 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); }
internal void CreateFileScanOperation(AMFilter_FileScanArgsTraceData data) { // If we can't get the process or thread index, bail. ProcessIndex processIndex = data.Process().ProcessIndex; if (processIndex == ProcessIndex.Invalid) { return; } ThreadIndex threadIndex = data.Thread().ThreadIndex; if (threadIndex == ThreadIndex.Invalid) { return; } // Get the process container. Dictionary <ThreadIndex, FileScanOperation> processContainer = GetOrCreateProcessContainer(processIndex); // Create a new file scan operation. // This happens when the scan is requested inside the user process. FileScanOperation scan = new FileScanOperation() { File = data.FileName, Reason = data.Reason, RequestorStack = _stackSource.GetCallStack(data.CallStackIndex(), data) }; processContainer[threadIndex] = scan; }
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); }
/// <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.TimeRelMSec = this.BlockTimeStartRelMsec; sample.Metric = (float)(data.TimeStampRelativeMSec - this.BlockTimeStartRelMsec); // Generate the stack trace. ScenarioThreadState scenarioThreadState = GetScenarioThreadState(stateMachine); StackSourceCallStackIndex callStackIndex = scenarioThreadState.GetCallStackIndex(stackSource, thread); // Add the thread. StackSourceFrameIndex threadFrameIndex = stackSource.GetFrameIndexForName(thread.VerboseThreadName); callStackIndex = stackSource.GetCallStack(threadFrameIndex, callStackIndex); // Add the full call stack. callStackIndex = stackSource.GetCallStack(data.CallStackIndex(), callStackIndex, null); StackSourceFrameIndex frameIndex = stackSource.GetFrameIndexForName("BLOCKED TIME"); callStackIndex = stackSource.GetCallStack(frameIndex, callStackIndex); // Add the call stack to the sample. sample.StackIndex = callStackIndex; // Add the sample. stackSource.AddSample(sample); // Mark the thread as executing. BlockTimeStartRelMsec = -1; } }
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> /// 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; MutableTraceEventStackSource stackSource = stateMachine.StackSource; // Attempt to charge the CPU to a request. ScenarioThreadState scenarioThreadState = GetScenarioThreadState(stateMachine); StackSourceCallStackIndex callStackIndex = scenarioThreadState.GetCallStackIndex(stackSource, thread); // Add the thread. StackSourceFrameIndex threadFrameIndex = stackSource.GetFrameIndexForName(thread.VerboseThreadName); callStackIndex = stackSource.GetCallStack(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(data.CallStackIndex(), callStackIndex, null); // Add the CPU frame. StackSourceFrameIndex cpuFrameIndex = stackSource.GetFrameIndexForName("CPU"); callStackIndex = stackSource.GetCallStack(cpuFrameIndex, callStackIndex); // Add the sample. sample.StackIndex = callStackIndex; sample.Metric = 1; sample.TimeRelMSec = data.TimeStampRelativeMSec; stackSource.AddSample(sample); }
/// <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 = BlockTimeStartRelativeMSec; sample.Metric = (float)(data.TimeStampRelativeMSec - 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; } }
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); }
/// <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); }
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; }
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); }
//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)); } }
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); }