EventSource tracing with correlated activity id

Question

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.

This happens because a Console Application uses the `ThreadPoolSynchronizationContext`, which executes continuations on an arbitary threadpool thread. Will you be using ETW from there or is that simply for testing purposes? — Yuval Itzchakov, Oct 14 '14 at 22:17
@YuvalItzchakov - it will be a Windows Service, so yes. I've implemented an STA sync context but there's too much overhead. The point is that await is supposed to log a transfer event and set a new activity id on the new thread. I found out that await is doing its job, but the out-of-process Semantic logging block is not picking it up so I've submitted this as a bug to Microsoft. — Chris Gessler, Oct 15 '14 at 11:44
How did you get that working? For me EventSource.CurrentThreadActivityId is always zeroes after await for the sample above? — Mikl X, Sep 28 '16 at 09:57
If you're using .net 4.6+ you can implement your own wrapper using AsyncLocal. But there is still no great solution to this AFAIK. — Alex Vallejo, Jun 27 '18 at 22:38

Chris Gessler · Accepted Answer · 2014-10-15T13:11:05.507

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...

EventSource tracing with correlated activity id

1 Answers1