Teilen über

EventSource-Aktivitäts-IDs

Dieser Artikel bezieht sich auf: ✔️ .NET Core 3.1 und höhere Versionen ✔️ .NET Framework 4.5 und neuere Versionen

In diesem Leitfaden werden Aktivitäts-IDs erläutert, ein optionaler Bezeichner, der mit jedem Ereignis protokolliert werden kann, das mit System.Diagnostics.Tracing.EventSource generiert wird. Eine Einführung finden Sie unter "Erste Schritte mit EventSource".

Die Herausforderung, gleichzeitige Arbeit zu protokollieren

Vor langer Zeit konnte eine typische Anwendung einfach und eindimensional sein, was die Protokollierung erleichtert. Sie können jeden Schritt in eine Protokolldatei schreiben und dann das Protokoll genau in der Reihenfolge lesen, in der er geschrieben wurde, um zu verstehen, was passiert ist. Wenn die App Anforderungen verarbeitet hat, wurde jeweils nur eine Anforderung verarbeitet. Alle Protokollnachrichten für Anforderung A würden in der Reihenfolge, dann alle Nachrichten für B usw. gedruckt. Wenn Apps multithreads werden, funktioniert diese Strategie nicht mehr, da mehrere Anforderungen gleichzeitig behandelt werden. Wenn jedoch jeder Anforderung ein einzelner Thread zugewiesen ist, der es 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

Durch das Lesen der Thread-IDs wissen Sie, dass Thread 12 die Anforderung A und Thread 190 die Anforderung B verarbeitete, daher bezieht sich die Meldung "uh-oh Fehler aufgetreten" auf die Anforderung A. Die Gleichzeitigkeit der Anwendung ist jedoch immer weiter gewachsen und immer komplexer geworden. Es ist jetzt üblich, async und await zu verwenden, damit eine einzelne Anforderung teilweise in vielen verschiedenen Threads bearbeitet werden kann, bevor die Arbeit abgeschlossen ist. Thread-IDs reichen nicht mehr aus, um alle nachrichten zu korrelieren, die für eine Anforderung erstellt wurden. Aktivitäts-IDs lösen dieses Problem. Sie stellen einen feineren Bezeichner bereit, der einzelne Anforderungen oder Teile von Anforderungen nachverfolgen kann, unabhängig davon, ob die Arbeit über verschiedene Threads verteilt ist.

Hinweis

Das hier genannte Aktivitäts-ID-Konzept ist trotz der ähnlichen Benennung nicht mit dem System.Diagnostics.Tracing.Activity identisch.

Nachverfolgen von Arbeiten 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 möglicherweise zu ungültigen Aktivitäts-IDs führen kann, die generiert werden. 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 der Aktivitäts-IDs können Sie sehen, dass alle Nachrichten für Arbeitsaufgabe A über ID 00000011-... und alle Nachrichten für Arbeitsaufgabe B verfügen 00000012-.... Beide Arbeitsaufgaben haben zunächst einige Arbeit an Thread 21256 ausgeführt, aber dann setzte jeder von ihnen ihre Arbeit an separaten Threadpoolthreads 11348 und 14728 fort, 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 Start- und Stopp einer Arbeitseinheit betrachtet wird. Durch das Protokollieren des Startereignisses für eine neue Arbeitseinheit wird eine neue Aktivitäts-ID erstellt und beginnt mit der Protokollierung aller Ereignisse im selben Thread mit dieser Aktivitäts-ID, bis das Stoppereignis protokolliert wird. Die ID folgt bei Verwendung von async und await auch automatisch einer asynchronen Ablaufsteuerung. Wir empfehlen zwar, die Namenssuffixe "Start/Beenden" zu verwenden, aber Sie können die Ereignisse beliebig benennen, indem Sie sie mit der Eigenschaft EventAttribute.Opcode explizit annotieren. Legen Sie das erste Ereignis auf EventOpcode.Start und das zweite Ereignis auf EventOpcode.Stop.

Protokollieren von Anforderungen, die parallele Aufgaben ausführen

Manchmal kann eine einzelne Anforderung verschiedene Teile ihrer Arbeit parallel ausführen, und Sie möchten alle Protokollereignisse und die Unterparts gruppieren. Im folgenden Beispiel wird eine Anforderung simuliert, die zwei Datenbankabfragen parallel ausführt und anschließend eine Verarbeitung des Ergebnisses jeder Abfrage durchführt. Sie möchten die Arbeit für jede Abfrage isolieren, aber auch verstehen, welche Abfragen derselben Anforderung angehören, wenn viele gleichzeitige Anforderungen ausgeführt werden können. Dies wird als Struktur modelliert, in der jede Anforderung auf oberster Ebene ein Stamm und dann Unterportionen der Arbeit Zweige sind. 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. Obwohl es bei der visuellen Erkennung der Beziehung in einfachen Fällen helfen kann, ist es am besten, dass Tools nicht darauf angewiesen sind und die IDs als undurchsichtige IDs 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 von Teilaufgaben viele verschiedene Aktivitäts-IDs generieren, werden diese IDs in der Regel am besten von Tools analysiert, anstatt zu versuchen, die Struktur manuell zu rekonstruieren. PerfView ist ein Tool, das weiß, wie Ereignisse korreliert werden, die mit diesen IDs kommentiert werden.

  • Last updated on