EventSource-Aktivitäts-IDs
Dieser Artikel gilt für: ✔️ .NET Core 3.1 und höhere Versionen ✔️ .NET Framework 4.5 und höhere Versionen
In diesem Leitfaden werden Aktivitäts-IDs erläutert, optionale Bezeichner, die mit jedem Ereignis protokolliert werden können, das mit System.Diagnostics.Tracing.EventSource generiert wird. Eine Einführung finden Sie unter Erste Schritte mit EventSource.
Die Herausforderung, gleichzeitige Vorgänge zu protokollieren
Vor langer Zeit waren Anwendungen häufig simpel und arbeiteten mit nur einem Thread – was die Protokollierung vereinfacht. Sie konnten jeden Schritt in eine Protokolldatei schreiben und dann das Protokoll genau in der Reihenfolge lesen, in der es geschrieben wurde, um zu verstehen, was passiert war. Die App verarbeitete jeweils immer nur eine Anforderung. Alle Protokollnachrichten für Anforderung A wurden ausgegeben, dann alle Nachrichten für Anforderung B usw. Bei Apps mit mehreren Threads funktioniert diese Strategie nicht mehr, da mehrere Anforderungen gleichzeitig verarbeitet werden müssen. Wenn jedoch jede Anforderung einem einzelnen Thread zugewiesen ist, der diese vollständig verarbeitet, können Sie das Problem lösen, indem Sie eine Thread-ID für jede Protokollnachricht aufzeichnen. Beispielsweise kann eine Multithread-App Folgendes protokollieren:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Anhand der Thread-IDs können Sie erkennen, dass Thread 12 Anforderung A und Thread 190 Anforderung B verarbeitet hat, daher steht die Meldung „uh-oh error happened“ im Zusammenhang mit Anforderung A. Die Parallelitätsanforderungen für Anwendungen werden jedoch immer komplexer. Heute ist es gängige Praxis, async und await zu verwenden, damit eine einzelne Anforderung teilweise in mehreren verschiedenen Threads verarbeitet werden kann, bevor die Arbeit abgeschlossen ist. Thread-IDs reichen nicht mehr aus, um alle Nachrichten zu korrelieren, die für eine einzige Anforderung erzeugt werden. Aktivitäts-IDs lösen dieses Problem. Sie stellen einen differenzierteren Bezeichner bereit, der einzelne Anforderungen oder Teile von Anforderungen nachverfolgen kann, unabhängig davon, ob die Arbeit auf verschiedene Threads verteilt ist.
Hinweis
Das hier beschriebene Konzept der Aktivitäts-IDs ist trotz der ähnlichen Benennung nicht mit System.Diagnostics.Tracing.Activity identisch.
Nachverfolgen der Verarbeitung mithilfe einer Aktivitäts-ID
Sie können den folgenden Code ausführen, um die Aktivitätsnachverfolgung in Aktion anzuzeigen.
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();
}
}
}
}
Dieser Code gibt bei der Ausführung Folgendes aus:
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
Hinweis
Es gibt ein bekanntes Problem, bei dem der Visual Studio-Debugger die Generierung von ungültigen Aktivitäts-IDs verursachen kann. Problemumgehung: Entweder führen Sie dieses Beispiel nicht im Debugger aus, oder Sie legen am Anfang von „Main“ einen Haltepunkt fest und werten den Ausdruck „System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false“ im Direktfenster aus, bevor Sie die Verarbeitung fortsetzen.
Mithilfe von Aktivitäts-IDs können Sie sehen, dass alle Nachrichten für Arbeitselement A die ID 00000011-... und alle Nachrichten für Arbeitselement B die ID 00000012-... haben. Beide Arbeitselemente haben zunächst einige Aufgaben in Thread 21256 ausgeführt, dann aber die Verarbeitung in den separaten Threadpoolthreads 11348 und 14728 fortgesetzt, sodass der Versuch, die Anforderung nur mit Thread-IDs nachzuverfolgen, nicht funktioniert hätte.
EventSource verfügt über eine automatische Heuristik, bei der das Definieren eines Ereignisses mit dem Namen „_Something_Start“ gefolgt von einem anderen Ereignis mit dem Namen „_Something_Stop“ als Beginn und Ende einer Arbeitseinheit betrachtet wird. Durch das Protokollieren des Start-Ereignisses für eine neue Arbeitseinheit wird eine neue Aktivitäts-ID erstellt. Dann beginnt die Protokollierung aller Ereignisse im Thread mit dieser Aktivitäts-ID, bis das Stop-Ereignis protokolliert wird. Die ID folgt bei Verwendung von async und await auch automatisch einer asynchronen Ablaufsteuerung. Es wird zwar empfohlen, die Namenssuffixe „Start“ und „Stop“ zu verwenden, aber Sie können beliebige Namen für die Ereignisse angeben, indem Sie mithilfe der EventAttribute.Opcode-Eigenschaft explizit eine Anmerkung hinzufügen. Legen Sie das erste Ereignis auf EventOpcode.Start und das zweite auf EventOpcode.Stop fest.
Protokollieren von Anforderungen, die parallele Aufgaben ausführen
Manchmal führt eine einzelne Anforderung verschiedene Teile ihrer Verarbeitung parallel aus, und Sie möchten alle Protokollereignisse und die untergeordneten Teile gruppieren. Das folgende Beispiel simuliert eine Anforderung simuliert, die zwei Datenbankabfragen parallel ausführt und anschließend Verarbeitungsaufgaben für die Ergebnisses jeder Abfrage durchführt. Sie möchten die Aufgaben für jede Abfrage isolieren, aber auch verstehen, welche Abfragen zu ein und derselben Anforderung gehören, wenn viele gleichzeitige Anforderungen ausgeführt werden. Die Modellierung erfolgt als Baumstruktur, in der jede Anforderung auf oberster Ebene den Stamm darstellt und die einzelnen Unteraufgaben die Zweige repräsentieren. Jeder Knoten in der Struktur erhält eine eigene Aktivitäts-ID, und das erste Ereignis, das mit der neuen untergeordneten Aktivitäts-ID protokolliert wird, protokolliert ein zusätzliches Feld namens „Related Activity ID“, um das übergeordnete Element zu beschreiben.
Führen Sie den folgenden Code aus:
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();
}
}
}
}
Dieses Beispiel führt zu folgender Ausgabe:
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
In diesem Beispiel wurde nur eine Anforderung der obersten Ebene ausgeführt, der die Aktivitäts-ID 00000011-... zugewiesen wurde. Anschließend startete jedes QueryStart-Ereignis eine neue Verzweigung der Anforderung mit den Aktivitäts-IDs 00001011-... bzw. 00002011-.... Dass diese IDs untergeordnete Elemente der ursprünglichen Anforderung sind, können Sie daran erkennen, dass beide Startereignisse ihre übergeordneten Aktivitäts-ID 00000011-... im Feld „Related Activity ID“ protokolliert haben.
Hinweis
Sie haben sicherlich das Muster in den numerischen Werten der IDs für die übergeordneten und untergeordneten Elemente erkannt – diese Werte sind nicht zufällig. Das kann zwar in einfachen Fällen beim Erkennen von Beziehungen helfen, aber Tools sollten nicht darauf angewiesen sein und die IDs stattdessen als opake Bezeichner behandeln. Wenn weitere Schachtelungsebenen hinzukommen, ändert sich das Bytemuster. Die Verwendung des Felds „Related Activity ID“ ist die beste Methode, um sicherzustellen, dass Tools unabhängig von der Schachtelungsebene zuverlässig funktionieren.
Da Anforderungen mit komplexen Strukturen aus vielen Teilaufgaben viele verschiedene Aktivitäts-IDs generieren, sollten Sie diese IDs in der Regel von Tools parsen lassen, anstatt zu versuchen, die Struktur manuell zu rekonstruieren. Das Tool PerfView beispielsweise kann Ereignisse korrelieren, die Anmerkungen mit diesen IDs enthalten.
