EventSource アクティビティ ID
この記事の対象: ✔️ .NET Core 3.1 以降のバージョン ✔️ .NET Framework 4.5 以降のバージョン
このガイドでは、System.Diagnostics.Tracing.EventSource を使用して生成される各イベントと共にログに記録できる、省略可能なアクティビティ ID について説明します。 概要については、「EventSource の使用を開始する」を参照してください。
同時実行作業のログ記録に関する問題
一昔前ならば一般的なアプリケーションは単純なシングルスレッドであったかもしれず、そうであればログ記録を行うことは簡単です。 各ステップをログ ファイルに順番に書き込んだ後は、書き込まれた順序で正確にログを読み出して、何が起こったかを理解することができました。 アプリで要求を処理したのであれば、一度に処理された要求は 1 つだけでした。 要求 A のすべてのログ メッセージが順番に出力されら、次に B のすべてのメッセージが出力され、のように続いたでしょう。 アプリがマルチスレッドになると、複数の要求が同時に処理されているために、その戦略が機能しなくなります。 ただし、各要求が、それ全体を処理する 1 つのスレッドに割り当てられている場合は、各ログ メッセージのスレッド 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 error happened" というメッセージになったことがわかります。ただし、アプリケーションの同時実行は、これまで以上に高度になり続けています。 今では、作業が完了する前に 1 つの要求を多くの異なるスレッドで部分的に処理できるように、async と await を使用することが一般的になっています。 スレッド ID は、1 つの要求に対して生成されるすべてのメッセージを同時に関連付けるためには十分ではなくなりました。 アクティビティ ID は、この問題を解決するものです。 これらが、作業が異なるスレッドにわたって分散されているかどうかに関わらず、個々の要求や要求の一部を追跡できる、よりきめ細かな識別子となっています。
Note
ここで言及されているアクティビティ 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
Note
Visual Studio デバッガーが無効なアクティビティ ID が生成される原因になる可能性がある既知の問題が存在します。 このサンプルを、このデバッガーでは実行しないようにするか、Main の先頭にブレークポイントを設定して、イミディエイト ウィンドウで式 "System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false" を評価してから、問題の回避を続行します。
アクティビティ ID を使用すると、作業項目 A のすべてのメッセージに ID 00000011-... があり、作業項目 B のすべてのメッセージに ID 00000012-... があることが分ります。 どちらの作業項目も最初はスレッド 21256 で何らかの作業を行っていましたが、その後、各作業項目は別個の threadpool スレッド 11348 と 14728 で続行されるので、スレッド ID のみを使用して要求の追跡を試みても、うまくいかなかったでしょう。
EventSource には、_Something_Start という名前のイベントの直後に _Something_Stop という名前のイベントを定義すると作業単位の開始と停止と見なされる、自動ヒューリスティックがあります。 新しい作業単位の開始イベントをログに記録すると、新しいアクティビティ ID が作成され、そのアクティビティ ID を持つ同一スレッド上のイベントすべてのログ記録が開始されて、停止イベントが記録されるまで続きます。 async と await の使用時にも、ID は非同期制御フローに自動的に従います。 Start/Stop という名前付けサフィックスを使うことをお勧めしますが、EventAttribute.Opcode プロパティを使って明示的に注釈を付けることで、イベントに好きな名前を付けることができます。 最初のイベントを EventOpcode.Start に、2 番目のイベントを EventOpcode.Stop に設定します。
並列処理を行う要求をログに記録する
1 つの要求で、その作業のさまざまな部分を並列実行し、すべてのログ イベントとサブパーツをグループ化したい場合があります。 下の例は、2 つのデータベース クエリを並列実行してから、各クエリの結果に対してある処理を実行する要求をシミュレートたものです。 クエリごとに作業を分離する必要がありますが、多くの同時要求が実行されている可能性があるときに、どのクエリが同じ要求に属しているかを把握する必要もあります。 これはツリーとしてモデル化されていて、最上位レベルの各要求がルートであり、作業のサブパーツが分岐となっています。 ツリー内の各ノードが独自のアクティビティ ID を取得し、新しい子アクティビティ ID を使用してログに記録される最初のイベントは、その親を記述するための Related Activity 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-... が割り当てられた最上位レベルの要求を 1 つだけ実行しました。 次に、各 QueryStart イベントにより、それぞれがアクティビティ ID 00001011-... と 00002011-... を持つ、要求の新しい分岐が開始されました。 これらの ID は、どちらの開始イベントについても Related Activity ID に親 00000011-... が記録されているため、元の要求の子であることを識別できます。
Note
ID の数値については、親と子の間に明確なパターンがあり、ランダムではないことに気付いたかもしれません。 これは、単純な場合には関係を視覚的に見分ける助けになりますが、ツールではこれに依存しないで ID を非透過的な識別子として扱うことをお勧めします。 入れ子のレベルが深くなるにつれて、バイトのパターンが変化します。 Related Activity ID フィールドを使用することは、入れ子のレベルを問わずツールの動作の信頼性を確保するうえで最適な方法です。
サブ作業項目のツリーが複雑な要求では、多くの異なるアクティビティ ID が生成されるため、これらの ID は通常、手作業でツリーの再構築を試みるのではなく、ツールによって解析するのが適切です。 PerfView は、これらの ID で注釈が付けられたイベントを関連付ける方法が認識されている 1 つのツールです。
.NET