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