How do I listen to TPL TaskStarted/TaskCompleted ETW events

Question

I am interested in listening to ETW (event tracing for Windows) TPL events, in particular I'd like to know when a Task starts and when it stops.

Here's a sample program I've used for testing:

   using System;
   using System.Collections.Generic;
   using System.Diagnostics.Tracing;
   using System.Linq;
   using System.Text;
   using System.Threading;
   using System.Threading.Tasks;

   namespace ConsoleApplication10
   {
      class Listener : EventListener
      {
         private static readonly Guid tplGuid = new Guid("2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5");

         protected override void OnEventSourceCreated(EventSource eventSource)
         {
            Console.WriteLine("Got guid: " + eventSource.Guid);
            EnableEvents(eventSource, EventLevel.LogAlways);
         }

         protected override void OnEventWritten(EventWrittenEventArgs eventData)
         {
            Console.WriteLine("Event: " + eventData.EventId);
         }
      }

      class Program
      {
         static void Main(string[] args)
         {
            using (var listener = new Listener())
            {
               Action doIt = null;
               doIt = () =>
               {
                  Thread.Sleep(1000);
                  Console.Write('.');
                  Task.Run(doIt);
               };
               Task.Run(doIt);

               Parallel.Invoke(() => Console.WriteLine("invoke"));

               Console.Read();
            }
         }
      }
   }

Sample output is as follows on my machine:

Got guid: 8e9f5090-2d75-4d03-8a81-e5afbf85daf1
Got guid: 2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5
Event: 3
invoke
Event: 4
.......

So the Invoke method causes an event to fire, yet the Tasks fire none. Looking at the Task source (e.g. reference source) the code appears no different from how the Parallel.Invoke event fires.

What is wrong with the above, or, how do I listen to TaskStarted and TaskCompleted events (or any Task related event for that matter)?

Answer 1

Your question challanged me to look into ETW (which I've been wanting to look into for a while). I was able to capture "task start" and "task end" using Microsoft.Diagnostics.Tracing.TraceEvent NuGet library with the simple following code:

private static void Main(string[] args)
{
    Task.Run(() =>
    {
        using (var session = new TraceEventSession("TplCaptureSession"))
        {
            session.EnableProvider(new Guid("2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5"),
                                   TraceEventLevel.Always);

            session.Source.Dynamic.AddCallbackForProviderEvent("System.Threading.Tasks
                                                               .TplEventSource",
                "TaskExecute/Start", @event =>
                {
                    Console.WriteLine("Inside Task Started");
                });

            session.Source.Dynamic.AddCallbackForProviderEvent("System.Threading.Tasks
                                                   .TplEventSource", 
                "TaskExecute/Stop", @event =>
                {
                    Console.WriteLine("Inside Task Stopped");
                });

            session.Source.Process();
        }
    });

    var task = Task.Run(async () =>
    {
        await Task.Delay(20000);
    });

    task.Wait();
}

Basically what happens is:

1. We start new a live event capturing session using TraceEventSession where we pass it TraceEventLevel.Always to print out all messages (we could narrow this down to TranceEventLevel.Information, but for the example I chose all).

2. We enable the TplEventSource provider by passing its Guid to session.EnableProvider.

3. We register a callback to be invoked once TplEventSource (which is the event source for TPL, obviously) fires either TaskExecute/Start or TaskExecute/Stop events (taken from the reference source)

4. We print out once we're inside the event.

Note my use of Task.Run was simply because session.Source.Process() is a blocking call, and I wanted it to run in the background.

Answer 2

Here is an example of code I wrote that listens to TPL ETW events using only the BCL.

The part that tripped me up was the fact that you need to run this code:

// Cause the type initializer for System.Threading.Tasks.TplEtwProvider to run.
// Otherwise async method builders starting events will be missed.
Type.GetType("System.Threading.Tasks.TplEtwProvider, mscorlib", true).GetField("Log").GetValue(null);

Otherwise, everything just seems to work the way you'd expect. No need for third-party libraries!