public static string Path(ActivityInfo?activityInfo)
{
if (activityInfo == null)
{
return("");
}
return(Path(activityInfo.m_creator) + "/" + activityInfo.m_uniqueId.ToString());
}
public static string LiveActivities(ActivityInfo?list)
{
if (list == null)
{
return("");
}
return(list.ToString() + ";" + LiveActivities(list.m_creator));
}
public static string Path(ActivityInfo?activityInfo)
{
if (activityInfo == null)
{
return("");
}
return($"{Path(activityInfo.m_creator)}/{activityInfo.m_uniqueId}");
}
public ActivityInfo(string name, long uniqueId, ActivityInfo?creator, Guid activityIDToRestore, EventActivityOptions options)
{
m_name = name;
m_eventOptions = options;
m_creator = creator;
m_uniqueId = uniqueId;
m_level = creator != null ? creator.m_level + 1 : 0;
m_activityIdToRestore = activityIDToRestore;
// Create a nice GUID that encodes the chain of activities that started this one.
CreateActivityPathGuid(out m_guid, out m_activityPathGuidOffset);
}
/// <summary>
/// Searched for a active (nonstopped) activity with the given name. Returns null if not found.
/// </summary>
private static ActivityInfo?FindActiveActivity(string name, ActivityInfo?startLocation)
{
ActivityInfo?activity = startLocation;
while (activity != null)
{
if (name == activity.m_name && activity.m_stopped == 0)
{
return(activity);
}
activity = activity.m_creator;
}
return(null);
}
/// <summary>
/// If we can't fit the activity Path into the GUID we come here. What we do is simply
/// generate a 4 byte number (s_nextOverflowId). Then look for an ancestor that has
/// sufficient space for this ID. By doing this, we preserve the fact that this activity
/// is a child (of unknown depth) from that ancestor.
/// </summary>
private unsafe void CreateOverflowGuid(Guid *outPtr)
{
// Search backwards for an ancestor that has sufficient space to put the ID.
for (ActivityInfo?ancestor = m_creator; ancestor != null; ancestor = ancestor.m_creator)
{
if (ancestor.m_activityPathGuidOffset <= 10) // we need at least 2 bytes.
{
uint id = unchecked ((uint)Interlocked.Increment(ref ancestor.m_lastChildID)); // Get a unique ID
// Try to put the ID into the GUID
* outPtr = ancestor.m_guid;
int endId = AddIdToGuid(outPtr, ancestor.m_activityPathGuidOffset, id, true);
// Does it fit?
if (endId <= 12)
{
break;
}
}
}
}
// This callback is used to initialize the m_current AsyncLocal Variable.
// Its job is to keep the ETW Activity ID (part of thread local storage) in sync
// with m_current.ActivityID
//
// WARNING: When mixing manual usage of EventSource.SetCurrentThreadActivityID
// and Start/Stop EventSource events I can't identify a clear design how this
// synchronization is intended to work. For example code that changes
// SetCurrentThreadActivityID after a FooStart() event will not flow the
// explicit ID with the async work, but if FooStart() event is called after
// SetCurrentThreadActivityID then the explicit ID change does flow.
// For now I've adopted the approach:
// Priority 1: Make the API predictable/sensible when only Start/Stop events
// are in use.
// Priority 2: If users aren't complaining and it doesn't interfere with
// goal #1, try to preserve the arbitrary/buggy? existing behavior
// for mixed usage of SetActivityID + events.
//
// For scenarios that only use start/stop events this is what we expect:
// calling start -> push new ID on stack and update thread-local to match new ID
// calling stop -> pop ID from stack and update thread-local to match new topmost
// still active ID. If there is none, set ID to zero
// thread swap -> update thread-local to match topmost active ID.
// If there is none, set ID to zero.
private void ActivityChanging(AsyncLocalValueChangedArgs <ActivityInfo?> args)
{
ActivityInfo?cur = args.CurrentValue;
ActivityInfo?prev = args.PreviousValue;
// Special case only relevant for mixed SetActivityID usage:
//
// Are we MAYBE popping off a value? (we have a prev, and it creator is cur)
// We can't be certain this is a pop because a thread swapping between two
// ExecutionContexts can also appear the same way.
// Then check if we should use the GUID at the time of the start event
if (prev != null && prev.m_creator == cur)
{
// If the saved activity ID is not the same as the creator activity
// that takes precedence (it means someone explicitly did a SetActivityID)
// Set it to that and get out
if (cur == null || prev.m_activityIdToRestore != cur.ActivityId)
{
EventSource.SetCurrentThreadActivityId(prev.m_activityIdToRestore);
return;
}
}
// Set the activity to current ActivityInfo. However that activity
// might be dead, in which case we should skip it, so we never set
// the ID to dead things.
while (cur != null)
{
// We found a live activity (typically the first time), set it to that.
if (cur.m_stopped == 0)
{
EventSource.SetCurrentThreadActivityId(cur.ActivityId);
return;
}
cur = cur.m_creator;
}
// we can get here if there is no information on our activity stack (everything is dead)
// Set ActivityID to zero
EventSource.SetCurrentThreadActivityId(Guid.Empty);
}
// This callback is used to initialize the m_current AsyncLocal Variable.
// Its job is to keep the ETW Activity ID (part of thread local storage) in sync
// with m_current.ActivityID
private void ActivityChanging(AsyncLocalValueChangedArgs <ActivityInfo?> args)
{
ActivityInfo?cur = args.CurrentValue;
ActivityInfo?prev = args.PreviousValue;
// Are we popping off a value? (we have a prev, and it creator is cur)
// Then check if we should use the GUID at the time of the start event
if (prev != null && prev.m_creator == cur)
{
// If the saved activity ID is not the same as the creator activity
// that takes precedence (it means someone explicitly did a SetActivityID)
// Set it to that and get out
if (cur == null || prev.m_activityIdToRestore != cur.ActivityId)
{
EventSource.SetCurrentThreadActivityId(prev.m_activityIdToRestore);
return;
}
}
// OK we did not have an explicit SetActivityID set. Then we should be
// setting the activity to current ActivityInfo. However that activity
// might be dead, in which case we should skip it, so we never set
// the ID to dead things.
while (cur != null)
{
// We found a live activity (typically the first time), set it to that.
if (cur.m_stopped == 0)
{
EventSource.SetCurrentThreadActivityId(cur.ActivityId);
return;
}
cur = cur.m_creator;
}
// we can get here if there is no information on our activity stack (everything is dead)
// currently we do nothing, as that seems better than setting to Guid.Emtpy.
}
/// <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, bool useTplSource = true)
{
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 (useTplSource && 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 = useTplSource ? TplEventSource.Log : null;
bool tplDebug = log != null && log.Debug;
if (tplDebug)
{
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 (tplDebug)
{
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 (tplDebug)
{
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, bool useTplSource = true)
{
if (m_current == null) // We are not enabled
{
return;
}
string fullActivityName = NormalizeActivityName(providerName, activityName, task);
TplEventSource?log = useTplSource ? TplEventSource.Log : null;
bool tplDebug = log != null && log.Debug;
if (tplDebug)
{
log !.DebugFacilityMessage("OnStopEnter", fullActivityName);
log !.DebugFacilityMessage("OnStopEnterActivityState", ActivityInfo.LiveActivities(m_current.Value));
}
while (true) // 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 (tplDebug)
{
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.
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.
newCurrentActivity ??= activityToStop.m_creator;
m_current.Value = newCurrentActivity;
if (tplDebug)
{
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.
}
}
