EventSource 活动 ID

本文适用范围:✔️ .NET Core 3.1 及更高版本 ✔️ .NET Framework 4.5 及更高版本

本指南介绍活动 ID,这是一个可选的标识符,可以与每个使用 System.Diagnostics.Tracing.EventSource 生成的事件一起记录。 有关简介,请参阅 EventSource 入门

记录并发工作的挑战

很久以前,典型的应用程序可能是简单的、单线程的,这使得日志记录简单明了。 你可以按顺序将每个步骤写入日志文件,然后按写入的顺序完全读回日志,以了解发生了什么情况。 如果应用处理了请求,则一次只处理一个请求。 请求 A 的所有日志消息将按顺序打印,然后是请求 B 的所有消息,依次类推。 当应用变成多线程时,这种策略将不再有效,因为多个请求同时进行处理。 但是,如果将每个请求分配给可进行完全处理的单个线程,则可以通过记录每个日志消息的线程 ID 来解决该问题。 例如,多线程应用可能会记录以下内容:

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

通过读取线程 ID,你知道线程 12 正在处理请求 A,线程 190 正在处理请求 B,因此“啊哦,发生了错误”消息与请求 A 相关。然而,应用程序的并发性一直在不断增长,越来越复杂。 现在,使用 asyncawait 是很常见的,这样,在完成工作之前,可以在多个不同的线程上部分处理单个请求。 线程 ID 不再足以将为一个请求生成的所有消息关联在一起。 活动 ID 可解决此问题。 它们提供了更精细的标识符,可以跟踪单个请求或请求的一部分,而不管工作是否分布在不同的线程中。

注意

这里提到的活动 ID 概念与 System.Diagnostics.Tracing.Activity 不同,尽管名称类似。

使用活动 ID 跟踪工作

可以运行以下代码来查看活动跟踪的实际效果。

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();
            }
        }
    }
}

运行后,此代码打印以下输出:

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

注意

存在一个已知问题,Visual Studio 调试器可能导致生成无效的活动 ID。 在继续解决此问题之前,要么不要在调试器下运行此示例,要么在 Main 的开头设置一个断点,并在即时窗口中评估表达式“System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false”。

使用活动 ID,你可以看到工作项 A 的所有消息都有 ID 00000011-...,工作项 B 的所有消息都有 ID 00000012-...。 这两个工作项先在线程 21256 上执行一些工作,但随后它们各自在独立的线程池线程 11348 和 14728 上继续工作,因此尝试仅使用线程 ID 来跟踪请求将不起作用。

EventSource 具有一个自动启发式方法,即定义一个名为 _Something_Start 的事件,紧接着另一个名为 _Something_Stop 的事件被视为一个工作单元的开始和停止。 记录新工作单元的开始事件会创建新的活动 ID,并使用该活动 ID 开始记录同一线程上的所有事件,直到记录停止事件为止。 使用 asyncawait 时,ID 还会自动跟踪异步控制流。 尽管我们建议使用 Start/Stop 命名后缀,但你可以通过使用 EventAttribute.Opcode 属性显式注释事件,来命名任何目标事件。 将第一个事件设置为 EventOpcode.Start,将第二个事件设置为 EventOpcode.Stop

记录并行工作的请求

有时,单个请求可能会并行执行其工作的不同部分,并且你希望对所有日志事件和子部分进行分组。 下面的示例模拟了一个请求,它并行执行两个数据库查询,并对每个查询的结果进行一些处理。 你希望隔离每个查询的工作,但同时要了解当多个并发请求可能正在运行时,哪些查询属于同一请求。 这会建模为一个树,其中每个顶级请求是根,而工作的子部分是分支。 树中的每个节点均获取自己的活动 ID,并且使用新的子活动 ID 记录的第一个事件将记录一个名为“相关活动 ID”的额外字段,以描述其父项。

运行以下代码:

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();
            }
        }
    }
}

此示例打印以下输出:

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

此示例仅运行了一个已分配有活动 ID 00000011-... 的顶级请求。 然后,每个 QueryStart 事件都将分别开始一个具有活动 ID 00001011-...00002011-... 的请求的新分支。 可以将这些 ID 标识为原始请求的子项,因为这两个开始事件都在“相关活动 ID”字段中记录了父项 00000011-...

注意

你可能已注意到,ID 的数值在父项和子项之间具有一些清晰的模式,并不是随机的。 虽然它有助于在简单的情况下直观地发现关系,但对于工具来说,最好不要依赖这一点,并将 ID 视为不透明的标识符。 随着嵌套级别加深,字节模式将随之发生变化。 使用“相关活动 ID”字段是确保工具可靠工作的最佳方式,不受嵌套级别的限制。

由于具有子工作项的复杂树的请求将生成许多不同的活动 ID,因此这些 ID 通常最好由工具进行分析,而不是尝试手动重新构造树。 可以借助 PerfView 工具,将使用这些 ID 批注的事件关联起来。