// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. using System.Runtime.CompilerServices; using System.Diagnostics.Tracing; using Internal.Runtime.CompilerServices; namespace System.Threading.Tasks { /// Provides an event source for tracing TPL information. [EventSource( Name = "System.Threading.Tasks.TplEventSource", Guid = "2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5" #if CORECLR ,LocalizationResources = "FxResources.System.Private.CoreLib.SR" #endif )] internal sealed class TplEtwProvider : EventSource { /// Used to determine if tasks should generate Activity IDs for themselves internal bool TasksSetActivityIds; // This keyword is set internal bool Debug; private bool DebugActivityId; private const int DefaultAppDomainID = 1; /// /// Get callbacks when the ETW sends us commands` /// protected override void OnEventCommand(EventCommandEventArgs command) { // To get the AsyncCausality events, we need to inform the AsyncCausalityTracer if (command.Command == EventCommand.Enable) AsyncCausalityTracer.EnableToETW(true); else if (command.Command == EventCommand.Disable) AsyncCausalityTracer.EnableToETW(false); if (IsEnabled(EventLevel.Informational, Keywords.TasksFlowActivityIds)) ActivityTracker.Instance.Enable(); else TasksSetActivityIds = IsEnabled(EventLevel.Informational, Keywords.TasksSetActivityIds); Debug = IsEnabled(EventLevel.Informational, Keywords.Debug); DebugActivityId = IsEnabled(EventLevel.Informational, Keywords.DebugActivityId); } /// /// Defines the singleton instance for the TPL ETW provider. /// The TPL Event provider GUID is {2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5}. /// public static readonly TplEtwProvider Log = new TplEtwProvider(); /// Prevent external instantiation. All logging should go through the Log instance. private TplEtwProvider() : base(new Guid(0x2e5dba47, 0xa3d2, 0x4d16, 0x8e, 0xe0, 0x66, 0x71, 0xff, 0xdc, 0xd7, 0xb5), "System.Threading.Tasks.TplEventSource") { } /// Configured behavior of a task wait operation. public enum TaskWaitBehavior : int { /// A synchronous wait. Synchronous = 1, /// An asynchronous await. Asynchronous = 2 } /// ETW tasks that have start/stop events. public class Tasks // this name is important for EventSource { /// A parallel loop. public const EventTask Loop = (EventTask)1; /// A parallel invoke. public const EventTask Invoke = (EventTask)2; /// Executing a Task. public const EventTask TaskExecute = (EventTask)3; /// Waiting on a Task. public const EventTask TaskWait = (EventTask)4; /// A fork/join task within a loop or invoke. public const EventTask ForkJoin = (EventTask)5; /// A task is scheduled to execute. public const EventTask TaskScheduled = (EventTask)6; /// An await task continuation is scheduled to execute. public const EventTask AwaitTaskContinuationScheduled = (EventTask)7; /// AsyncCausalityFunctionality. public const EventTask TraceOperation = (EventTask)8; public const EventTask TraceSynchronousWork = (EventTask)9; } public class Keywords // thisname is important for EventSource { /// /// Only the most basic information about the workings of the task library /// This sets activity IDS and logs when tasks are schedules (or waits begin) /// But are otherwise silent /// public const EventKeywords TaskTransfer = (EventKeywords)1; /// /// TaskTranser events plus events when tasks start and stop /// public const EventKeywords Tasks = (EventKeywords)2; /// /// Events associted with the higher level parallel APIs /// public const EventKeywords Parallel = (EventKeywords)4; /// /// These are relatively verbose events that effectively just redirect /// the windows AsyncCausalityTracer to ETW /// public const EventKeywords AsyncCausalityOperation = (EventKeywords)8; public const EventKeywords AsyncCausalityRelation = (EventKeywords)0x10; public const EventKeywords AsyncCausalitySynchronousWork = (EventKeywords)0x20; /// /// Emit the stops as well as the schedule/start events /// public const EventKeywords TaskStops = (EventKeywords)0x40; /// /// TasksFlowActivityIds indicate that activity ID flow from one task /// to any task created by it. /// public const EventKeywords TasksFlowActivityIds = (EventKeywords)0x80; /// /// Events related to the happenings of async methods. /// public const EventKeywords AsyncMethod = (EventKeywords)0x100; /// /// TasksSetActivityIds will cause the task operations to set Activity Ids /// This option is incompatible with TasksFlowActivityIds flow is ignored /// if that keyword is set. This option is likely to be removed in the future /// public const EventKeywords TasksSetActivityIds = (EventKeywords)0x10000; /// /// Relatively Verbose logging meant for debugging the Task library itself. Will probably be removed in the future /// public const EventKeywords Debug = (EventKeywords)0x20000; /// /// Relatively Verbose logging meant for debugging the Task library itself. Will probably be removed in the future /// public const EventKeywords DebugActivityId = (EventKeywords)0x40000; } /// Enabled for all keywords. private const EventKeywords ALL_KEYWORDS = (EventKeywords)(-1); //----------------------------------------------------------------------------------- // // TPL Event IDs (must be unique) // /// The beginning of a parallel loop. private const int PARALLELLOOPBEGIN_ID = 1; /// The ending of a parallel loop. private const int PARALLELLOOPEND_ID = 2; /// The beginning of a parallel invoke. private const int PARALLELINVOKEBEGIN_ID = 3; /// The ending of a parallel invoke. private const int PARALLELINVOKEEND_ID = 4; /// A task entering a fork/join construct. private const int PARALLELFORK_ID = 5; /// A task leaving a fork/join construct. private const int PARALLELJOIN_ID = 6; /// A task is scheduled to a task scheduler. private const int TASKSCHEDULED_ID = 7; /// A task is about to execute. private const int TASKSTARTED_ID = 8; /// A task has finished executing. private const int TASKCOMPLETED_ID = 9; /// A wait on a task is beginning. private const int TASKWAITBEGIN_ID = 10; /// A wait on a task is ending. private const int TASKWAITEND_ID = 11; /// A continuation of a task is scheduled. private const int AWAITTASKCONTINUATIONSCHEDULED_ID = 12; /// A continuation of a taskWaitEnd is complete private const int TASKWAITCONTINUATIONCOMPLETE_ID = 13; /// A continuation of a taskWaitEnd is complete private const int TASKWAITCONTINUATIONSTARTED_ID = 19; private const int TRACEOPERATIONSTART_ID = 14; private const int TRACEOPERATIONSTOP_ID = 15; private const int TRACEOPERATIONRELATION_ID = 16; private const int TRACESYNCHRONOUSWORKSTART_ID = 17; private const int TRACESYNCHRONOUSWORKSTOP_ID = 18; //----------------------------------------------------------------------------------- // // Task Events // // These are all verbose events, so we need to call IsEnabled(EventLevel.Verbose, ALL_KEYWORDS) // call. However since the IsEnabled(l,k) call is more expensive than IsEnabled(), we only want // to incur this cost when instrumentation is enabled. So the Task codepaths that call these // event functions still do the check for IsEnabled() #region TaskScheduled /// /// Fired when a task is queued to a TaskScheduler. /// /// The scheduler ID. /// The task ID. /// The task ID. /// The task ID /// The options used to create the task. [Event(TASKSCHEDULED_ID, Task = Tasks.TaskScheduled, Version = 1, Opcode = EventOpcode.Send, Level = EventLevel.Informational, Keywords = Keywords.TaskTransfer | Keywords.Tasks)] public void TaskScheduled( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int TaskID, int CreatingTaskID, int TaskCreationOptions, int appDomain = DefaultAppDomainID) { // IsEnabled() call is an inlined quick check that makes this very fast when provider is off if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.TaskTransfer | Keywords.Tasks)) { unsafe { EventData* eventPayload = stackalloc EventData[6]; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&OriginatingTaskSchedulerID)); eventPayload[0].Reserved = 0; eventPayload[1].Size = sizeof(int); eventPayload[1].DataPointer = ((IntPtr)(&OriginatingTaskID)); eventPayload[1].Reserved = 0; eventPayload[2].Size = sizeof(int); eventPayload[2].DataPointer = ((IntPtr)(&TaskID)); eventPayload[2].Reserved = 0; eventPayload[3].Size = sizeof(int); eventPayload[3].DataPointer = ((IntPtr)(&CreatingTaskID)); eventPayload[3].Reserved = 0; eventPayload[4].Size = sizeof(int); eventPayload[4].DataPointer = ((IntPtr)(&TaskCreationOptions)); eventPayload[4].Reserved = 0; eventPayload[5].Size = sizeof(int); eventPayload[5].DataPointer = ((IntPtr)(&appDomain)); eventPayload[5].Reserved = 0; if (TasksSetActivityIds) { Guid childActivityId = CreateGuidForTaskID(TaskID); WriteEventWithRelatedActivityIdCore(TASKSCHEDULED_ID, &childActivityId, 6, eventPayload); } else WriteEventCore(TASKSCHEDULED_ID, 6, eventPayload); } } } #endregion #region TaskStarted /// /// Fired just before a task actually starts executing. /// /// The scheduler ID. /// The task ID. /// The task ID. [Event(TASKSTARTED_ID, Level = EventLevel.Informational, Keywords = Keywords.Tasks)] public void TaskStarted( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int TaskID) { if (IsEnabled(EventLevel.Informational, Keywords.Tasks)) WriteEvent(TASKSTARTED_ID, OriginatingTaskSchedulerID, OriginatingTaskID, TaskID); } #endregion #region TaskCompleted /// /// Fired right after a task finished executing. /// /// The scheduler ID. /// The task ID. /// The task ID. /// Whether the task completed due to an error. [Event(TASKCOMPLETED_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.TaskStops)] public void TaskCompleted( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int TaskID, bool IsExceptional) { if (IsEnabled(EventLevel.Informational, Keywords.Tasks)) { unsafe { EventData* eventPayload = stackalloc EventData[4]; int isExceptionalInt = IsExceptional ? 1 : 0; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&OriginatingTaskSchedulerID)); eventPayload[0].Reserved = 0; eventPayload[1].Size = sizeof(int); eventPayload[1].DataPointer = ((IntPtr)(&OriginatingTaskID)); eventPayload[1].Reserved = 0; eventPayload[2].Size = sizeof(int); eventPayload[2].DataPointer = ((IntPtr)(&TaskID)); eventPayload[2].Reserved = 0; eventPayload[3].Size = sizeof(int); eventPayload[3].DataPointer = ((IntPtr)(&isExceptionalInt)); eventPayload[3].Reserved = 0; WriteEventCore(TASKCOMPLETED_ID, 4, eventPayload); } } } #endregion #region TaskWaitBegin /// /// Fired when starting to wait for a taks's completion explicitly or implicitly. /// /// The scheduler ID. /// The task ID. /// The task ID. /// Configured behavior for the wait. /// /// If known, if 'TaskID' has a 'continueWith' task, mention give its ID here. /// 0 means unknown. This allows better visualization of the common sequential chaining case. /// [Event(TASKWAITBEGIN_ID, Version = 3, Task = TplEtwProvider.Tasks.TaskWait, Opcode = EventOpcode.Send, Level = EventLevel.Informational, Keywords = Keywords.TaskTransfer | Keywords.Tasks)] public void TaskWaitBegin( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int TaskID, TaskWaitBehavior Behavior, int ContinueWithTaskID) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.TaskTransfer | Keywords.Tasks)) { unsafe { EventData* eventPayload = stackalloc EventData[5]; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&OriginatingTaskSchedulerID)); eventPayload[0].Reserved = 0; eventPayload[1].Size = sizeof(int); eventPayload[1].DataPointer = ((IntPtr)(&OriginatingTaskID)); eventPayload[1].Reserved = 0; eventPayload[2].Size = sizeof(int); eventPayload[2].DataPointer = ((IntPtr)(&TaskID)); eventPayload[2].Reserved = 0; eventPayload[3].Size = sizeof(int); eventPayload[3].DataPointer = ((IntPtr)(&Behavior)); eventPayload[3].Reserved = 0; eventPayload[4].Size = sizeof(int); eventPayload[4].DataPointer = ((IntPtr)(&ContinueWithTaskID)); eventPayload[4].Reserved = 0; if (TasksSetActivityIds) { Guid childActivityId = CreateGuidForTaskID(TaskID); WriteEventWithRelatedActivityIdCore(TASKWAITBEGIN_ID, &childActivityId, 5, eventPayload); } else { WriteEventCore(TASKWAITBEGIN_ID, 5, eventPayload); } } } } #endregion /// /// Fired when the wait for a tasks completion returns. /// /// The scheduler ID. /// The task ID. /// The task ID. [Event(TASKWAITEND_ID, Level = EventLevel.Verbose, Keywords = Keywords.Tasks)] public void TaskWaitEnd( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int TaskID) { // Log an event if indicated. if (IsEnabled() && IsEnabled(EventLevel.Verbose, Keywords.Tasks)) WriteEvent(TASKWAITEND_ID, OriginatingTaskSchedulerID, OriginatingTaskID, TaskID); } /// /// Fired when the work (method) associated with a TaskWaitEnd completes /// /// The task ID. [Event(TASKWAITCONTINUATIONCOMPLETE_ID, Level = EventLevel.Verbose, Keywords = Keywords.TaskStops)] public void TaskWaitContinuationComplete(int TaskID) { // Log an event if indicated. if (IsEnabled() && IsEnabled(EventLevel.Verbose, Keywords.Tasks)) WriteEvent(TASKWAITCONTINUATIONCOMPLETE_ID, TaskID); } /// /// Fired when the work (method) associated with a TaskWaitEnd completes /// /// The task ID. [Event(TASKWAITCONTINUATIONSTARTED_ID, Level = EventLevel.Verbose, Keywords = Keywords.TaskStops)] public void TaskWaitContinuationStarted(int TaskID) { // Log an event if indicated. if (IsEnabled() && IsEnabled(EventLevel.Verbose, Keywords.Tasks)) WriteEvent(TASKWAITCONTINUATIONSTARTED_ID, TaskID); } /// /// Fired when the an asynchronous continuation for a task is scheduled /// /// The scheduler ID. /// The task ID. [Event(AWAITTASKCONTINUATIONSCHEDULED_ID, Task = Tasks.AwaitTaskContinuationScheduled, Opcode = EventOpcode.Send, Level = EventLevel.Informational, Keywords = Keywords.TaskTransfer | Keywords.Tasks)] public void AwaitTaskContinuationScheduled( int OriginatingTaskSchedulerID, int OriginatingTaskID, // PFX_COMMON_EVENT_HEADER int ContinuwWithTaskId) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.TaskTransfer | Keywords.Tasks)) { unsafe { EventData* eventPayload = stackalloc EventData[3]; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&OriginatingTaskSchedulerID)); eventPayload[0].Reserved = 0; eventPayload[1].Size = sizeof(int); eventPayload[1].DataPointer = ((IntPtr)(&OriginatingTaskID)); eventPayload[1].Reserved = 0; eventPayload[2].Size = sizeof(int); eventPayload[2].DataPointer = ((IntPtr)(&ContinuwWithTaskId)); eventPayload[2].Reserved = 0; if (TasksSetActivityIds) { Guid continuationActivityId = CreateGuidForTaskID(ContinuwWithTaskId); WriteEventWithRelatedActivityIdCore(AWAITTASKCONTINUATIONSCHEDULED_ID, &continuationActivityId, 3, eventPayload); } else WriteEventCore(AWAITTASKCONTINUATIONSCHEDULED_ID, 3, eventPayload); } } } [Event(TRACEOPERATIONSTART_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.AsyncCausalityOperation)] public void TraceOperationBegin(int TaskID, string OperationName, long RelatedContext) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.AsyncCausalityOperation)) { unsafe { fixed (char* operationNamePtr = OperationName) { EventData* eventPayload = stackalloc EventData[3]; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&TaskID)); eventPayload[0].Reserved = 0; eventPayload[1].Size = ((OperationName.Length + 1) * 2); eventPayload[1].DataPointer = ((IntPtr)operationNamePtr); eventPayload[1].Reserved = 0; eventPayload[2].Size = sizeof(long); eventPayload[2].DataPointer = ((IntPtr)(&RelatedContext)); eventPayload[2].Reserved = 0; WriteEventCore(TRACEOPERATIONSTART_ID, 3, eventPayload); } } } } [Event(TRACEOPERATIONRELATION_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.AsyncCausalityRelation)] public void TraceOperationRelation(int TaskID, CausalityRelation Relation) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.AsyncCausalityRelation)) WriteEvent(TRACEOPERATIONRELATION_ID, TaskID, (int)Relation); // optimized overload for this exists } [Event(TRACEOPERATIONSTOP_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.AsyncCausalityOperation)] public void TraceOperationEnd(int TaskID, AsyncCausalityStatus Status) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.AsyncCausalityOperation)) WriteEvent(TRACEOPERATIONSTOP_ID, TaskID, (int)Status); // optimized overload for this exists } [Event(TRACESYNCHRONOUSWORKSTART_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.AsyncCausalitySynchronousWork)] public void TraceSynchronousWorkBegin(int TaskID, CausalitySynchronousWork Work) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.AsyncCausalitySynchronousWork)) WriteEvent(TRACESYNCHRONOUSWORKSTART_ID, TaskID, (int)Work); // optimized overload for this exists } [Event(TRACESYNCHRONOUSWORKSTOP_ID, Version = 1, Level = EventLevel.Informational, Keywords = Keywords.AsyncCausalitySynchronousWork)] public void TraceSynchronousWorkEnd(CausalitySynchronousWork Work) { if (IsEnabled() && IsEnabled(EventLevel.Informational, Keywords.AsyncCausalitySynchronousWork)) { unsafe { EventData* eventPayload = stackalloc EventData[1]; eventPayload[0].Size = sizeof(int); eventPayload[0].DataPointer = ((IntPtr)(&Work)); eventPayload[0].Reserved = 0; WriteEventCore(TRACESYNCHRONOUSWORKSTOP_ID, 1, eventPayload); } } } [NonEvent] public unsafe void RunningContinuation(int TaskID, object Object) { RunningContinuation(TaskID, (long)*((void**)Unsafe.AsPointer(ref Object))); } [Event(20, Keywords = Keywords.Debug)] private void RunningContinuation(int TaskID, long Object) { if (Debug) WriteEvent(20, TaskID, Object); } [NonEvent] public unsafe void RunningContinuationList(int TaskID, int Index, object Object) { RunningContinuationList(TaskID, Index, (long)*((void**)Unsafe.AsPointer(ref Object))); } [Event(21, Keywords = Keywords.Debug)] public void RunningContinuationList(int TaskID, int Index, long Object) { if (Debug) WriteEvent(21, TaskID, Index, Object); } [Event(23, Keywords = Keywords.Debug)] public void DebugFacilityMessage(string Facility, string Message) { WriteEvent(23, Facility, Message); } [Event(24, Keywords = Keywords.Debug)] public void DebugFacilityMessage1(string Facility, string Message, string Value1) { WriteEvent(24, Facility, Message, Value1); } [Event(25, Keywords = Keywords.DebugActivityId)] public void SetActivityId(Guid NewId) { if (DebugActivityId) WriteEvent(25, NewId); } [Event(26, Keywords = Keywords.Debug)] public void NewID(int TaskID) { if (Debug) WriteEvent(26, TaskID); } [NonEvent] public void IncompleteAsyncMethod(IAsyncStateMachineBox stateMachineBox) { System.Diagnostics.Debug.Assert(stateMachineBox != null); if (IsEnabled(EventLevel.Warning, Keywords.AsyncMethod)) { IAsyncStateMachine stateMachine = stateMachineBox.GetStateMachineObject(); if (stateMachine != null) { string description = AsyncMethodBuilderCore.GetAsyncStateMachineDescription(stateMachine); IncompleteAsyncMethod(description); } } } [Event(27, Level = EventLevel.Warning, Keywords = Keywords.AsyncMethod)] private void IncompleteAsyncMethod(string stateMachineDescription) => WriteEvent(27, stateMachineDescription); /// /// Activity IDs are GUIDS but task IDS are integers (and are not unique across appdomains /// This routine creates a process wide unique GUID given a task ID /// internal static Guid CreateGuidForTaskID(int taskID) { // The thread pool generated a process wide unique GUID from a task GUID by // using the taskGuid, the appdomain ID, and 8 bytes of 'randomization' chosen by // using the last 8 bytes as the provider GUID for this provider. // These were generated by CreateGuid, and are reasonably random (and thus unlikely to collide uint pid = EventSource.s_currentPid; return new Guid(taskID, (short)DefaultAppDomainID, (short)(DefaultAppDomainID >> 16), (byte)pid, (byte)(pid >> 8), (byte)(pid >> 16), (byte)(pid >> 24), 0xff, 0xdc, 0xd7, 0xb5); } } }