Muokkaa

Jaa


EventSource Activity IDs

This article applies to: ✔️ .NET Core 3.1 and later versions ✔️ .NET Framework 4.5 and later versions

This guide explains Activity IDs, an optional identifier that can be logged with each event generated using System.Diagnostics.Tracing.EventSource. For an introduction, see Getting Started with EventSource.

The challenge of logging concurrent work

Long ago, a typical application may have been simple and single-threaded, which makes logging straightforward. You could write each step to a log file in order and then read the log back exactly in the order it was written to understand what happened. If the app handled requests then only one request was handled at a time. All log messages for request A would be printed in order, then all the messages for B, and so on. When apps become multi-threaded that strategy no longer works because multiple requests are being handled at the same time. However if each request is assigned to a single thread that processes it entirely, you can solve the problem by recording a thread ID for each log message. For example, a multi-threaded app might log:

Thread Id      Message
---------      -------
12             BeginRequest A
12             Doing some work
190            BeginRequest B
12             uh-oh error happened
190            Doing some work

By reading the thread IDs you know that thread 12 was processing request A and thread 190 was processing request B, therefore the 'uh-oh error happened' message related to request A. However application concurrency has continued to grow ever more sophisticated. It's now common to use async and await so that a single request could be handled partially on many different threads before the work is complete. Thread IDs are no longer sufficient to correlate together all the messages produced for one request. Activity IDs solve this problem. They provide a finer grain identifier that can track individual requests, or portions of requests, regardless of if the work is spread across different threads.

Note

The Activity ID concept referred to here is not the same as the System.Diagnostics.Tracing.Activity, despite the similar naming.

Tracking work using an Activity ID

You can run the code below to see Activity tracking in action.

using System.Diagnostics.Tracing;

public static class Program
{
    public static async Task Main(string[] args)
    {
        ConsoleWriterEventListener listener = new ConsoleWriterEventListener();

        Task a = ProcessWorkItem("A");
        Task b = ProcessWorkItem("B");
        await Task.WhenAll(a, b);
    }

    private static async Task ProcessWorkItem(string requestName)
    {
        DemoEventSource.Log.WorkStart(requestName);
        await HelperA();
        await HelperB();
        DemoEventSource.Log.WorkStop();
    }

    private static async Task HelperA()
    {
        DemoEventSource.Log.DebugMessage("HelperA");
        await Task.Delay(100); // pretend to do some work
    }

    private static async Task HelperB()
    {
        DemoEventSource.Log.DebugMessage("HelperB");
        await Task.Delay(100); // pretend to do some work
    }
}

[EventSource(Name ="Demo")]
class DemoEventSource : EventSource
{
    public static DemoEventSource Log = new DemoEventSource();

    [Event(1)]
    public void WorkStart(string requestName) => WriteEvent(1, requestName);
    [Event(2)]
    public void WorkStop() => WriteEvent(2);

    [Event(3)]
    public void DebugMessage(string message) => WriteEvent(3, message);
}

class ConsoleWriterEventListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if(eventSource.Name == "Demo")
        {
            Console.WriteLine("{0,-5} {1,-40} {2,-15} {3}", "TID", "Activity ID", "Event", "Arguments");
            EnableEvents(eventSource, EventLevel.Verbose);
        }
        else if(eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Activity IDs aren't enabled by default.
            // Enabling Keyword 0x80 on the TplEventSource turns them on
            EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)0x80);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        lock (this)
        {
            Console.Write("{0,-5} {1,-40} {2,-15} ", eventData.OSThreadId, eventData.ActivityId, eventData.EventName);
            if (eventData.Payload.Count == 1)
            {
                Console.WriteLine(eventData.Payload[0]);
            }
            else
            {
                Console.WriteLine();
            }
        }
    }
}

When run, this code prints output:

TID   Activity ID                              Event           Arguments
21256 00000011-0000-0000-0000-00006ab99d59     WorkStart       A
21256 00000011-0000-0000-0000-00006ab99d59     DebugMessage    HelperA
21256 00000012-0000-0000-0000-00006bb99d59     WorkStart       B
21256 00000012-0000-0000-0000-00006bb99d59     DebugMessage    HelperA
14728 00000011-0000-0000-0000-00006ab99d59     DebugMessage    HelperB
11348 00000012-0000-0000-0000-00006bb99d59     DebugMessage    HelperB
11348 00000012-0000-0000-0000-00006bb99d59     WorkStop
14728 00000011-0000-0000-0000-00006ab99d59     WorkStop

Note

There is a known issue where Visual Studio debugger may cause invalid Activity IDs to be generated. Either don't run this sample under the debugger or set a breakpoint at the beginning of Main and evaluate the expression 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' in the immediate window before continuing to work around the issue.

Using the Activity IDs you can see that all of the messages for work item A have ID 00000011-... and all the messages for work item B have ID 00000012-.... Both work items first did some work on thread 21256, but then each of them continued their work on separate threadpool threads 11348 and 14728 so trying to track the request only with thread IDs wouldn't have worked.

