本文适用于：✔️ .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 相关的“发生uh-oh 错误”消息。但是，应用程序并发性继续变得越来越复杂。 现在通常使用asyncawait，因此，在完成工作之前，可以在许多不同的线程上部分处理单个请求。 线程 ID 不再足以将为一个请求生成的所有消息关联在一起。 活动 ID 可解决此问题。 它们提供了更精细的标识符，可以跟踪单个请求或请求的一部分，而不管工作是否分布在不同的线程中。
注释
此处提到的活动 ID 概念与 System.Diagnostics.Tracing.Activity 不同，尽管命名类似。
使用活动标识符跟踪工作
可以运行下面的代码以查看活动跟踪是否正常运行。
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 相关联的事件。
