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.

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

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.

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.