/// <summary>
/// Outputs a WaitBegin ETW event, and augments the continuation action to output a WaitEnd ETW event.
/// </summary>
/// <param name="task">The task being awaited.</param>
/// <param name="continuation">The action to invoke when the await operation completes.</param>
/// <returns>The action to use as the actual continuation.</returns>
private static Action OutputWaitEtwEvents(Task task, Action continuation)
{
Debug.Assert(task != null, "Need a task to wait on");
Debug.Assert(continuation != null, "Need a continuation to invoke when the wait completes");
if (Task.s_asyncDebuggingEnabled)
{
Task.AddToActiveTasks(task);
}
TplEventSource log = TplEventSource.Log;
if (log.IsEnabled())
{
// ETW event for Task Wait Begin
Task?currentTaskAtBegin = Task.InternalCurrent;
// If this task's continuation is another task, get it.
Task?continuationTask = AsyncMethodBuilderCore.TryGetContinuationTask(continuation);
log.TaskWaitBegin(
currentTaskAtBegin != null ? currentTaskAtBegin.m_taskScheduler !.Id : TaskScheduler.Default.Id,
currentTaskAtBegin != null ? currentTaskAtBegin.Id : 0,
task.Id, TplEventSource.TaskWaitBehavior.Asynchronous,
continuationTask != null ? continuationTask.Id : 0);
}
// Create a continuation action that outputs the end event and then invokes the user
// provided delegate. This incurs the allocations for the closure/delegate, but only if the event
// is enabled, and in doing so it allows us to pass the awaited task's information into the end event
// in a purely pay-for-play manner (the alternatively would be to increase the size of TaskAwaiter
// just for this ETW purpose, not pay-for-play, since GetResult would need to know whether a real yield occurred).
return(AsyncMethodBuilderCore.CreateContinuationWrapper(continuation, static (innerContinuation, innerTask) =>
/// <summary>
/// Outputs a WaitBegin ETW event, and augments the continuation action to output a WaitEnd ETW event.
/// </summary>
/// <param name="task">The task being awaited.</param>
/// <param name="continuation">The action to invoke when the await operation completes.</param>
/// <returns>The action to use as the actual continuation.</returns>
private static Action OutputWaitEtwEvents(Task task, Action continuation)
{
Debug.Assert(task != null, "Need a task to wait on");
Debug.Assert(continuation != null, "Need a continuation to invoke when the wait completes");
if (Task.s_asyncDebuggingEnabled)
{
Task.AddToActiveTasks(task);
}
TplEventSource log = TplEventSource.Log;
if (log.IsEnabled())
{
// ETW event for Task Wait Begin
Task?currentTaskAtBegin = Task.InternalCurrent;
// If this task's continuation is another task, get it.
Task?continuationTask = AsyncMethodBuilderCore.TryGetContinuationTask(continuation);
log.TaskWaitBegin(
currentTaskAtBegin != null ? currentTaskAtBegin.m_taskScheduler !.Id : TaskScheduler.Default.Id,
currentTaskAtBegin != null ? currentTaskAtBegin.Id : 0,
task.Id, TplEventSource.TaskWaitBehavior.Asynchronous,
continuationTask != null ? continuationTask.Id : 0);
}
// Create a continuation action that outputs the end event and then invokes the user
// provided delegate. This incurs the allocations for the closure/delegate, but only if the event
// is enabled, and in doing so it allows us to pass the awaited task's information into the end event
// in a purely pay-for-play manner (the alternatively would be to increase the size of TaskAwaiter
// just for this ETW purpose, not pay-for-play, since GetResult would need to know whether a real yield occurred).
return(AsyncMethodBuilderCore.CreateContinuationWrapper(continuation, (innerContinuation, innerTask) =>
{
if (Task.s_asyncDebuggingEnabled)
{
Task.RemoveFromActiveTasks(innerTask);
}
TplEventSource innerEtwLog = TplEventSource.Log;
// ETW event for Task Wait End.
Guid prevActivityId = default;
bool bEtwLogEnabled = innerEtwLog.IsEnabled();
if (bEtwLogEnabled)
{
Task?currentTaskAtEnd = Task.InternalCurrent;
innerEtwLog.TaskWaitEnd(
currentTaskAtEnd != null ? currentTaskAtEnd.m_taskScheduler !.Id : TaskScheduler.Default.Id,
currentTaskAtEnd != null ? currentTaskAtEnd.Id : 0,
innerTask.Id);
// Ensure the continuation runs under the activity ID of the task that completed for the
// case the antecedent is a promise (in the other cases this is already the case).
if (innerEtwLog.TasksSetActivityIds && (innerTask.Options & (TaskCreationOptions)InternalTaskOptions.PromiseTask) != 0)
{
EventSource.SetCurrentThreadActivityId(TplEventSource.CreateGuidForTaskID(innerTask.Id), out prevActivityId);
}
}
/// <summary>
/// Called on work item begins. The activity name = providerName + activityName without 'Start' suffix.
/// It updates CurrentActivityId to track.
///
/// It returns true if the Start should be logged, otherwise (if it is illegal recursion) it return false.
///
/// The start event should use as its activity ID the CurrentActivityId AFTER calling this routine and its
/// RelatedActivityID the CurrentActivityId BEFORE calling this routine (the creator).
///
/// If activity tracing is not on, then activityId and relatedActivityId are not set
/// </summary>
public void OnStart(string providerName, string activityName, int task, ref Guid activityId, ref Guid relatedActivityId, EventActivityOptions options)
{
if (m_current == null) // We are not enabled
{
// We used to rely on the TPL provider turning us on, but that has the disadvantage that you don't get Start-Stop tracking
// until you use Tasks for the first time (which you may never do). Thus we change it to pull rather tan push for whether
// we are enabled.
if (m_checkedForEnable)
{
return;
}
m_checkedForEnable = true;
if (TplEventSource.Log.IsEnabled(EventLevel.Informational, TplEventSource.Keywords.TasksFlowActivityIds))
{
Enable();
}
if (m_current == null)
{
return;
}
}
Debug.Assert((options & EventActivityOptions.Disable) == 0);
ActivityInfo?currentActivity = m_current.Value;
string fullActivityName = NormalizeActivityName(providerName, activityName, task);
TplEventSource log = TplEventSource.Log;
if (log.Debug)
{
log.DebugFacilityMessage("OnStartEnter", fullActivityName);
log.DebugFacilityMessage("OnStartEnterActivityState", ActivityInfo.LiveActivities(currentActivity));
}
if (currentActivity != null)
{
// Stop activity tracking if we reached the maximum allowed depth
if (currentActivity.m_level >= MAX_ACTIVITY_DEPTH)
{
activityId = Guid.Empty;
relatedActivityId = Guid.Empty;
if (log.Debug)
{
log.DebugFacilityMessage("OnStartRET", "Fail");
}
return;
}
// Check for recursion, and force-stop any activities if the activity already started.
if ((options & EventActivityOptions.Recursive) == 0)
{
ActivityInfo?existingActivity = FindActiveActivity(fullActivityName, currentActivity);
if (existingActivity != null)
{
OnStop(providerName, activityName, task, ref activityId);
currentActivity = m_current.Value;
}
}
}
// Get a unique ID for this activity.
long id;
if (currentActivity == null)
{
id = Interlocked.Increment(ref m_nextId);
}
else
{
id = Interlocked.Increment(ref currentActivity.m_lastChildID);
}
// The previous ID is my 'causer' and becomes my related activity ID
relatedActivityId = EventSource.CurrentThreadActivityId;
// Add to the list of started but not stopped activities.
ActivityInfo newActivity = new ActivityInfo(fullActivityName, id, currentActivity, relatedActivityId, options);
m_current.Value = newActivity;
// Remember the current ID so we can log it
activityId = newActivity.ActivityId;
if (log.Debug)
{
log.DebugFacilityMessage("OnStartRetActivityState", ActivityInfo.LiveActivities(newActivity));
log.DebugFacilityMessage1("OnStartRet", activityId.ToString(), relatedActivityId.ToString());
}
}
/// <summary>
/// Called when a work item stops. The activity name = providerName + activityName without 'Stop' suffix.
/// It updates m_current variable to track this fact. The Stop event associated with stop should log the ActivityID associated with the event.
///
/// If activity tracing is not on, then activityId and relatedActivityId are not set
/// </summary>
public void OnStop(string providerName, string activityName, int task, ref Guid activityId)
{
if (m_current == null) // We are not enabled
{
return;
}
string fullActivityName = NormalizeActivityName(providerName, activityName, task);
TplEventSource log = TplEventSource.Log;
if (log.Debug)
{
log.DebugFacilityMessage("OnStopEnter", fullActivityName);
log.DebugFacilityMessage("OnStopEnterActivityState", ActivityInfo.LiveActivities(m_current.Value));
}
for (; ;) // This is a retry loop.
{
ActivityInfo?currentActivity = m_current.Value;
ActivityInfo?newCurrentActivity = null; // if we have seen any live activities (orphans), at he first one we have seen.
// Search to find the activity to stop in one pass. This insures that we don't let one mistake
// (stopping something that was not started) cause all active starts to be stopped
// By first finding the target start to stop we are more robust.
ActivityInfo?activityToStop = FindActiveActivity(fullActivityName, currentActivity);
// ignore stops where we can't find a start because we may have popped them previously.
if (activityToStop == null)
{
activityId = Guid.Empty;
// TODO add some logging about this. Basically could not find matching start.
if (log.Debug)
{
log.DebugFacilityMessage("OnStopRET", "Fail");
}
return;
}
activityId = activityToStop.ActivityId;
// See if there are any orphans that need to be stopped.
ActivityInfo?orphan = currentActivity;
while (orphan != activityToStop && orphan != null)
{
if (orphan.m_stopped != 0) // Skip dead activities.
{
orphan = orphan.m_creator;
continue;
}
if (orphan.CanBeOrphan())
{
// We can't pop anything after we see a valid orphan, remember this for later when we update m_current.
if (newCurrentActivity == null)
{
newCurrentActivity = orphan;
}
}
else
{
orphan.m_stopped = 1;
Debug.Assert(orphan.m_stopped != 0);
}
orphan = orphan.m_creator;
}
// try to Stop the activity atomically. Other threads may be trying to do this as well.
if (Interlocked.CompareExchange(ref activityToStop.m_stopped, 1, 0) == 0)
{
// I succeeded stopping this activity. Now we update our m_current pointer
// If I haven't yet determined the new current activity, it is my creator.
if (newCurrentActivity == null)
{
newCurrentActivity = activityToStop.m_creator;
}
m_current.Value = newCurrentActivity;
if (log.Debug)
{
log.DebugFacilityMessage("OnStopRetActivityState", ActivityInfo.LiveActivities(newCurrentActivity));
log.DebugFacilityMessage("OnStopRet", activityId.ToString());
}
return;
}
// We failed to stop it. We must have hit a race to stop it. Just start over and try again.
}
}
