// 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.
// =+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+=+
//
//
//
// EventSource for TPL.
//
// =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
using System;
using System.Collections.Generic;
using System.Text;
using System.Security;
using System.Runtime.CompilerServices;
namespace System.Threading.Tasks
{
using System.Diagnostics.Tracing;
/// Provides an event source for tracing TPL information.
[EventSource(
Name = "System.Threading.Tasks.TplEventSource",
Guid = "2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5",
LocalizationResources = System.CoreLib.Name)]
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;
///
/// 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 TplEtwProvider Log = new TplEtwProvider();
/// Prevent external instantiation. All logging should go through the Log instance.
private TplEtwProvider() { }
/// 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;
///
/// 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 likley 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)
{
// 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[1].Size = sizeof(int);
eventPayload[1].DataPointer = ((IntPtr) (&OriginatingTaskID));
eventPayload[2].Size = sizeof(int);
eventPayload[2].DataPointer = ((IntPtr) (&TaskID));
eventPayload[3].Size = sizeof(int);
eventPayload[3].DataPointer = ((IntPtr) (&CreatingTaskID));
eventPayload[4].Size = sizeof(int);
eventPayload[4].DataPointer = ((IntPtr) (&TaskCreationOptions));
eventPayload[5].Size = sizeof(int);
eventPayload[5].DataPointer = ((IntPtr) (&appDomain));
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];
Int32 isExceptionalInt = IsExceptional ? 1 : 0;
eventPayload[0].Size = sizeof(int);
eventPayload[0].DataPointer = ((IntPtr) (&OriginatingTaskSchedulerID));
eventPayload[1].Size = sizeof(int);
eventPayload[1].DataPointer = ((IntPtr) (&OriginatingTaskID));
eventPayload[2].Size = sizeof(int);
eventPayload[2].DataPointer = ((IntPtr) (&TaskID));
eventPayload[3].Size = sizeof(int);
eventPayload[3].DataPointer = ((IntPtr) (&isExceptionalInt));
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[1].Size = sizeof(int);
eventPayload[1].DataPointer = ((IntPtr)(&OriginatingTaskID));
eventPayload[2].Size = sizeof(int);
eventPayload[2].DataPointer = ((IntPtr)(&TaskID));
eventPayload[3].Size = sizeof(int);
eventPayload[3].DataPointer = ((IntPtr)(&Behavior));
eventPayload[4].Size = sizeof(int);
eventPayload[4].DataPointer = ((IntPtr)(&ContinueWithTaskID));
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 the work (method) associated with a TaskWaitEnd completes
///
/// The scheduler ID.
/// The task ID.
/// 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 the work (method) associated with a TaskWaitEnd completes
///
/// The scheduler ID.
/// The task ID.
/// 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.
/// The activityId for the continuation.
[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[1].Size = sizeof(int);
eventPayload[1].DataPointer = ((IntPtr) (&OriginatingTaskID));
eventPayload[2].Size = sizeof(int);
eventPayload[2].DataPointer = ((IntPtr) (&ContinuwWithTaskId));
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[1].Size = ((OperationName.Length + 1) * 2);
eventPayload[1].DataPointer = ((IntPtr) operationNamePtr);
eventPayload[2].Size = sizeof(long);
eventPayload[2].DataPointer = ((IntPtr) (&RelatedContext));
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); // optmized 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); // optmized 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); // optmized 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));
WriteEventCore(TRACESYNCHRONOUSWORKSTOP_ID, 1, eventPayload);
}
}
}
[NonEvent]
unsafe public void RunningContinuation(int TaskID, object Object) { RunningContinuation(TaskID, (long) *((void**) JitHelpers.UnsafeCastToStackPointer(ref Object))); }
[Event(20, Keywords = Keywords.Debug)]
private void RunningContinuation(int TaskID, long Object)
{
if (Debug)
WriteEvent(20, TaskID, Object);
}
[NonEvent]
unsafe public void RunningContinuationList(int TaskID, int Index, object Object) { RunningContinuationList(TaskID, Index, (long) *((void**) JitHelpers.UnsafeCastToStackPointer(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);
}
///
/// 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 unlikley to collide
uint pid = EventSource.s_currentPid;
int appDomainID = System.Threading.Thread.GetDomainID();
return new Guid(taskID,
(short) appDomainID , (short) (appDomainID >> 16),
(byte)pid, (byte)(pid >> 8), (byte)(pid >> 16), (byte)(pid >> 24),
0xff, 0xdc, 0xd7, 0xb5);
}
}
}