/// <summary>
/// Updates it so that 'thread' is now working on newStartStop, which can be null which means that it is not working on any
/// start-stop task.
/// </summary>
private void UpdateThreadToWorkOnStartStopActivity(TraceThread thread, StartStopActivity newStartStop, TraceEvent data)
{
// Make the new-start stop activity be the top most one. This is all we need and is more robust in the case
// of unusual state transitions (e.g. lost events non-nested start-stops ...). Ref-counting is very fragile
// after all...
if (newStartStop != null)
{
while (newStartStop.Creator != null)
{
newStartStop = newStartStop.Creator;
}
}
StartStopActivity oldStartStop = m_threadToStartStopActivity[(int)thread.ThreadIndex];
Debug.Assert(oldStartStop == null || oldStartStop.Creator == null);
if (oldStartStop == newStartStop) // No change, nothing to do, quick exit.
{
return;
}
// Decrement the start-stop which lost its thread.
if (oldStartStop != null)
{
double unknownStartTimeMSec = m_unknownTimeStartMsec.Get((int)oldStartStop.Index);
Debug.Assert(unknownStartTimeMSec < 0);
if (unknownStartTimeMSec < 0)
{
unknownStartTimeMSec++; //We represent the ref count as a negative number, here we are decrementing the ref count
if (unknownStartTimeMSec == 0)
{
unknownStartTimeMSec = data.TimeStampRelativeMSec; // Remember when we dropped to zero.
}
m_unknownTimeStartMsec.Set((int)oldStartStop.Index, unknownStartTimeMSec);
}
}
m_threadToStartStopActivity[(int)thread.ThreadIndex] = newStartStop;
// Increment refcount on the new startStop activity
if (newStartStop != null)
{
double unknownStartTimeMSec = m_unknownTimeStartMsec.Get((int)newStartStop.Index);
// If we were off before (a positive number) then log the unknown time.
if (0 < unknownStartTimeMSec)
{
AddUnkownAsyncDurationIfNeeded(newStartStop, unknownStartTimeMSec, data);
unknownStartTimeMSec = 0;
}
--unknownStartTimeMSec; //We represent the ref count as a negative number, here we are incrementing the ref count
m_unknownTimeStartMsec.Set((int)newStartStop.Index, unknownStartTimeMSec);
}
}
private void AddUnkownAsyncDurationIfNeeded(StartStopActivity startStopActivity, double unknownStartTimeMSec, TraceEvent data)
{
Debug.Assert(0 < unknownStartTimeMSec);
Debug.Assert(unknownStartTimeMSec <= data.TimeStampRelativeMSec);
if (startStopActivity.IsStopped)
{
return;
}
// We dont bother with times that are too small, we consider 1msec the threshold
double delta = data.TimeStampRelativeMSec - unknownStartTimeMSec;
if (delta < 1)
{
return;
}
// Add a sample with the amount of unknown duration.
var sample = new StackSourceSample(m_outputStackSource);
sample.Metric = (float)delta;
sample.TimeRelativeMSec = unknownStartTimeMSec;
StackSourceCallStackIndex stackIndex = m_startStopActivities.GetStartStopActivityStack(m_outputStackSource, startStopActivity, data.Process());
StackSourceFrameIndex unknownAsyncFrame = m_outputStackSource.Interner.FrameIntern("UNKNOWN_ASYNC");
stackIndex = m_outputStackSource.Interner.CallStackIntern(unknownAsyncFrame, stackIndex);
sample.StackIndex = stackIndex;
// We can't add the samples right now because AWAIT nodes might overlap and we have to take these back.
// The add the to this list so that they can be trimmed at that time if needed.
List <StackSourceSample> list = m_startStopActivityToAsyncUnknownSamples.Get((int)startStopActivity.Index);
if (list == null)
{
list = new List <StackSourceSample>();
m_startStopActivityToAsyncUnknownSamples.Set((int)startStopActivity.Index, list);
}
list.Add(sample);
}
/// <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;
}
