Search code examples
c#async-await.net-4.5etw

EventSource tracing with correlated activity id


I've started using ETW and the out-of-process Semantic Logging Block from Entlib 6. When I use async/await, the CurrentThreadActivityId is not set on the continuation thread and the TPL framework does not log a transfer event. This makes it extremely difficult to perform end-to-end tracing.

According to Microsoft's documentation, the TPL framework is supposed to log a transfer event and generate a new activityid, but I can't seem to get it to work.

Documentation from Entlib 6

Here's a small example showing the problem:

To log TPL events, I'm using the following:

<eventSource name="System.Threading.Tasks.TplEventSource" level="Informational" matchAnyKeyword="1"/>

And here my test code:

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

namespace AsyncContextTest
{
    class Program
    {
        static Guid _activityId = Guid.NewGuid();

        static void Main(string[] args)
        {
            EventSource.SetCurrentThreadActivityId(_activityId);
            Console.WriteLine(EventSource.CurrentThreadActivityId);
            Task t = Task.Run(async () => await DoStuffAsync());
            Console.WriteLine(EventSource.CurrentThreadActivityId);

            Console.Read();
        }

        public static async Task DoStuffAsync()
        {
            var x = "one,two,three".Split(',');
            Console.WriteLine(EventSource.CurrentThreadActivityId);
            await Task.Delay(1000);
            Console.WriteLine(EventSource.CurrentThreadActivityId);
            var y = String.Join(",", x);

            Console.WriteLine("Done");

        }
    }
}

Results

334540cc-ccb1-4196-8587-815abf237e4c
334540cc-ccb1-4196-8587-815abf237e4c
00000000-0000-0000-0000-000000000000
00000000-0000-0000-0000-000000000000
Done

Does anyone have a simple example showing the proper way to do end to end tracing with ETW and async/await?

EDIT:

I was able to get this working properly with an in-process listener, but not with the out-of-process listener. Nothing is logged from TPL.


Solution

  • Change the configuration to use the event source's GUID instead of the name.

    <eventSource id="2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5" level="Informational" />
    

    Output will look like:

    605e615a-c849-4ee7-95b8-e6677f945c3f
    605e615a-c849-4ee7-95b8-e6677f945c3f
    00000001-0001-0000-0c22-0000ffdcd7b5
    00000002-0001-0000-0c22-0000ffdcd7b5
    Done
    

    Does anyone have a simple example showing the proper way to do end to end tracing with ETW and async/await?

    Still looking...