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 List <object> getDataForFile(string pathToItem) { List <object> childrenContainer = new List <object>(); // IF REAL FILE (e.g. .etl.zip, .etl) if (new FileInfo(pathToItem).Exists) { // TODO: Separate this into another function, if not another endpoint // Assume only .etl.zip for now string etlFileName = pathToItem; var etlFile = PerfViewExtensibility.CommandEnvironment.OpenETLFile(etlFileName); TraceEvents events = etlFile.TraceLog.Events; // Create CPU Stacks as child Stacks CPUStacks = etlFile.CPUStacks(); Dictionary <string, object> child = new Dictionary <string, object>(); childrenContainer.Add(child); child.Add("text", "CPU Stacks"); child.Add("type", "stacks"); child.Add("stackType", "CPU"); child.Add("path", pathToItem); child.Add("hasChildren", false); // TODO: Create Process / Files / Registry Stacks as child // TODO: Create TraceInfo htmlReport as child // TODO: Create Processes htmlReport as child // TODO: Create Events as child // TODO: Create Memory Group as child // TODO: Create Advanced Group as child } // TODO: Form proper response return(childrenContainer); }
public bool LoadEvents(int procID, int sampleInterval100ns) { m_procID = procID; m_SampleInterval = sampleInterval100ns / 10000.0; // Filter to process TraceEvents processEvents = m_traceLog.Events.Filter(FilterEvent); // Get Dispatcher TraceEventDispatcher source = processEvents.GetSource(); kernelGuid = KernelTraceEventParser.ProviderGuid; // Hookup events source.Clr.All += OnClrEvent; ClrPrivateTraceEventParser clrPrivate = new ClrPrivateTraceEventParser(source); clrPrivate.All += OnClrPrivateEvent; KernelTraceEventParser kernel = source.Kernel; kernel.PerfInfoSample += delegate(SampledProfileTraceData data) { ThreadMemoryInfo thread = GetThread(data.ThreadID); thread.AddEvent(HeapEvents.CPUSample, data.TimeStampRelativeMSec); }; kernel.VirtualMemAlloc += OnVirtualMem; kernel.VirtualMemFree += OnVirtualMem; m_processLookup = new Dictionary <int, Microsoft.Diagnostics.Tracing.Analysis.TraceProcess>(); // Process all events into GCProcess lookup dictionary Microsoft.Diagnostics.Tracing.Analysis.TraceLoadedDotNetRuntimeExtensions.NeedLoadedDotNetRuntimes(source); Microsoft.Diagnostics.Tracing.Analysis.TraceProcessesExtensions.AddCallbackOnProcessStart(source, proc => { Microsoft.Diagnostics.Tracing.Analysis.TraceProcessesExtensions.SetSampleIntervalMSec(proc, sampleInterval100ns); proc.Log = m_traceLog; }); source.Process(); foreach (var proc in Microsoft.Diagnostics.Tracing.Analysis.TraceProcessesExtensions.Processes(source)) { if (Microsoft.Diagnostics.Tracing.Analysis.TraceLoadedDotNetRuntimeExtensions.LoadedDotNetRuntime(proc) != null) { m_processLookup.Add(proc.ProcessID, proc); } } // Get the process we want if (!m_processLookup.ContainsKey(procID)) { return(false); } m_process = m_processLookup[procID]; m_runtime = Microsoft.Diagnostics.Tracing.Analysis.TraceLoadedDotNetRuntimeExtensions.LoadedDotNetRuntime(m_process); return(true); }
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)); } 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); }
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); 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); }
public static LogTrace GetLogTrace(string traceXML) { LogTrace LogTraces = new LogTrace(); try { XDocument document = XDocument.Parse(traceXML); XElement lsttraces = document.Descendants("trace").FirstOrDefault(); LogTraces.SimulationID = lsttraces.Attribute("id").Value; LogTraces.Percentage = GetPercentageInDouble(lsttraces.Attribute("percentage").Value); LogTraces.Title = lsttraces.Attribute("title").Value; IEnumerable <XElement> lstevents = lsttraces.Descendants("event"); List <TraceEvents> LstTraceEvents = new List <TraceEvents>(); foreach (var item in lstevents) { TraceEvents traceEvents = new TraceEvents(); traceEvents.EventID = item.Attribute("id").Value; traceEvents.EventLabel = item.Attribute("label").Value; traceEvents.EventRole = item.Attribute("role").Value; LstTraceEvents.Add(traceEvents); } LogTraces.EventIDs = LstTraceEvents; } catch (Exception) { // throw; } return(LogTraces); }
public StackSource GetStackSource(TraceEvents events) { if (events == null) { ThrowHelper.ThrowArgumentNullException(nameof(events)); } TraceLog log = events.Log; var stackSource = new MutableTraceEventStackSource(log) /* ShowUnknownAddresses = true */ }
public TraceSinkEvent FindEvent(string method, object parameters) { var expectedPayload = Utils.ObjectToDictionary(parameters); return(TraceEvents.SingleOrDefault(evt => String.Equals(evt.Name, method, StringComparison.OrdinalIgnoreCase) && // All expected keys must be present and equal. expectedPayload.All(pair => evt.Payload.ContainsKey(pair.Key) && Equals(evt.Payload[pair.Key], expectedPayload[pair.Key])))); }
public static StackSource CPUStacks(this TraceLog eventLog, TraceProcess process = null, bool showUnknownAddresses = false, Predicate <TraceEvent> predicate = null) { TraceEvents events = process == null?eventLog.Events.Filter(x => (predicate == null || predicate(x)) && x is SampledProfileTraceData && x.ProcessID != 0) : process.EventsInProcess.Filter(x => (predicate == null || predicate(x)) && x is SampledProfileTraceData); var traceStackSource = new TraceEventStackSource(events) { ShowUnknownAddresses = showUnknownAddresses }; return(traceStackSource); }
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 TraceEventStackSource(TraceEvents events) { Debug.Assert(m_log == null); if (events != null) { m_log = events.Log; } m_goodTopModuleIndex = ModuleFileIndex.Invalid; m_curSample = new StackSourceSample(this); m_curSample.Metric = events.Log.SampleProfileInterval100ns / 10000.0F; m_events = events; m_maxPseudoStack = m_log.CodeAddresses.MaxCodeAddressIndex; // This really is a guess as to how many stacks we need. }
/// <summary> /// Creates a new TraceEventStackSource given a list of events 'events' from a TraceLog /// </summary> /// <param name="events"></param> public TraceEventStackSource(TraceEvents events) { Debug.Assert(m_log == null); if (events != null) { m_log = events.Log; } m_goodTopModuleIndex = ModuleFileIndex.Invalid; m_curSample = new StackSourceSample(this); m_curSample.Metric = (float)events.Log.SampleProfileInterval.TotalMilliseconds; m_events = events; m_maxPseudoStack = m_log.CodeAddresses.Count * 2 + m_log.Threads.Count; // This really is a guess as to how many stacks we need. You can have as many as codeAddresses*threads }
public CallTreeDataProvider(TraceLog log, FilterParams filterParams, SymbolReader reader, ITraceDataPlugin plugin) { if (log == null) { ThrowHelper.ThrowArgumentNullException(nameof(log)); } if (filterParams == null) { ThrowHelper.ThrowArgumentNullException(nameof(filterParams)); } if (reader == null) { ThrowHelper.ThrowArgumentNullException(nameof(reader)); } if (plugin == null) { ThrowHelper.ThrowArgumentNullException(nameof(plugin)); } this.reader = reader; TraceEvents events = log.Events; var unfilteredStacksource = plugin.GetStackSource(events); this.summaryPredicate = plugin.SummaryPredicate; CallTree.DisableParallelism = true; // important this.stacksource = new FilterStackSource(filterParams, unfilteredStacksource, ScalingPolicyKind.TimeMetric); this.callTree = new CallTree(ScalingPolicyKind.TimeMetric) { StackSource = this.stacksource }; // Indicate I want the Time histograms to be computed. double startTimeRelativeMsec = 0; double.TryParse(filterParams.StartTimeRelativeMSec, out startTimeRelativeMsec); //System.Diagnostics.Debug.WriteLine("\n\nTIME: 1" + filterParams.StartTimeRelativeMSec + "\n2 " + startTimeRelativeMsec + "\n3 " + this.stacksource.SampleTimeRelativeMSecLimit + "\n\n"); callTree.TimeHistogramController = new TimeHistogramController(callTree, startTimeRelativeMsec, this.stacksource.SampleTimeRelativeMSecLimit); float minIncusiveTimePercent; if (float.TryParse(filterParams.MinInclusiveTimePercent, out minIncusiveTimePercent) && minIncusiveTimePercent > 0) { this.callTree.FoldNodesUnder(minIncusiveTimePercent * this.callTree.Root.InclusiveMetric / 100, true); } }
public void CalculateStatistics(string etlFileName, string providerName, string startEvent, string stopEvent, string outputReport = "report.xlsx") { Parser parser = new Parser(GetViewer(outputReport)); using (ETLDataFile etlFile = OpenETLFile(etlFileName)) { ParserArguments arguments = new ParserArguments { ProviderName = providerName, StartEvent = startEvent, StopEvent = stopEvent, OutputReport = outputReport }; TraceEvents events = GetTraceEventsWithProcessFilter(etlFile); parser.Parse(events, arguments); } }
private void Initialize(int processID, ProcessIndex processIndex, TraceEventDispatcher source) { ProcessID = processID; ParentID = -1; ProcessIndex = processIndex; endTimeQPC = long.MaxValue; CommandLine = ""; ImageFileName = ""; Source = source; Is64Bit = false; LoadedModules = null; Log = null; Parent = null; Threads = null; EventsInProcess = null; EventsDuringProcess = null; StartTime = EndTime = default(DateTime); StartTimeRelativeMsec = EndTimeRelativeMsec = -1; }
/// <summary> /// Allows the game to perform any initialization it needs to before starting to run. /// This is where it can query for any required services and load any non-graphic /// related content. Calling base.Initialize will enumerate through any components /// and initialize them as well. /// </summary> protected override void Initialize() { base.Initialize(); et = new EventTrace(this); TraceEvents.Register(et); testCount = 0; while (TestEntries.g_testEntries[testCount].createFcn != null) { ++testCount; } testIndex = MathUtils.Clamp(testIndex, 0, testCount - 1); testSelection = testIndex; entry = TestEntries.g_testEntries[testIndex]; test = entry.createFcn(); }
public CallTreeDataProvider(TraceLog log, FilterParams filterParams, SymbolReader reader, ITraceDataPlugin plugin) { if (log == null) { ThrowHelper.ThrowArgumentNullException(nameof(log)); } if (filterParams == null) { ThrowHelper.ThrowArgumentNullException(nameof(filterParams)); } if (reader == null) { ThrowHelper.ThrowArgumentNullException(nameof(reader)); } if (plugin == null) { ThrowHelper.ThrowArgumentNullException(nameof(plugin)); } this.reader = reader; TraceEvents events = log.Events; this.stacksource = plugin.GetStackSource(events); this.summaryPredicate = plugin.SummaryPredicate; CallTree.DisableParallelism = true; // important this.stacksource = new FilterStackSource(filterParams, this.stacksource, ScalingPolicyKind.TimeMetric); this.callTree = new CallTree(ScalingPolicyKind.TimeMetric) { StackSource = this.stacksource }; float minIncusiveTimePercent; if (float.TryParse(filterParams.MinInclusiveTimePercent, out minIncusiveTimePercent) && minIncusiveTimePercent > 0) { this.callTree.FoldNodesUnder(minIncusiveTimePercent * this.callTree.Root.InclusiveMetric / 100, true); } }
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); }
public bool LoadEvents(int procID, int sampleInterval100ns) { m_procID = procID; m_SampleInterval = sampleInterval100ns / 10000.0; // Filter to process TraceEvents processEvents = m_traceLog.Events.Filter(FilterEvent); // Get Dispatcher TraceEventDispatcher source = processEvents.GetSource(); kernelGuid = KernelTraceEventParser.ProviderGuid; // Hookup events source.Clr.All += OnClrEvent; ClrPrivateTraceEventParser clrPrivate = new ClrPrivateTraceEventParser(source); clrPrivate.All += OnClrPrivateEvent; KernelTraceEventParser kernel = source.Kernel; kernel.PerfInfoSample += delegate(SampledProfileTraceData data) { ThreadMemoryInfo thread = GetThread(data.ThreadID); thread.AddEvent(HeapEvents.CPUSample, data.TimeStampRelativeMSec); }; kernel.VirtualMemAlloc += OnVirtualMem; kernel.VirtualMemFree += OnVirtualMem; m_processLookup = new ProcessLookup <GCProcess>(); // Process all events into GCProcess lookup dictionary GCProcess.Collect(source, sampleInterval100ns, m_processLookup, null, false, m_traceLog); // Get the process we want return(m_processLookup.TryGetByID(procID, out m_gcProcess)); }
public static StackSource SingleEventTypeStack(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 traceStackSource = new TraceEventStackSource(events) { ShowUnknownAddresses = true }; return(CopyStackSource.Clone(traceStackSource)); }
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> /// This demo scans a particular ETL file for a strongly typed events (in this case Image Load events) /// and prints them out. /// </summary> public void DemoLoadLibrary(string etlFileName) { using (var etlFile = OpenETLFile(etlFileName)) { // If the user asked to focus on one process, do so. TraceEvents events = GetTraceEventsWithProcessFilter(etlFile); // Using this callback model is more efficient than the 'foreach' model because each event goes to // its callback already strongly typed to exactly the right type for the event. Search for subclasses // of TraceEventParser to see what strongly typed events exist. The Kernel and CLR events have these // and you can even make TraceEventParser's for your own events. var traceEventSource = events.GetSource(); // Set it up so that this code gets called back every time an ImageLoad event is encountered. traceEventSource.Kernel.ImageLoad += delegate(ImageLoadTraceData data) { LogFile.WriteLine("At {0:f3} Msec loaded at 0x{1:x} {2}", data.TimeStampRelativeMSec, data.ImageBase, data.FileName); }; // Process all the events in the 'events' list (do the callbacks that have been set up) traceEventSource.Process(); LogFile.WriteLine("[See log file for report]"); // Tell the user where the info is. } }
/// <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; }
/// <summary> /// Here is an example of a 'real' report. It computes startup statistics for a given process. /// </summary> /// <param name="etlFileName">The ETL file to open</param> /// <param name="processName">The name of the process to focus on. If not present, the first process to start is used.</param> public void DemoStartupReport(string etlFileName, string processName = null) { using (var etlFile = OpenETLFile(etlFileName)) { if (processName != null) { CommandLineArgs.Process = processName; } TraceProcess process = null; if (CommandLineArgs.Process != null) { process = etlFile.Processes.LastProcessWithName(CommandLineArgs.Process); if (process == null) { throw new ApplicationException("Could not find process named " + CommandLineArgs.Process); } LogFile.WriteLine("Focusing on process: {0} ({1}) starting at {2:n3} Msec", process.Name, process.ProcessID, process.StartTimeRelativeMsec); } else { // Find the first process that actually started in the trace. foreach (var processInFile in etlFile.Processes) { if (0 < processInFile.StartTimeRelativeMsec) { process = processInFile; } } if (process == null) { throw new ApplicationException("No process started in the trace."); } LogFile.WriteLine("Focusing on first process: {0} ({1}) starting at {2:n3} Msec", process.Name, process.ProcessID, process.StartTimeRelativeMsec); } // We define idle as the first time there this many msecs goes by without the process consuming // CPU or disk. Because the Prefetcher can keep the process 'idle' as it does bulk I/O for longer // than this we require that at least 3 DLL be loaded (since the Prefetcher happens VERY early). double idleDurationMSec = 200; // todo Make this a parameter. // Using this callback model is more efficient than the 'foreach' model because each event goes to // its callback already strongly typed to exactly the right type for the event. Search for subclasses // of TraceEventParser to see what strongly typed events exist. The Kernel and CLR events have these // and you can even make TraceEventParser's for your own events. TraceEvents events = process.EventsInProcess; var traceEventSource = events.GetSource(); double startTimeRelativeMSec = process.StartTimeRelativeMsec; /* Walk the events, gathering stats on I/O and CPU */ double lastNonIdleRelativeMSec = startTimeRelativeMSec; // used to compute idle int imageLoadCount = 0; // used to compute idle var CpuTimeByDllMSec = new Dictionary <string, double>(); double CpuTimeMSecTotal = 0; var IOTimeByFileMSec = new Dictionary <string, double>(); double IOTimeTotalMSec = 0; var lastIObyDisk = new double[4]; // Needed to compute service time. expanded as needed. traceEventSource.Kernel.ImageLoad += delegate(ImageLoadTraceData data) { imageLoadCount++; }; traceEventSource.Kernel.DiskIORead += delegate(DiskIOTraceData data) { // Stop if we have hit idle if (imageLoadCount > 2 && data.TimeStampRelativeMSec - lastNonIdleRelativeMSec > idleDurationMSec) { LogFile.WriteLine("Processing stopped at {0:n3} MSec", data.TimeStampRelativeMSec); traceEventSource.StopProcessing(); } lastNonIdleRelativeMSec = data.TimeStampRelativeMSec; if (data.DiskNumber >= lastIObyDisk.Length) { var newLastIObyDisk = new double[data.DiskNumber + 1]; Array.Copy(lastIObyDisk, newLastIObyDisk, lastIObyDisk.Length); lastIObyDisk = newLastIObyDisk; } // Service time is defined as the time the disk is actually servicing your requests (not waiting // for the requests in front of it to complete). This can be computed by taking the Min of // the Elapsed time and the time since the last I/O time from that disk (which is when it got to the // front of the queue). double serviceTimeMSec = Math.Min(data.ElapsedTimeMSec, data.TimeStampRelativeMSec - lastIObyDisk[data.DiskNumber]); // Accumulate I/O time var fileName = data.FileName; double fileIOTime = 0; IOTimeByFileMSec.TryGetValue(fileName, out fileIOTime); IOTimeByFileMSec[fileName] = fileIOTime + serviceTimeMSec; IOTimeTotalMSec += serviceTimeMSec; lastIObyDisk[data.DiskNumber] = data.TimeStampRelativeMSec; }; traceEventSource.Kernel.PerfInfoSample += delegate(SampledProfileTraceData data) { // Stop if we have hit idle if (imageLoadCount > 2 && data.TimeStampRelativeMSec - lastNonIdleRelativeMSec > idleDurationMSec) { LogFile.WriteLine("Processing stoped at {0:n3} Msec", data.TimeStampRelativeMSec); traceEventSource.StopProcessing(); } lastNonIdleRelativeMSec = data.TimeStampRelativeMSec; // Accumulate CPU time by dll double sampleCpuMSec = etlFile.TraceLog.SampleProfileInterval.TotalMilliseconds; CpuTimeMSecTotal += sampleCpuMSec; var moduleFilePath = "UNKNOWN"; var codeAddrIdx = data.IntructionPointerCodeAddressIndex(); if (codeAddrIdx != CodeAddressIndex.Invalid) { var moduleFile = data.Log().CodeAddresses.ModuleFile(codeAddrIdx); if (moduleFile != null) { moduleFilePath = moduleFile.FilePath; } } if (!string.IsNullOrEmpty(moduleFilePath)) { double curCpuTimeByDll = 0; CpuTimeByDllMSec.TryGetValue(moduleFilePath, out curCpuTimeByDll); CpuTimeByDllMSec[moduleFilePath] = curCpuTimeByDll + sampleCpuMSec; } }; // Process all the events in the 'events' list (do the callbacks that have been set up) traceEventSource.Process(); /* OK, my statistics variables have been udpated. Generate the report. */ var htmlFileName = CreateUniqueCacheFileName("StartupReport", ".html"); using (var htmlWriter = File.CreateText(htmlFileName)) { htmlWriter.WriteLine("<h1>Startup report for {0}</h1>", process.Name); htmlWriter.WriteLine("<ol>"); htmlWriter.WriteLine("<li>Total Startup time: {0:n3} MSec</li>", lastNonIdleRelativeMSec - startTimeRelativeMSec); htmlWriter.WriteLine("<li>Total CPU time: {0:n3} MSec</li>", CpuTimeMSecTotal); htmlWriter.WriteLine("<li>Total I/O time: {0:n3} MSec</li>", IOTimeTotalMSec); htmlWriter.WriteLine("</ol>"); htmlWriter.WriteLine("<h2>CPU Breakdown by DLL</h2>"); htmlWriter.WriteLine("<table border=\"1\">"); htmlWriter.WriteLine("<TR><TH>Dll Name</TH><TH>Cpu MSec</TH></TR>"); var dllNames = new List <string>(CpuTimeByDllMSec.Keys); // Sort decending by CPU time. dllNames.Sort((x, y) => CpuTimeByDllMSec[y].CompareTo(CpuTimeByDllMSec[x])); foreach (var dllName in dllNames) { htmlWriter.WriteLine("<TR><TD>{0}</TD><TD>{1:n3}</TD></TR>", Path.GetFileName(dllName), CpuTimeByDllMSec[dllName]); } htmlWriter.WriteLine("</table>"); htmlWriter.WriteLine("<h2>I/O Breakdown by DLL</h2>"); htmlWriter.WriteLine("<table border=\"1\">"); htmlWriter.WriteLine("<TR><TH>File Name</TH><TH>I/O MSec</TH></TR>"); var fileNames = new List <string>(IOTimeByFileMSec.Keys); // Sort decending by I/O time. fileNames.Sort((x, y) => IOTimeByFileMSec[y].CompareTo(IOTimeByFileMSec[x])); foreach (var fileName in fileNames) { htmlWriter.WriteLine("<TR><TD>{0}</TD><TD>{1:n3}</TD></TR>", Path.GetFileName(fileName), IOTimeByFileMSec[fileName]); } htmlWriter.WriteLine("</table>"); } LogFile.WriteLine("[Opening {0}]", htmlFileName); OpenHtmlReport(htmlFileName, "Startup Report", delegate(string command, TextWriter log, WebBrowserWindow window) { // This gets called when hyperlinks with a url that begin with 'command:' are clicked. // Typically you open up new Html windows or create CSV files and use OpenExcel log.WriteLine("[clicked on command {0}]", command); }); } }
public IEnumerable <TraceSinkEvent> GetEventsByMethod(string method) { return(TraceEvents.Where(evt => String.Equals(evt.Name, method, StringComparison.OrdinalIgnoreCase))); }