EventSource has an automatic heuristic where defining an event named _Something_Start followed immediately by another event named _Something_Stop is considered the start and stop of a unit of work. Logging the start event for a new unit of work creates a new Activity ID and begins logging all events on the same thread with that Activity ID until the stop event is logged. The ID also automatically follows async control flow when using async and await. Although we recommend that you use the Start/Stop naming suffixes, you may name the events anything you like by explicitly annotating them using the EventAttribute.Opcode property. Set the first event to EventOpcode.Start and the second to EventOpcode.Stop.

Log requests that do parallel work

Sometimes a single request might do different parts of its work in parallel, and you want to group all the log events and the subparts. The example below simulates a request that does two database queries in parallel and then does some processing on the result of each query. You want to isolate the work for each query, but also understand which queries belong to the same request when many concurrent requests could be running. This is modeled as a tree where each top-level request is a root and then subportions of work are branches. Each node in the tree gets its own Activity ID, and the first event logged with the new child Activity ID logs an extra field called Related Activity ID to describe its parent.

Run the following code:

using System.Diagnostics.Tracing;

public static class Program
{
    public static async Task Main(string[] args)
    {
        ConsoleWriterEventListener listener = new ConsoleWriterEventListener();

        await ProcessWorkItem("A");
    }

    private static async Task ProcessWorkItem(string requestName)
    {
        DemoEventSource.Log.WorkStart(requestName);
        Task query1 = Query("SELECT bowls");
        Task query2 = Query("SELECT spoons");
        await Task.WhenAll(query1, query2);
        DemoEventSource.Log.WorkStop();
    }

    private static async Task Query(string query)
    {
        DemoEventSource.Log.QueryStart(query);
        await Task.Delay(100); // pretend to send a query
        DemoEventSource.Log.DebugMessage("processing query");
        await Task.Delay(100); // pretend to do some work
        DemoEventSource.Log.QueryStop();
    }
}

[EventSource(Name = "Demo")]
class DemoEventSource : EventSource
{
    public static DemoEventSource Log = new DemoEventSource();

    [Event(1)]
    public void WorkStart(string requestName) => WriteEvent(1, requestName);
    [Event(2)]
    public void WorkStop() => WriteEvent(2);
    [Event(3)]
    public void DebugMessage(string message) => WriteEvent(3, message);
    [Event(4)]
    public void QueryStart(string query) => WriteEvent(4, query);
    [Event(5)]
    public void QueryStop() => WriteEvent(5);
}

class ConsoleWriterEventListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name == "Demo")
        {
            Console.WriteLine("{0,-5} {1,-40} {2,-40} {3,-15} {4}", "TID", "Activity ID", "Related Activity ID", "Event", "Arguments");
            EnableEvents(eventSource, EventLevel.Verbose);
        }
        else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Activity IDs aren't enabled by default.
            // Enabling Keyword 0x80 on the TplEventSource turns them on
            EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)0x80);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        lock (this)
        {
            Console.Write("{0,-5} {1,-40} {2, -40} {3,-15} ", eventData.OSThreadId, eventData.ActivityId, eventData.RelatedActivityId, eventData.EventName);
            if (eventData.Payload.Count == 1)
            {
                Console.WriteLine(eventData.Payload[0]);
            }
            else
            {
                Console.WriteLine();
            }
        }
    }
}

This example prints output such as:

TID   Activity ID                              Related Activity ID                      Event           Arguments
34276 00000011-0000-0000-0000-000086af9d59     00000000-0000-0000-0000-000000000000     WorkStart       A
34276 00001011-0000-0000-0000-0000869f9d59     00000011-0000-0000-0000-000086af9d59     QueryStart      SELECT bowls
34276 00002011-0000-0000-0000-0000868f9d59     00000011-0000-0000-0000-000086af9d59     QueryStart      SELECT spoons
32684 00002011-0000-0000-0000-0000868f9d59     00000000-0000-0000-0000-000000000000     DebugMessage    processing query
18624 00001011-0000-0000-0000-0000869f9d59     00000000-0000-0000-0000-000000000000     DebugMessage    processing query
18624 00002011-0000-0000-0000-0000868f9d59     00000000-0000-0000-0000-000000000000     QueryStop
32684 00001011-0000-0000-0000-0000869f9d59     00000000-0000-0000-0000-000000000000     QueryStop
32684 00000011-0000-0000-0000-000086af9d59     00000000-0000-0000-0000-000000000000     WorkStop

This example only ran one top-level request, which was assigned Activity ID 00000011-.... Then each QueryStart event began a new branch of the request with Activity IDs 00001011-... and 00002011-... respectively. You can identify these IDs are children of the original request because both of the start events logged their parent 00000011-... in the Related Activity ID field.

Note

You may have noticed the numerical values of the IDs have some clear patterns between parent and child and aren't random. Although it can assist in spotting the relationship visually in simple cases, it's best for tools not to rely on this and treat the IDs as opaque identifiers. As the nesting level grows deeper, the byte pattern will change. Using the Related Activity ID field is the best way to ensure tools work reliably regardless of nesting level.

Because requests with complex trees of subwork items will generate many different Activity IDs, these IDs are usually best parsed by tools rather than trying to reconstruct the tree by hand. PerfView is one tool that knows how to correlate events annotated with these IDs.