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