/// <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. } }