/// <summary>
/// Generate the thread time stacks, outputting to 'stackSource'.
/// </summary>
/// <param name="outputStackSource"></param>
/// <param name="traceEvents">Optional filtered trace events.</param>
public void GenerateThreadTimeStacks(MutableTraceEventStackSource outputStackSource, TraceEvents traceEvents = null)
{
m_outputStackSource = outputStackSource;
m_sample = new StackSourceSample(outputStackSource);
m_nodeNameInternTable = new Dictionary <double, StackSourceFrameIndex>(10);
m_ExternalFrameIndex = outputStackSource.Interner.FrameIntern("UNMANAGED_CODE_TIME");
m_cpuFrameIndex = outputStackSource.Interner.FrameIntern("CPU_TIME");
TraceLogEventSource eventSource = traceEvents == null?m_eventLog.Events.GetSource() :
traceEvents.GetSource();
if (GroupByStartStopActivity)
{
UseTasks = true;
}
if (UseTasks)
{
m_activityComputer = new ActivityComputer(eventSource, m_symbolReader);
m_activityComputer.AwaitUnblocks += delegate(TraceActivity activity, TraceEvent data)
{
var sample = m_sample;
sample.Metric = (float)(activity.StartTimeRelativeMSec - activity.CreationTimeRelativeMSec);
sample.TimeRelativeMSec = activity.CreationTimeRelativeMSec;
// The stack at the Unblock, is the stack at the time the task was created (when blocking started).
sample.StackIndex = m_activityComputer.GetCallStackForActivity(m_outputStackSource, activity, GetTopFramesForActivityComputerCase(data, data.Thread(), true));
StackSourceFrameIndex awaitFrame = m_outputStackSource.Interner.FrameIntern("AWAIT_TIME");
sample.StackIndex = m_outputStackSource.Interner.CallStackIntern(awaitFrame, sample.StackIndex);
m_outputStackSource.AddSample(sample);
if (m_threadToStartStopActivity != null)
{
UpdateStartStopActivityOnAwaitComplete(activity, data);
}
};
// We can provide a bit of extra value (and it is useful for debugging) if we immediately log a CPU
// sample when we schedule or start a task. That we we get the very instant it starts.
var tplProvider = new TplEtwProviderTraceEventParser(eventSource);
tplProvider.AwaitTaskContinuationScheduledSend += OnSampledProfile;
tplProvider.TaskScheduledSend += OnSampledProfile;
tplProvider.TaskExecuteStart += OnSampledProfile;
tplProvider.TaskWaitSend += OnSampledProfile;
tplProvider.TaskWaitStop += OnTaskUnblock; // Log the activity stack even if you don't have a stack.
}
if (GroupByStartStopActivity)
{
m_startStopActivities = new StartStopActivityComputer(eventSource, m_activityComputer, IgnoreApplicationInsightsRequestsWithRelatedActivityId);
// Maps thread Indexes to the start-stop activity that they are executing.
m_threadToStartStopActivity = new StartStopActivity[m_eventLog.Threads.Count];
/********* Start Unknown Async State machine for StartStop activities ******/
// The delegates below along with the AddUnkownAsyncDurationIfNeeded have one purpose:
// To inject UNKNOWN_ASYNC stacks when there is an active start-stop activity that is
// 'missing' time. It has the effect of insuring that Start-Stop tasks always have
// a metric that is not unrealistically small.
m_activityComputer.Start += delegate(TraceActivity activity, TraceEvent data)
{
StartStopActivity newStartStopActivityForThread = m_startStopActivities.GetCurrentStartStopActivity(activity.Thread, data);
UpdateThreadToWorkOnStartStopActivity(activity.Thread, newStartStopActivityForThread, data);
};
m_activityComputer.AfterStop += delegate(TraceActivity activity, TraceEvent data, TraceThread thread)
{
StartStopActivity newStartStopActivityForThread = m_startStopActivities.GetCurrentStartStopActivity(thread, data);
UpdateThreadToWorkOnStartStopActivity(thread, newStartStopActivityForThread, data);
};
m_startStopActivities.Start += delegate(StartStopActivity startStopActivity, TraceEvent data)
{
// We only care about the top-most activities since unknown async time is defined as time
// where a top most activity is running but no thread (or await time) is associated with it
// fast out otherwise (we just insure that we mark the thread as doing this activity)
if (startStopActivity.Creator != null)
{
UpdateThreadToWorkOnStartStopActivity(data.Thread(), startStopActivity, data);
return;
}
// Then we have a refcount of exactly one
Debug.Assert(m_unknownTimeStartMsec.Get((int)startStopActivity.Index) >= 0); // There was nothing running before.
m_unknownTimeStartMsec.Set((int)startStopActivity.Index, -1); // Set it so just we are running.
m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] = startStopActivity;
};
m_startStopActivities.Stop += delegate(StartStopActivity startStopActivity, TraceEvent data)
{
// We only care about the top-most activities since unknown async time is defined as time
// where a top most activity is running but no thread (or await time) is associated with it
// fast out otherwise
if (startStopActivity.Creator != null)
{
return;
}
double unknownStartTime = m_unknownTimeStartMsec.Get((int)startStopActivity.Index);
if (0 < unknownStartTime)
{
AddUnkownAsyncDurationIfNeeded(startStopActivity, unknownStartTime, data);
}
// Actually emit all the async unknown events.
List <StackSourceSample> samples = m_startStopActivityToAsyncUnknownSamples.Get((int)startStopActivity.Index);
if (samples != null)
{
foreach (var sample in samples)
{
m_outputStackSource.AddSample(sample); // Adding Unknown ASync
}
m_startStopActivityToAsyncUnknownSamples.Set((int)startStopActivity.Index, null);
}
m_unknownTimeStartMsec.Set((int)startStopActivity.Index, 0);
Debug.Assert(m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] == startStopActivity ||
m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] == null);
m_threadToStartStopActivity[(int)data.Thread().ThreadIndex] = null;
};
}
eventSource.Clr.GCAllocationTick += OnSampledProfile;
eventSource.Clr.GCSampledObjectAllocation += OnSampledProfile;
var eventPipeTraceEventPraser = new SampleProfilerTraceEventParser(eventSource);
eventPipeTraceEventPraser.ThreadSample += OnSampledProfile;
if (IncludeEventSourceEvents)
{
eventSource.Dynamic.All += delegate(TraceEvent data)
{
// TODO decide what the correct heuristic is.
// Currently I only do this for things that might be an EventSoruce (uses the name->Guid hashing)
// Most importantly, it excludes the high volume CLR providers.
if (!TraceEventProviders.MaybeAnEventSource(data.ProviderGuid))
{
return;
}
// We don't want most of the FrameworkEventSource events either.
if (data.ProviderGuid == FrameworkEventSourceTraceEventParser.ProviderGuid)
{
if (!((TraceEventID)140 <= data.ID && data.ID <= (TraceEventID)143)) // These are the GetResponce and GetResestStream events
{
return;
}
}
// We don't care about EventPipe sample profiler events.
if (data.ProviderGuid == SampleProfilerTraceEventParser.ProviderGuid)
{
return;
}
// We don't care about the TPL provider. Too many events.
if (data.ProviderGuid == TplEtwProviderTraceEventParser.ProviderGuid)
{
return;
}
// We don't care about ManifestData events.
if (data.ID == (TraceEventID)0xFFFE)
{
return;
}
TraceThread thread = data.Thread();
if (thread == null)
{
return;
}
StackSourceCallStackIndex stackIndex = GetCallStack(data, thread);
// Tack on additional info about the event.
var fieldNames = data.PayloadNames;
for (int i = 0; i < fieldNames.Length; i++)
{
var fieldName = fieldNames[i];
var value = data.PayloadString(i);
var fieldNodeName = "EventData: " + fieldName + "=" + value;
var fieldNodeIndex = m_outputStackSource.Interner.FrameIntern(fieldNodeName);
stackIndex = m_outputStackSource.Interner.CallStackIntern(fieldNodeIndex, stackIndex);
}
stackIndex = m_outputStackSource.Interner.CallStackIntern(m_outputStackSource.Interner.FrameIntern("EventName: " + data.ProviderName + "/" + data.EventName), stackIndex);
m_threadState[(int)thread.ThreadIndex].LogThreadStack(data.TimeStampRelativeMSec, stackIndex, thread, this, false);
};
}
eventSource.Process();
m_outputStackSource.DoneAddingSamples();
m_threadState = null;
}
public override void ForEach(Func <EventRecord, bool> callback)
{
int cnt = 0;
double startTime = StartTimeRelativeMSec;
double endTime = EndTimeRelativeMSec;
// TODO could be more efficient about process filtering by getting all the processes that match.
Regex procRegex = null;
string procNameMustStartWith = null;
if (ProcessFilterRegex != null)
{
// As an optimization, find the part that is just alphaNumeric
procNameMustStartWith = Regex.Match(ProcessFilterRegex, @"^(\w*)").Groups[1].Value;
procRegex = new Regex(ProcessFilterRegex, RegexOptions.IgnoreCase);
}
Predicate <ETWEventRecord> textFilter = null;
if (!string.IsNullOrWhiteSpace(TextFilterRegex))
{
string pat = TextFilterRegex;
bool negate = false;
if (pat.StartsWith("!"))
{
negate = true;
pat = pat.Substring(1);
}
var textRegex = new Regex(pat, RegexOptions.IgnoreCase);
textFilter = delegate(ETWEventRecord eventRecord)
{
bool match = eventRecord.Matches(textRegex);
return(negate ? !match : match);
};
}
Dictionary <string, int> columnOrder = null;
ColumnSums = null;
if (ColumnsToDisplay != null)
{
columnOrder = new Dictionary <string, int>();
for (int i = 0; i < ColumnsToDisplay.Count;)
{
// Discard duplicate columns
if (columnOrder.ContainsKey(ColumnsToDisplay[i]))
{
ColumnsToDisplay.RemoveAt(i);
continue;
}
columnOrder.Add(ColumnsToDisplay[i], i);
i++;
}
ColumnSums = new double[ColumnsToDisplay.Count];
}
if (m_selectedEvents != null)
{
ETWEventRecord emptyEventRecord = new ETWEventRecord(this);
var startStopRecords = new Dictionary <StartStopKey, double>(10);
// Figure out if you need m_activityComputer or not
// Because it is moderately expensive, and not typically used, we only include the activity stuff
// when you explicitly ask for it
m_needsComputers = false;
if (ColumnsToDisplay != null)
{
foreach (string column in ColumnsToDisplay)
{
if (column == "*" || column == "ActivityInfo" || column == "StartStopActivity")
{
m_needsComputers = true;
break;
}
}
}
/***********************************************************************/
/* The main event loop */
EventVisitedVersion.CurrentVersion++;
var source = m_tracelog.Events.FilterByTime(m_needsComputers ? 0 : startTime, endTime).GetSource(); // If you need computers, you need the events from the start.
if (m_needsComputers)
{
m_activityComputer = new ActivityComputer(source, App.GetSymbolReader());
m_startStopActivityComputer = new StartStopActivityComputer(source, m_activityComputer);
}
source.AllEvents += delegate(TraceEvent data)
{
// FilterByTime would cover this, however for m_needsComputer == true we may not be able to do it that way.
if (data.TimeStampRelativeMSec < startTime)
{
return;
}
double durationMSec = -1;
var eventFilterVersion = data.EventTypeUserData as EventVisitedVersion;
if (eventFilterVersion == null || eventFilterVersion.Version != EventVisitedVersion.CurrentVersion)
{
var eventName = data.ProviderName + "/" + data.EventName;
bool processButDontShow = false;
var shouldKeep = m_selectedAllEvents;
if (!shouldKeep)
{
if (m_selectedEvents.TryGetValue(eventName, out processButDontShow))
{
shouldKeep = true;
}
}
eventFilterVersion = new EventVisitedVersion(shouldKeep, processButDontShow);
if (!(data is UnhandledTraceEvent))
{
data.EventTypeUserData = eventFilterVersion;
}
}
if (!eventFilterVersion.ShouldProcess)
{
return;
}
// If this is a StopEvent compute the DURATION_MSEC
var opcode = data.Opcode;
var task = data.Task;
CorelationOptions corelationOptions = CorelationOptions.None;
if (data.ProviderGuid == ClrTraceEventParser.ProviderGuid)
{
// Fix Suspend and restart events to line up to make durations.
if ((int)data.ID == 9) // SuspendEEStart
{
corelationOptions = CorelationOptions.UseThreadContext;
task = (TraceEventTask)0xFFFE; // unique task
opcode = TraceEventOpcode.Start;
}
else if ((int)data.ID == 8) // SuspendEEStop
{
corelationOptions = CorelationOptions.UseThreadContext;
task = (TraceEventTask)0xFFFE; // unique task (used for both suspend and Suspend-Restart.
opcode = TraceEventOpcode.Stop;
}
else if ((int)data.ID == 3) // RestartEEStop
{
corelationOptions = CorelationOptions.UseThreadContext;
task = (TraceEventTask)0xFFFE; // unique task
opcode = TraceEventOpcode.Stop;
}
}
if (data.ProviderGuid == httpServiceProviderGuid)
{
corelationOptions = CorelationOptions.UseActivityID;
if (opcode == (TraceEventOpcode)13) // HttpServiceDeliver
{
opcode = TraceEventOpcode.Start;
}
// HttpServiceSendComplete ZeroSend FastSend
else if (opcode == (TraceEventOpcode)51 || opcode == (TraceEventOpcode)22 || opcode == (TraceEventOpcode)21)
{
opcode = TraceEventOpcode.Stop;
}
}
if (data.ProviderGuid == systemDataProviderGuid)
{
corelationOptions = CorelationOptions.UseActivityID;
if ((int)data.ID == 1) // BeginExecute
{
task = (TraceEventTask)0xFFFE; // unique task but used for both BeginExecute and EndExecute.
opcode = TraceEventOpcode.Start;
}
else if ((int)data.ID == 2) // EndExecute
{
task = (TraceEventTask)0xFFFE; // unique task but used for both BeginExecute and EndExecute.
opcode = TraceEventOpcode.Stop;
}
}
if (opcode == TraceEventOpcode.Start || opcode == TraceEventOpcode.Stop)
{
// Figure out what we use as a correlater between the start and stop.
Guid contextID = GetCoorelationIDForEvent(data, corelationOptions);
var key = new StartStopKey(data.ProviderGuid, task, contextID);
if (opcode == TraceEventOpcode.Start)
{
startStopRecords[key] = data.TimeStampRelativeMSec;
}
else
{
double startTimeStamp;
if (startStopRecords.TryGetValue(key, out startTimeStamp))
{
durationMSec = data.TimeStampRelativeMSec - startTimeStamp;
// A bit of a hack. WE use the same start event (SuspenEEStart) for two durations.
// Thus don't remove it after SuspendEEStop because we also use it for RestartEEStop.
if (!(task == (TraceEventTask)0xFFFE && (int)data.ID == 8)) // Is this the SuspendEEStop event?
{
startStopRecords.Remove(key);
}
}
}
}
if (!eventFilterVersion.ShouldShow)
{
return;
}
if (procRegex != null)
{
CSwitchTraceData cSwitch = data as CSwitchTraceData;
if (!data.ProcessName.StartsWith(procNameMustStartWith, StringComparison.OrdinalIgnoreCase))
{
if (cSwitch == null)
{
return;
}
// Special case. Context switches will work for both the old and the new process
if (!cSwitch.OldProcessName.StartsWith(procNameMustStartWith, StringComparison.OrdinalIgnoreCase))
{
return;
}
}
var fullProcessName = data.ProcessName;
if (!fullProcessName.StartsWith("("))
{
fullProcessName += " (" + data.ProcessID + ")";
}
if (!procRegex.IsMatch(fullProcessName))
{
if (cSwitch == null)
{
return;
}
// Special case. Context switches will work for both the old and the new process
var fullOldProcessName = cSwitch.OldProcessName;
if (!fullOldProcessName.StartsWith("("))
{
fullOldProcessName += " (" + cSwitch.OldProcessName + ")";
}
if (!procRegex.IsMatch(fullOldProcessName))
{
return;
}
}
}
ETWEventRecord eventRecord = null;
if (textFilter != null)
{
eventRecord = new ETWEventRecord(this, data, columnOrder, NonRestFields, durationMSec);
if (!textFilter(eventRecord))
{
return;
}
}
cnt++;
if (MaxRet < cnt)
{
// We have exceeded our MaxRet, return an empty record.
eventRecord = emptyEventRecord;
eventRecord.m_timeStampRelativeMSec = data.TimeStampRelativeMSec;
}
if (eventRecord == null)
{
eventRecord = new ETWEventRecord(this, data, columnOrder, NonRestFields, durationMSec);
}
if (ColumnSums != null)
{
var fields = eventRecord.DisplayFields;
var min = Math.Min(ColumnSums.Length, fields.Length);
for (int i = 0; i < min; i++)
{
string value = fields[i];
double asDouble;
if (value != null && double.TryParse(value, out asDouble))
{
ColumnSums[i] += asDouble;
}
}
}
if (!callback(eventRecord))
{
source.StopProcessing();
}
};
source.Process();
}
}
