2 using System.Diagnostics;
3 using System.Threading;
4 #if !ES_BUILD_AGAINST_DOTNET_V35
5 using Contract = System.Diagnostics.Contracts.Contract;
7 using Contract = Microsoft.Diagnostics.Contracts.Internal.Contract;
10 #if ES_BUILD_STANDALONE
11 namespace Microsoft.Diagnostics.Tracing
13 using System.Threading.Tasks;
14 namespace System.Diagnostics.Tracing
18 /// Tracks activities. This is meant to be a singleton (accessed by the ActivityTracer.Instance static property)
20 /// Logically this is simply holds the m_current variable that holds the async local that holds the current ActivityInfo
21 /// An ActivityInfo is represents a activity (which knows its creator and thus knows its path).
23 /// Most of the magic is in the async local (it gets copied to new tasks)
25 /// On every start event call OnStart
28 /// Guid relatedActivityID;
29 /// if (OnStart(activityName, out activityID, out relatedActivityID, ForceStop, options))
30 /// // Log Start event with activityID and relatedActivityID
32 /// On every stop event call OnStop
35 /// if (OnStop(activityName, ref activityID ForceStop))
36 /// // Stop event with activityID
38 /// On any normal event log the event with activityTracker.CurrentActivityId
40 internal class ActivityTracker
44 /// Called on work item begins. The activity name = providerName + activityName without 'Start' suffix.
45 /// It updates CurrentActivityId to track.
47 /// It returns true if the Start should be logged, otherwise (if it is illegal recurision) it return false.
49 /// The start event should use as its activity ID the CurrentActivityId AFTER calling this routine and its
50 /// RelatedActivityID the CurrentActivityId BEFORE calling this routine (the creator).
52 /// If activity tracing is not on, then activityId and relatedActivityId are not set
54 public void OnStart(string providerName, string activityName, int task, ref Guid activityId, ref Guid relatedActivityId, EventActivityOptions options)
56 if (m_current == null) // We are not enabled
58 // We used to rely on the TPL provider turning us on, but that has the disadvantage that you don't get Start-Stop tracking
59 // until you use Tasks for the first time (which you may never do). Thus we change it to pull rather tan push for whether
61 if (m_checkedForEnable)
63 m_checkedForEnable = true;
64 #if ES_BUILD_STANDALONE
65 Enable(); // Enable it unconditionally.
67 if (System.Threading.Tasks.TplEtwProvider.Log.IsEnabled(EventLevel.Informational, System.Threading.Tasks.TplEtwProvider.Keywords.TasksFlowActivityIds))
76 Contract.Assert((options & EventActivityOptions.Disable) == 0);
78 var currentActivity = m_current.Value;
79 var fullActivityName = NormalizeActivityName(providerName, activityName, task);
81 var etwLog = TplEtwProvider.Log;
84 etwLog.DebugFacilityMessage("OnStartEnter", fullActivityName);
85 etwLog.DebugFacilityMessage("OnStartEnterActivityState", ActivityInfo.LiveActivities(currentActivity));
88 if (currentActivity != null)
90 // Stop activity tracking if we reached the maximum allowed depth
91 if (currentActivity.m_level >= MAX_ACTIVITY_DEPTH)
93 activityId = Guid.Empty;
94 relatedActivityId = Guid.Empty;
96 etwLog.DebugFacilityMessage("OnStartRET", "Fail");
99 // Check for recursion, and force-stop any activities if the activity already started.
100 if ((options & EventActivityOptions.Recursive) == 0)
102 ActivityInfo existingActivity = FindActiveActivity(fullActivityName, currentActivity);
103 if (existingActivity != null)
106 OnStop(providerName, activityName, task, ref activityId);
107 currentActivity = m_current.Value;
112 // Get a unique ID for this activity.
114 if (currentActivity == null)
115 id = Interlocked.Increment(ref m_nextId);
117 id = Interlocked.Increment(ref currentActivity.m_lastChildID);
119 // The previous ID is my 'causer' and becomes my related activity ID
120 relatedActivityId = EventSource.CurrentThreadActivityId;
122 // Add to the list of started but not stopped activities.
123 ActivityInfo newActivity = new ActivityInfo(fullActivityName, id, currentActivity, relatedActivityId, options);
124 m_current.Value = newActivity;
126 // Remember the current ID so we can log it
127 activityId = newActivity.ActivityId;
131 etwLog.DebugFacilityMessage("OnStartRetActivityState", ActivityInfo.LiveActivities(newActivity));
132 etwLog.DebugFacilityMessage1("OnStartRet", activityId.ToString(), relatedActivityId.ToString());
137 /// Called when a work item stops. The activity name = providerName + activityName without 'Stop' suffix.
138 /// It updates m_current variable to track this fact. The Stop event associated with stop should log the ActivityID associated with the event.
140 /// If activity tracing is not on, then activityId and relatedActivityId are not set
142 public void OnStop(string providerName, string activityName, int task, ref Guid activityId)
144 if (m_current == null) // We are not enabled
147 var fullActivityName = NormalizeActivityName(providerName, activityName, task);
149 var etwLog = TplEtwProvider.Log;
152 etwLog.DebugFacilityMessage("OnStopEnter", fullActivityName);
153 etwLog.DebugFacilityMessage("OnStopEnterActivityState", ActivityInfo.LiveActivities(m_current.Value));
156 for (; ; ) // This is a retry loop.
158 ActivityInfo currentActivity = m_current.Value;
159 ActivityInfo newCurrentActivity = null; // if we have seen any live activities (orphans), at he first one we have seen.
161 // Search to find the activity to stop in one pass. This insures that we don't let one mistake
162 // (stopping something that was not started) cause all active starts to be stopped
163 // By first finding the target start to stop we are more robust.
164 ActivityInfo activityToStop = FindActiveActivity(fullActivityName, currentActivity);
166 // ignore stops where we can't find a start because we may have popped them previously.
167 if (activityToStop == null)
169 activityId = Guid.Empty;
172 etwLog.DebugFacilityMessage("OnStopRET", "Fail");
176 activityId = activityToStop.ActivityId;
178 // See if there are any orphans that need to be stopped.
179 ActivityInfo orphan = currentActivity;
180 while (orphan != activityToStop && orphan != null)
182 if (orphan.m_stopped != 0) // Skip dead activities.
184 orphan = orphan.m_creator;
187 if (orphan.CanBeOrphan())
189 // We can't pop anything after we see a valid orphan, remember this for later when we update m_current.
190 if (newCurrentActivity == null)
191 newCurrentActivity = orphan;
195 orphan.m_stopped = 1;
196 Contract.Assert(orphan.m_stopped != 0);
198 orphan = orphan.m_creator;
201 // try to Stop the activity atomically. Other threads may be trying to do this as well.
202 if (Interlocked.CompareExchange(ref activityToStop.m_stopped, 1, 0) == 0)
204 // I succeeded stopping this activity. Now we update our m_current pointer
206 // If I haven't yet determined the new current activity, it is my creator.
207 if (newCurrentActivity == null)
208 newCurrentActivity = activityToStop.m_creator;
210 m_current.Value = newCurrentActivity;
214 etwLog.DebugFacilityMessage("OnStopRetActivityState", ActivityInfo.LiveActivities(newCurrentActivity));
215 etwLog.DebugFacilityMessage("OnStopRet", activityId.ToString());
219 // We failed to stop it. We must have hit a ---- to stop it. Just start over and try again.
224 /// Turns on activity tracking. It is sticky, once on it stays on (---- issues otherwise)
226 [System.Security.SecuritySafeCritical]
229 if (m_current == null)
231 m_current = new AsyncLocal<ActivityInfo>(ActivityChanging);
236 /// An activity tracker is a singleton, this is how you get the one and only instance.
238 public static ActivityTracker Instance { get { return s_activityTrackerInstance; } }
244 /// The current activity ID. Use this to log normal events.
246 private Guid CurrentActivityId { get { return m_current.Value.ActivityId; } }
249 /// Searched for a active (nonstopped) activity with the given name. Returns null if not found.
251 private ActivityInfo FindActiveActivity(string name, ActivityInfo startLocation)
253 var activity = startLocation;
254 while (activity != null)
256 if (name == activity.m_name && activity.m_stopped == 0)
258 activity = activity.m_creator;
264 /// Strip out "Start" or "End" suffix from activity name and add providerName prefix.
265 /// If 'task' it does not end in Start or Stop and Task is non-zero use that as the name of the activity
267 private string NormalizeActivityName(string providerName, string activityName, int task)
269 if (activityName.EndsWith(EventSource.s_ActivityStartSuffix))
270 activityName = activityName.Substring(0, activityName.Length - EventSource.s_ActivityStartSuffix.Length);
271 else if (activityName.EndsWith(EventSource.s_ActivityStopSuffix))
272 activityName = activityName.Substring(0, activityName.Length - EventSource.s_ActivityStopSuffix.Length);
274 activityName = "task" + task.ToString();
276 // We use provider name to distinguish between activities from different providers.
277 return providerName + activityName;
280 // *******************************************************************************
282 /// An ActivityInfo represents a particular activity. It is almost read-only. The only
283 /// fields that change after creation are
284 /// m_lastChildID - used to generate unique IDs for the children activities and for the most part can be ignored.
285 /// m_stopped - indicates that this activity is dead
286 /// This read-only-ness is important because an activity's m_creator chain forms the
287 /// 'Path of creation' for the activity (which is also its unique ID) but is also used as
288 /// the 'list of live parents' which indicate of those ancestors, which are alive (if they
289 /// are not marked dead they are alive).
291 private class ActivityInfo
293 public ActivityInfo(string name, long uniqueId, ActivityInfo creator, Guid activityIDToRestore, EventActivityOptions options)
296 m_eventOptions = options;
298 m_uniqueId = uniqueId;
299 m_level = creator != null ? creator.m_level + 1 : 0;
300 m_activityIdToRestore = activityIDToRestore;
302 // Create a nice GUID that encodes the chain of activities that started this one.
303 CreateActivityPathGuid(out m_guid, out m_activityPathGuidOffset);
306 public Guid ActivityId
314 public static string Path(ActivityInfo activityInfo)
316 if (activityInfo == null)
318 return Path(activityInfo.m_creator) + "/" + activityInfo.m_uniqueId;
321 public override string ToString()
326 return m_name + "(" + Path(this) + dead + ")";
329 public static string LiveActivities(ActivityInfo list)
333 return list.ToString() + ";" + LiveActivities(list.m_creator);
336 public bool CanBeOrphan()
338 if ((m_eventOptions & EventActivityOptions.Detachable) != 0)
345 #region CreateActivityPathGuid
347 /// Logically every activity Path (see Path()) that describes the activities that caused this
348 /// (rooted in an activity that predates activity tracking.
350 /// We wish to encode this path in the Guid to the extent that we can. Many of the paths have
351 /// many small numbers in them and we take advantage of this in the encoding to output as long
352 /// a path in the GUID as possible.
354 /// Because of the possibility of GUID collision, we only use 96 of the 128 bits of the GUID
355 /// for encoding the path. The last 32 bits are a simple checksum (and random number) that
356 /// identifies this as using the convention defined here.
358 /// It returns both the GUID which has the path as well as the offset that points just beyond
359 /// the end of the activity (so it can be appended to). Note that if the end is in a nibble
360 /// (it uses nibbles instead of bytes as the unit of encoding, then it will point at the unfinished
361 /// byte (since the top nibble can't be zero you can determine if this is true by seeing if
362 /// this byte is nonZero. This offset is needed to efficiently create the ID for child activities.
364 [System.Security.SecuritySafeCritical]
365 private unsafe void CreateActivityPathGuid(out Guid idRet, out int activityPathGuidOffset)
367 fixed (Guid* outPtr = &idRet)
369 int activityPathGuidOffsetStart = 0;
370 if (m_creator != null)
372 activityPathGuidOffsetStart = m_creator.m_activityPathGuidOffset;
373 idRet = m_creator.m_guid;
380 appDomainID = System.Threading.Thread.GetDomainID();
382 // We start with the appdomain number to make this unique among appdomains.
383 activityPathGuidOffsetStart = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint)appDomainID);
386 activityPathGuidOffset = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint)m_uniqueId);
389 // If the path does not fit, Make a GUID by incrementing rather than as a path, keeping as much of the path as possible
390 if (12 < activityPathGuidOffset)
391 CreateOverflowGuid(outPtr);
396 /// If we can't fit the activity Path into the GUID we come here. What we do is simply
397 /// generate a 4 byte number (s_nextOverflowId). Then look for an ancestor that has
398 /// sufficient space for this ID. By doing this, we preserve the fact that this activity
399 /// is a child (of unknown depth) from that ancestor.
401 [System.Security.SecurityCritical]
402 private unsafe void CreateOverflowGuid(Guid* outPtr)
404 // Search backwards for an ancestor that has sufficient space to put the ID.
405 for (ActivityInfo ancestor = m_creator; ancestor != null; ancestor = ancestor.m_creator)
407 if (ancestor.m_activityPathGuidOffset <= 10) // we need at least 2 bytes.
409 uint id = unchecked((uint)Interlocked.Increment(ref ancestor.m_lastChildID)); // Get a unique ID
410 // Try to put the ID into the GUID
411 *outPtr = ancestor.m_guid;
412 int endId = AddIdToGuid(outPtr, ancestor.m_activityPathGuidOffset, id, true);
422 /// The encoding for a list of numbers used to make Activity GUIDs. Basically
423 /// we operate on nibbles (which are nice because they show up as hex digits). The
424 /// list is ended with a end nibble (0) and depending on the nibble value (Below)
425 /// the value is either encoded into nibble itself or it can spill over into the
426 /// bytes that follow.
428 enum NumberListCodes : byte
430 End = 0x0, // ends the list. No valid value has this prefix.
431 LastImmediateValue = 0xA,
433 PrefixCode = 0xB, // all the 'long' encodings go here. If the next nibble is MultiByte1-4
434 // than this is a 'overflow' id. Unlike the hierarchical IDs these are
435 // allocated densely but don't tell you anything about nesting. we use
436 // these when we run out of space in the GUID to store the path.
438 MultiByte1 = 0xC, // 1 byte follows. If this Nibble is in the high bits, it the high bits of the number are stored in the low nibble.
439 // commented out because the code does not explicitly reference the names (but they are logically defined).
440 // MultiByte2 = 0xD, // 2 bytes follow (we don't bother with the nibble optimization)
441 // MultiByte3 = 0xE, // 3 bytes follow (we don't bother with the nibble optimization)
442 // MultiByte4 = 0xF, // 4 bytes follow (we don't bother with the nibble optimization)
445 /// Add the activity id 'id' to the output Guid 'outPtr' starting at the offset 'whereToAddId'
446 /// Thus if this number is 6 that is where 'id' will be added. This will return 13 (12
447 /// is the maximum number of bytes that fit in a GUID) if the path did not fit.
448 /// If 'overflow' is true, then the number is encoded as an 'overflow number (which has a
449 /// special (longer prefix) that indicates that this ID is allocated differently
450 [System.Security.SecurityCritical]
451 private static unsafe int AddIdToGuid(Guid* outPtr, int whereToAddId, uint id, bool overflow = false)
453 byte* ptr = (byte*)outPtr;
454 byte* endPtr = ptr + 12;
457 return 13; // 12 means we might exactly fit, 13 means we definately did not fit
459 if (0 < id && id <= (uint)NumberListCodes.LastImmediateValue && !overflow)
460 WriteNibble(ref ptr, endPtr, id);
466 else if (id <= 0xFFFF)
468 else if (id <= 0xFFFFFF)
473 if (endPtr <= ptr + 2) // I need at least 2 bytes
476 // Write out the prefix code nibble and the length nibble
477 WriteNibble(ref ptr, endPtr, (uint)NumberListCodes.PrefixCode);
479 // The rest is the same for overflow and non-overflow case
480 WriteNibble(ref ptr, endPtr, (uint)NumberListCodes.MultiByte1 + (len - 1));
482 // Do we have an odd nibble? If so flush it or use it for the 12 byte case.
483 if (ptr < endPtr && *ptr != 0)
485 // If the value < 4096 we can use the nibble we are otherwise just outputting as padding.
488 // Indicate this is a 1 byte multicode with 4 high order bits in the lower nibble.
489 *ptr = (byte)(((uint)NumberListCodes.MultiByte1 << 4) + (id >> 8));
490 id &= 0xFF; // Now we only want the low order bits.
495 // Write out the bytes.
500 ptr++; // Indicate that we have overflowed
509 // Compute the checksum
510 uint* sumPtr = (uint*)outPtr;
511 // We set the last DWORD the sum of the first 3 DWORDS in the GUID. This
512 sumPtr[3] = sumPtr[0] + sumPtr[1] + sumPtr[2] + 0x599D99AD; // This last number is a random number (it identifies us as us)
514 return (int)(ptr - ((byte*)outPtr));
518 /// Write a single Nible 'value' (must be 0-15) to the byte buffer represented by *ptr.
519 /// Will not go past 'endPtr'. Also it assumes that we never write 0 so we can detect
520 /// whether a nibble has already been written to ptr because it will be nonzero.
521 /// Thus if it is non-zero it adds to the current byte, otherwise it advances and writes
522 /// the new byte (in the high bits) of the next byte.
524 [System.Security.SecurityCritical]
525 private static unsafe void WriteNibble(ref byte* ptr, byte* endPtr, uint value)
527 Contract.Assert(0 <= value && value < 16);
528 Contract.Assert(ptr < endPtr);
531 *ptr++ |= (byte)value;
533 *ptr = (byte)(value << 4);
536 #endregion // CreateGuidForActivityPath
538 readonly internal string m_name; // The name used in the 'start' and 'stop' APIs to help match up
539 readonly long m_uniqueId; // a small number that makes this activity unique among its siblings
540 internal readonly Guid m_guid; // Activity Guid, it is basically an encoding of the Path() (see CreateActivityPathGuid)
541 internal readonly int m_activityPathGuidOffset; // Keeps track of where in m_guid the causality path stops (used to generated child GUIDs)
542 internal readonly int m_level; // current depth of the Path() of the activity (used to keep recursion under control)
543 readonly internal EventActivityOptions m_eventOptions; // Options passed to start.
544 internal long m_lastChildID; // used to create a unique ID for my children activities
545 internal int m_stopped; // This work item has stopped
546 readonly internal ActivityInfo m_creator; // My parent (creator). Forms the Path() for the activity.
547 readonly internal Guid m_activityIdToRestore; // The Guid to restore after a stop.
551 // This callback is used to initialize the m_current AsyncLocal Variable.
552 // Its job is to keep the ETW Activity ID (part of thread local storage) in [....]
553 // with m_current.ActivityID
554 void ActivityChanging(AsyncLocalValueChangedArgs<ActivityInfo> args)
556 ActivityInfo cur = args.CurrentValue;
557 ActivityInfo prev = args.PreviousValue;
559 // Are we popping off a value? (we have a prev, and it creator is cur)
560 // Then check if we should use the GUID at the time of the start event
561 if (prev != null && prev.m_creator == cur)
563 // If the saved activity ID is not the same as the creator activity
564 // that takes precedence (it means someone explicitly did a SetActivityID)
565 // Set it to that and get out
566 if (cur == null || prev.m_activityIdToRestore != cur.ActivityId)
568 EventSource.SetCurrentThreadActivityId(prev.m_activityIdToRestore);
573 // OK we did not have an explicit SetActivityID set. Then we should be
574 // setting the activity to current ActivityInfo. However that activity
575 // might be dead, in which case we should skip it, so we never set
576 // the ID to dead things.
579 // We found a live activity (typically the first time), set it to that.
580 if (cur.m_stopped == 0)
582 EventSource.SetCurrentThreadActivityId(cur.ActivityId);
587 // we can get here if there is no information on our activity stack (everything is dead)
588 // currently we do nothing, as that seems better than setting to Guid.Emtpy.
592 /// Async local variables have the properly that the are automatically copied whenever a task is created and used
593 /// while that task is running. Thus m_current 'flows' to any task that is caused by the current thread that
596 /// This variable points a a linked list that represents all Activities that have started but have not stopped.
598 AsyncLocal<ActivityInfo> m_current;
599 bool m_checkedForEnable;
602 private static ActivityTracker s_activityTrackerInstance = new ActivityTracker();
604 // Used to create unique IDs at the top level. Not used for nested Ids (each activity has its own id generator)
605 static long m_nextId = 0;
606 private const ushort MAX_ACTIVITY_DEPTH = 100; // Limit maximum depth of activities to be tracked at 100.
607 // This will avoid leaking memory in case of activities that are never stopped.
612 #if ES_BUILD_STANDALONE
613 /******************************** SUPPORT *****************************/
615 /// This is supplied by the framework. It is has the semantics that the value is copied to any new Tasks that is created
616 /// by the current task. Thus all causally related code gets this value. Note that reads and writes to this VARIABLE
617 /// (not what it points it) to this does not need to be protected by locks because it is inherently thread local (you always
618 /// only get your thread local copy which means that you never have ----s.
621 [EventSource(Name="Microsoft.Tasks.Nuget")]
622 internal class TplEtwProvider : EventSource
624 public class Keywords
626 public const EventKeywords Debug = (EventKeywords) 1;
629 public static TplEtwProvider Log = new TplEtwProvider();
630 public bool Debug { get { return IsEnabled(EventLevel.Verbose, Keywords.Debug); } }
632 public void DebugFacilityMessage(string Facility, string Message) { WriteEvent(1, Facility, Message); }
633 public void DebugFacilityMessage1(string Facility, string Message, string Arg) { WriteEvent(2, Facility, Message, Arg); }
634 public void SetActivityId(Guid Id) { WriteEvent(3, Id); }
638 #if ES_BUILD_AGAINST_DOTNET_V35 || ES_BUILD_PCL || NO_ASYNC_LOCAL
640 internal sealed class AsyncLocalValueChangedArgs<T>
642 public AsyncLocalValueChangedArgs()
646 public T PreviousValue { get { return default(T); } }
647 public T CurrentValue { get { return default(T); } }
651 internal sealed class AsyncLocal<T>
657 public AsyncLocal(Action<AsyncLocalValueChangedArgs<T>> valueChangedHandler)
666 object obj = null; //
667 return (obj == null) ? default(T) : (T)obj;