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