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 相关。然而，应用程序的并发性一直在不断增长，越来越复杂。 现在，使用 async 和 await 是很常见的，这样，在完成工作之前，可以在多个不同的线程上部分处理单个请求。 线程 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 开始记录同一线程上的所有事件，直到记录停止事件为止。 使用 async 和 await 时，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 批注的事件关联起来。
