EventSource 活動識別碼
本文適用於：✔️.NET Core 3.1 和更新版本 ✔️ .NET Framework 4.5 和更新版本
本指南說明活動識別碼，其為選用的識別碼，使用 System.Diagnostics.Tracing.EventSource 所產生的每個事件的識別碼，都可記錄下來。 如需取得簡介，請參閱開始使用 EventSource。
記錄並行工作的挑戰
很久以前，一般的應用程式都較簡單且為單一執行緒，讓記錄能相當簡單明瞭。 您可以依序將每個步驟寫入記錄檔，然後完全以寫入記錄一樣的順序來讀取記錄檔，即可了解所發生的情況。 如果應用程式會處理要求，則一次只會處理一個要求。 要求 A 的所有記錄訊息，都會依序列印，然後列印 B 的所有訊息，依此類推。 當應用程式變成多執行緒時，該策略就不再有效，因為同時會處理多項要求。 不過，如果每個要求都指派到整個來處理它的單一執行緒，就可以藉由記錄下每個記錄訊息的執行緒識別碼，解決掉該問題。 例如，多執行緒應用程式可能會記錄：
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
藉由讀取執行緒識別碼，您知道執行緒 12 正在處理要求 A，而執行緒 190 正在處理要求 B，因此「糟了，發生錯誤了」訊息是與要求 A 相關。不過，應用程式並行作業仍然繼續變得更加複雜。 現在很常使用 async 和 await，讓單一要求可以在許多不同的執行緒上進行部分處理，直到工作完成為止。 執行緒識別碼已不足以將針對一個要求所產生的所有訊息，彼此相互關聯。 活動識別碼可解決此問題。 這些識別碼提供更精細的識別碼，可追蹤個別要求或部分要求，而不論工作是否分散到不同的執行緒。
注意
此處所說的活動識別碼概念，儘管與 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 偵錯工具可能會導致產生不正確的活動識別碼。 可以不要在偵錯工具下執行此範例，或是在 Main 的開頭設定中斷點，然後在目前的視窗中，評估運算式 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false'，然後再繼續，即可變通解決此問題。
使用活動識別碼可以看到識別碼為 00000011-... 的工作項目 A 之所有訊息，以及識別碼為 00000012-... 的工作項目 B 之所有訊息。 這兩個工作項目都會在執行緒 21256 上執行一些工作，但之後兩者會在不同的執行緒集區執行緒 11348 和 14728 上繼續它們的工作，因此嘗試只使用執行緒識別碼來追蹤要求，並不實際。
EventSource 有自動啟發學習法，其定義名為 _Something_Start 的事件，後面緊接著另一個名為 _Something_Stop 的事件，可被視為工作單位的開始和停止。 記錄新工作單位的開始事件，會建立新的活動識別碼，並會開始使用該活動識別碼，記錄相同執行緒上的所有事件，直到記錄到停止事件為止。 使用 async 和 await 時，識別碼也會自動遵循非同步控制流程。 雖然建議您使用開始/停止命名尾碼，但您可以使用 EventAttribute.Opcode 屬性明確地標註事件，隨意命名事件。 將第一個事件設定為 EventOpcode.Start，並將第二個設定為 EventOpcode.Stop。
記錄執行平行工作的要求
有時候，單一要求可能會以平行方式執行其工作的不同部分，而您希望將所有記錄事件和子元件能歸在一起。 下列範例即模擬平行執行兩個資料庫查詢，然後對每個查詢的結果進行一些處理的要求。 您想要隔離開每個查詢的工作，但也了解執行許多並行要求時，哪些查詢屬於相同的要求。 這會模型化為樹狀結構，其中每個最上層的要求都是一個根，然後工作的不同部分是分支。 樹狀結構中的每個節點，都會取得自己的活動識別碼，而第一個記錄了新的子活動識別碼的事件，會記錄下一個稱為「相關活動識別碼」的額外欄位，以描述其父代。
執行下列程式碼：
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
此範例只會執行一個最上層要求，指派給它的活動識別碼為 00000011-...。 然後，每個 QueryStart 事件都會以活動識別碼 00001011-... 和 00002011-...，分別開始一個要求的新分支。 因為這兩個開始事件在 [相關活動識別碼] 欄位中，都記錄了其父 00000011-...，所以您可以識別出這些識別碼是原始要求的子系。
注意
您可能已經注意到，識別碼的數值在父代和子系之間，有一些明確的模式，而且並非隨機的。 雖然在簡單的案例中，它有助於一眼就看出關聯性，但其最適合不依賴此識別碼，並將識別碼視為不透明識別碼的工具。 當巢狀層級變深時，位元組模式將會變更。 使用 [相關活動識別碼] 欄位是確保無論巢狀層級如何，工具都能可靠運作的最佳方式。
因為具有子工作項目複雜樹狀結構的要求，會產生許多不同的活動識別碼，因此這些識別碼通常最好由工具進行剖析，而不是嘗試手動重新建構樹狀結構。 PerfView (英文) 是知道如何將標註有這些識別碼的事件，彼此相互關聯的一種工具。
