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.
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...
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With