2 using System.Diagnostics;
3 using System.Threading;
4 using System.Threading.Tasks;
6 #if !ES_BUILD_AGAINST_DOTNET_V35
7 using Contract = System.Diagnostics.Contracts.Contract;
9 using Contract = Microsoft.Diagnostics.Contracts.Internal.Contract;
12 #if ES_BUILD_STANDALONE
13 namespace Microsoft.Diagnostics.Tracing
15 namespace System.Diagnostics.Tracing
19 /// Tracks activities. This is meant to be a singledon (accessed by the ActivityTracer.Instance static property)
21 /// Logically this is simply holds the m_current variable that holds the async local that holds the current ActivityInfo
22 /// An ActivityInfo is represents a actvity (which knows its creator and thus knows its path).
24 /// Most of the magic is in the async local (it gets copied to new tasks)
26 /// On every start event call OnStart
29 /// Guid relatedActivityID;
30 /// if (OnStart(activityName, out activityID, out relatedActivityID, ForceStop, options))
31 /// // Log Start event with activityID and relatedActivityID
33 /// On every stop event call OnStop
36 /// if (OnStop(activityName, ref activityID ForceStop))
37 /// // Stop event with activityID
39 /// On any normal event log the event with activityTracker.CurrentActivityId
41 internal class ActivityTracker
45 /// Called on work item begins. The activity name = providerName + activityName without 'Start' suffix.
46 /// It updates CurrentActivityId to track.
48 /// It returns true if the Start should be logged, otherwise (if it is illegal recurision) it return false.
50 /// The start event should use as its activity ID the CurrentActivityId AFTER calling this routine and its
51 /// RelatedActivityID the CurrentActivityId BEFORE calling this routine (the creator).
53 /// If activity tracing is not on, then activityId and relatedActivityId are not set
55 public void OnStart(string providerName, string activityName, int task, ref Guid activityId, ref Guid relatedActivityId, EventActivityOptions options)
57 if (m_current == null) // We are not enabled
60 Contract.Assert((options & EventActivityOptions.Disable) == 0);
62 var currentActivity = m_current.Value;
63 var fullActivityName = NormalizeActivityName(providerName, activityName, task);
65 var etwLog = TplEtwProvider.Log;
68 etwLog.DebugFacilityMessage("OnStartEnter", fullActivityName);
69 etwLog.DebugFacilityMessage("OnStartEnterActivityState", ActivityInfo.LiveActivities(currentActivity));
72 if (currentActivity != null)
74 // Stop activity tracking if we reached the maximum allowed depth
75 if (currentActivity.m_level >= MAX_ACTIVITY_DEPTH)
77 activityId = Guid.Empty;
78 relatedActivityId = Guid.Empty;
80 etwLog.DebugFacilityMessage("OnStartRET", "Fail");
83 // Check for recursion, and force-stop any activities if the activity already started.
84 if ((options & EventActivityOptions.Recursive) == 0)
86 ActivityInfo existingActivity = FindActiveActivity(fullActivityName, currentActivity);
87 if (existingActivity != null)
90 OnStop(providerName, activityName, task, ref activityId);
91 currentActivity = m_current.Value;
96 // Get a unique ID for this activity.
98 if (currentActivity == null)
99 id = Interlocked.Increment(ref m_nextId);
101 id = Interlocked.Increment(ref currentActivity.m_lastChildID);
103 // Remember the previous ID so we can log it
104 relatedActivityId = currentActivity != null ? currentActivity.ActivityId : Guid.Empty;
106 // Add to the list of started but not stopped activities.
107 ActivityInfo newActivity = new ActivityInfo(fullActivityName, id, currentActivity, options);
108 m_current.Value = newActivity;
110 // Remember the current ID so we can log it
111 activityId = newActivity.ActivityId;
115 etwLog.DebugFacilityMessage("OnStartRetActivityState", ActivityInfo.LiveActivities(newActivity));
116 etwLog.DebugFacilityMessage1("OnStartRet", activityId.ToString(), relatedActivityId.ToString());
121 /// Called when a work item stops. The activity name = providerName + activityName without 'Stop' suffix.
122 /// It updates CurrentActivityId to track this fact. The Stop event associated with stop should log the ActivityID associated with the event.
124 /// If activity tracing is not on, then activityId and relatedActivityId are not set
126 public void OnStop(string providerName, string activityName, int task, ref Guid activityId)
128 if (m_current == null) // We are not enabled
131 var fullActivityName = NormalizeActivityName(providerName, activityName, task);
133 var etwLog = TplEtwProvider.Log;
136 etwLog.DebugFacilityMessage("OnStopEnter", fullActivityName);
137 etwLog.DebugFacilityMessage("OnStopEnterActivityState", ActivityInfo.LiveActivities(m_current.Value));
140 for (; ;) // This is a retry loop.
142 ActivityInfo currentActivity = m_current.Value;
143 ActivityInfo newCurrentActivity = null; // if we have seen any live activities (orphans), at he first one we have seen.
145 // Search to find the activity to stop in one pass. This insures that we don't let one mistake
146 // (stopping something that was not started) cause all active starts to be stopped
147 // By first finding the target start to stop we are more robust.
148 ActivityInfo activityToStop = FindActiveActivity(fullActivityName, currentActivity);
150 // ignore stops where we can't find a start because we may have popped them previously.
151 if (activityToStop == null)
153 activityId = Guid.Empty;
156 etwLog.DebugFacilityMessage("OnStopRET", "Fail");
160 activityId = activityToStop.ActivityId;
162 // See if there are any orphans that need to be stopped.
163 ActivityInfo orphan = currentActivity;
164 while (orphan != activityToStop && orphan != null)
166 if (orphan.m_stopped != 0) // Skip dead activities.
168 orphan = orphan.m_creator;
171 if (orphan.CanBeOrphan())
173 // We can't pop anything after we see a valid orphan, remember this for later when we update m_current.
174 if (newCurrentActivity == null)
175 newCurrentActivity = orphan;
179 orphan.m_stopped = 1;
180 Contract.Assert(orphan.m_stopped != 0);
182 orphan = orphan.m_creator;
185 // try to Stop the activity atomically. Other threads may be trying to do this as well.
186 if (Interlocked.CompareExchange(ref activityToStop.m_stopped, 1, 0) == 0)
188 // I succeeded stopping this activity. Now we update our m_current pointer
190 // If I haven't yet determined the new current activity, it is my creator.
191 if (newCurrentActivity == null)
192 newCurrentActivity = activityToStop.m_creator;
194 m_current.Value = newCurrentActivity;
198 etwLog.DebugFacilityMessage("OnStopRetActivityState", ActivityInfo.LiveActivities(newCurrentActivity));
199 etwLog.DebugFacilityMessage("OnStopRet", activityId.ToString());
203 // We failed to stop it. We must have hit a ---- to stop it. Just start over and try again.
208 /// Turns on activity tracking. It is sticky, once on it stays on (---- issues otherwise)
210 [System.Security.SecuritySafeCritical]
213 if (m_current == null)
215 m_current = new AsyncLocal<ActivityInfo>(ActivityChanging);
220 /// An activity tracker is a singleton, this is how you get the one and only instance.
222 public static ActivityTracker Instance { get { return s_activityTrackerInstance; } }
228 /// The current activity ID. Use this to log normal events.
230 private Guid CurrentActivityId { get { return m_current.Value.ActivityId; } }
233 /// Searched for a active (nonstopped) activity with the given name. Returns null if not found.
235 private ActivityInfo FindActiveActivity(string name, ActivityInfo startLocation)
237 var activity = startLocation;
238 while (activity != null)
240 if (name == activity.m_name && activity.m_stopped == 0)
242 activity = activity.m_creator;
248 /// Strip out "Start" or "End" suffix from activity name and add providerName prefix.
249 /// If 'task' it does not end in Start or Stop and Task is non-zero use that as the name of the activity
251 private string NormalizeActivityName(string providerName, string activityName, int task)
253 if (activityName.EndsWith(EventSource.s_ActivityStartSuffix))
254 activityName = activityName.Substring(0, activityName.Length - EventSource.s_ActivityStartSuffix.Length);
255 else if (activityName.EndsWith(EventSource.s_ActivityStopSuffix))
256 activityName = activityName.Substring(0, activityName.Length - EventSource.s_ActivityStopSuffix.Length);
258 activityName = "task" + task.ToString();
260 // We use provider name to distinguish between activities from different providers.
261 return providerName + activityName;
264 // *******************************************************************************
266 /// An ActivityInfo repesents a particular activity. It is almost read-only the only
267 /// fields that change after creation are
268 /// m_lastChildID - used to generate unique IDs for the children activities and for the most part can be ignored.
269 /// m_stopped - indicates that this activity is dead
270 /// This read-only ness is important because an activity's m_creator chain forms the
271 /// 'Path of creation' for the activity (which is also its unique ID) but is also used as
272 /// the 'list of live parents' which indicate of those ancestors, which are alive (if they
273 /// are not marked dead they are alive).
275 private class ActivityInfo
277 public ActivityInfo(string name, long uniqueId, ActivityInfo creator, EventActivityOptions options)
280 m_eventOptions = options;
282 m_uniqueId = uniqueId;
283 m_level = creator != null ? creator.m_level + 1 : 0;
285 // Create a nice GUID that encodes the chain of activities that started this one.
286 CreateActivityPathGuid(out m_guid, out m_activityPathGuidOffset);
289 public Guid ActivityId
297 public static string Path(ActivityInfo activityInfo)
299 if (activityInfo == null)
301 return Path(activityInfo.m_creator) + "/" + activityInfo.m_uniqueId;
304 public override string ToString()
309 return m_name + "(" + Path(this) + dead + ")";
312 public static string LiveActivities(ActivityInfo list)
316 return list.ToString() + ";" + LiveActivities(list.m_creator);
319 public bool CanBeOrphan()
321 if ((m_eventOptions & EventActivityOptions.Detachable) != 0)
328 #region CreateActivityPathGuid
330 /// Logically every activity Path (see Path()) that describes the activities that caused this
331 /// (rooted in an activity that predates activity tracking.
333 /// We wish to encode this path in the Guid to the extent that we can. Many of the paths have
334 /// many small numbers in them and we take advatage of this in the encoding to output as long
335 /// a path in the GUID as possible.
337 /// Because of the possiblility of GUID collistion, we only use 96 of the 128 bits of the GUID
338 /// for encoding the path. The last 32 bits are a simple checksum (and random number) that
339 /// identifies this as using the convention defined here.
341 /// It returns both the GUID which has the path as well as the offset that points just beyond
342 /// the end of the activity (so it can be appended to). Note that if the end is in a nibble
343 /// (it uses nibbles instead of bytes as the unit of encoding, then it will point at the unfinished
344 /// byte (since the top nibble can't be zero you can determine if this is true by seeing if
345 /// this byte is nonZero. This offset is needed to efficiently create the ID for child activities.
347 [System.Security.SecuritySafeCritical]
348 private unsafe void CreateActivityPathGuid(out Guid idRet, out int activityPathGuidOffset)
350 fixed (Guid* outPtr = &idRet)
352 int activityPathGuidOffsetStart = 0;
353 if (m_creator != null)
355 activityPathGuidOffsetStart = m_creator.m_activityPathGuidOffset;
356 idRet = m_creator.m_guid;
360 // We start with the appdomain number to make this unique among appdomains.
361 activityPathGuidOffsetStart = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint) System.Threading.Thread.GetDomainID());
364 activityPathGuidOffset = AddIdToGuid(outPtr, activityPathGuidOffsetStart, (uint) m_uniqueId);
367 // If the path does not fit, Make a GUID by incrementing rather than as a path, keeping as much of the path as possible
368 if (12 < activityPathGuidOffset)
369 CreateOverflowGuid(outPtr);
374 /// If we can't fit the activity Path into the GUID we come here. What we do is simply
375 /// generate a 4 byte number (s_nextOverflowId). Then look for an anscesor that has
376 /// sufficient space for this ID. By doing this, we preserve the fact that this activity
377 /// is a child (of unknown depth) from that ancestor.
379 [System.Security.SecurityCritical]
380 private unsafe void CreateOverflowGuid(Guid* outPtr)
382 // Seach backwards for an ancestor that has sufficient space to put the ID.
383 for(ActivityInfo ancestor = m_creator; ancestor != null; ancestor = ancestor.m_creator)
385 if (ancestor.m_activityPathGuidOffset <= 10) // we need at least 2 bytes.
387 uint id = (uint) Interlocked.Increment(ref ancestor.m_lastChildID); // Get a unique ID
388 // Try to put the ID into the GUID
389 *outPtr = ancestor.m_guid;
390 int endId = AddIdToGuid(outPtr, ancestor.m_activityPathGuidOffset, id, true);
400 /// The encoding for a list of numbers used to make Activity Guids. Basically
401 /// we operate on nibbles (which are nice becase they show up as hex digits). The
402 /// list is ended with a end nibble (0) and depending on the nibble value (Below)
403 /// the value is either encoded into nibble itself or it can spill over into the
404 /// bytes that follow.
406 enum NumberListCodes : byte
408 End = 0x0, // ends the list. No valid value has this prefix.
409 LastImmediateValue = 0xA,
411 PrefixCode = 0xB, // all the 'long' encodings go here. If the next nibble is MultiByte1-4
412 // than this is a 'overflow' id. Unlike the hierarchitcal IDs these are
413 // allocated densly but don't tell you anything about nesting. we use
414 // these when we run out of space in the GUID to store the path.
416 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.
417 // commented out because the code does not explicitly reference the names (but they are logically defined).
418 // MultiByte2 = 0xD, // 2 bytes follow (we don't bother with the nibble optimzation)
419 // MultiByte3 = 0xE, // 3 bytes follow (we don't bother with the nibble optimzation)
420 // MultiByte4 = 0xF, // 4 bytes follow (we don't bother with the nibble optimzation)
423 /// Add the acivity id 'id' to the output Guid 'outPtr' starting at the offset 'whereToAddId'
424 /// Thus if this number is 6 that is where 'id' will be added. This will return 13 (12
425 /// is the maximum number of bytes that fit in a GUID) if the path did not fit.
426 /// If 'overflow' is true, then the number is encoded as an 'overflow number (which has a
427 /// special (longer prefix) that indicates that this ID is allocated differently
428 [System.Security.SecurityCritical]
429 private static unsafe int AddIdToGuid(Guid* outPtr, int whereToAddId, uint id, bool overflow = false)
431 byte* ptr = (byte*)outPtr;
432 byte* endPtr = ptr + 12;
435 return 13; // 12 means we might exactly fit, 13 means we definately did not fit
437 if (0 < id && id <= (uint)NumberListCodes.LastImmediateValue && !overflow)
438 WriteNibble(ref ptr, endPtr, id);
444 else if (id <= 0xFFFF)
446 else if (id <= 0xFFFFFF)
451 if (endPtr <= ptr + 2) // I need at least 2 bytes
454 // Write out the prefix code nibble and the length nibble
455 WriteNibble(ref ptr, endPtr, (uint) NumberListCodes.PrefixCode);
457 // The rest is the same for overflow and non-overflow case
458 WriteNibble(ref ptr, endPtr, (uint)NumberListCodes.MultiByte1 + (len - 1));
460 // Do we have an odd nibble? If so flush it or use it for the 12 byte case.
461 if (ptr < endPtr && *ptr != 0)
463 // If the value < 4096 we can use the nibble we are otherwise just outputing as padding.
466 // Indicate this is a 1 byte multicode with 4 high order bits in the lower nibble.
467 *ptr = (byte)(((uint)NumberListCodes.MultiByte1 << 4) + (id >> 8));
468 id &= 0xFF; // Now we only want the low order bits.
473 // Write out the bytes.
478 ptr++; // Indicate that we have overflowed
487 // Compute the checksum
488 uint* sumPtr = (uint*)outPtr;
489 // We set the last DWORD the sum of the first 3 DWORDS in the GUID. This
490 sumPtr[3] = sumPtr[0] + sumPtr[1] + sumPtr[2] + 0x599D99AD; // This last number is a random number (it identifies us as us)
492 return (int)(ptr - ((byte*)outPtr));
496 /// Write a single Nible 'value' (must be 0-15) to the byte buffer represented by *ptr.
497 /// Will not go past 'endPtr'. Also it assumes that we never write 0 so we can detect
498 /// whether a nibble has already been written to ptr because it will be nonzero.
499 /// Thus if it is non-zero it adds to the current byte, otherwise it advances and writes
500 /// the new byte (in the high bits) of the next byte.
502 [System.Security.SecurityCritical]
503 private static unsafe void WriteNibble(ref byte* ptr, byte* endPtr, uint value)
505 Contract.Assert(0 <= value && value < 16);
506 Contract.Assert(ptr < endPtr);
509 *ptr++ |= (byte)value;
511 *ptr = (byte)(value << 4);
514 #endregion // CreateGuidForActivityPath
516 readonly internal string m_name; // The name used in the 'start' and 'stop' APIs to help match up
517 readonly long m_uniqueId; // a small number that makes this activity unique among its siblings
518 internal readonly Guid m_guid; // Activity Guid, it is bascially an encoding of the Path() (see CreateActivityPathGuid)
519 internal readonly int m_activityPathGuidOffset; // Keeps track of where in m_guid the causality path stops (used to generated child GUIDs)
520 internal readonly int m_level; // current depth of the Path() of the activity (used to keep recursion under control)
521 readonly internal EventActivityOptions m_eventOptions; // Options passed to start.
522 internal long m_lastChildID; // used to create a unique ID for my children activities
523 internal int m_stopped; // This work item has stopped
524 readonly internal ActivityInfo m_creator; // My parent (creator). Forms the Path() for the activity.
528 // This callback is used to initialize the m_current AsyncLocal Variable.
529 // Its job is to keep the ETW Activity ID (part of thread local storage) in [....]
530 // with m_current.ActivityID
531 void ActivityChanging(AsyncLocalValueChangedArgs<ActivityInfo> args)
533 if (args.PreviousValue == args.CurrentValue)
536 if (args.CurrentValue != null)
538 // Allow subsequent activities inside this thread to automatically get the current activity ID.
539 EventSource.SetCurrentThreadActivityId(args.CurrentValue.ActivityId);
542 EventSource.SetCurrentThreadActivityId(Guid.Empty);
546 /// Async local variables have the propery that the are automatically copied whenever a task is created and used
547 /// while that task is running. Thus m_current 'flows' to any task that is caused by the current thread that
550 /// This variable points a a linked list that represents all Activities that have started but have not stopped.
552 AsyncLocal<ActivityInfo> m_current;
555 private static ActivityTracker s_activityTrackerInstance = new ActivityTracker();
557 // Used to create unique IDs at the top level. Not used for nested Ids (each activity has its own id generator)
558 static long m_nextId = 0;
559 private const ushort MAX_ACTIVITY_DEPTH = 100; // Limit maximum depth of activities to be tracked at 100.
560 // This will avoid leaking memory in case of activities that are never stopped.