Identyfikatory działań usługi EventSource

Ten artykuł dotyczy: ✔️ .NET Core 3.1 i nowsze wersje ✔️ programu .NET Framework 4.5 i nowszych wersji

W tym przewodniku opisano identyfikatory działań, opcjonalny identyfikator, który można rejestrować przy użyciu każdego zdarzenia wygenerowanego przy użyciu polecenia System.Diagnostics.Tracing.EventSource. Aby zapoznać się z wprowadzeniem, zobacz Wprowadzenie do usługi EventSource.

Wyzwanie dotyczące rejestrowania równoczesnej pracy

Dawno temu typowa aplikacja mogła być prosta i jednowątkowa, co sprawia, że rejestrowanie jest proste. Każdy krok można zapisać w pliku dziennika w kolejności, a następnie odczytać dziennik dokładnie w kolejności, w jakiej został zapisany, aby zrozumieć, co się stało. Jeśli aplikacja obsłużyła żądania, w danym momencie obsłużono tylko jedno żądanie. Wszystkie komunikaty dziennika dla żądania A zostaną wydrukowane w kolejności, a następnie wszystkie komunikaty dla B itd. Gdy aplikacje stają się wielowątkowa, ta strategia nie działa już, ponieważ wiele żądań jest obsługiwanych w tym samym czasie. Jeśli jednak każde żądanie jest przypisane do pojedynczego wątku, który przetwarza go w całości, możesz rozwiązać ten problem, rejestrując identyfikator wątku dla każdego komunikatu dziennika. Na przykład aplikacja wielowątkowa może rejestrować:

Thread Id      Message
---------      -------
12             BeginRequest A
12             Doing some work
190            BeginRequest B
12             uh-oh error happened
190            Doing some work

Czytając identyfikatory wątków, wiesz, że wątek 12 przetwarzał żądanie A, a wątek 190 przetwarzał żądanie B, dlatego komunikat "uh-oh error happened" powiązany z żądaniem A. Jednak współbieżność aplikacji nadal rośnie coraz bardziej wyrafinowana. Obecnie często używa async się pojedynczego żądania, await dzięki czemu pojedyncze żądanie może być częściowo obsługiwane w wielu różnych wątkach przed ukończeniem pracy. Identyfikatory wątków nie są już wystarczające do skorelowania wszystkich komunikatów generowanych dla jednego żądania. Identyfikatory działań rozwiązują ten problem. Zapewniają one bardziej precyzyjny identyfikator ziarna, który może śledzić poszczególne żądania lub fragmenty żądań, niezależnie od tego, czy praca jest rozłożona na różne wątki.

Śledzenie pracy przy użyciu identyfikatora działania

Możesz uruchomić poniższy kod, aby zobaczyć śledzenie aktywności w akcji.

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();
            }
        }
    }
}

Po uruchomieniu ten kod wyświetla dane wyjściowe:

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

Za pomocą identyfikatorów działań można zobaczyć, że wszystkie komunikaty dla elementu roboczego A mają identyfikator i wszystkie komunikaty dla elementu roboczego B mają identyfikator 00000011-...00000012-.... Oba elementy robocze najpierw działały w wątku 21256, ale następnie każdy z nich kontynuował pracę na osobnych wątkach wątków 11348 i 14728, więc próba śledzenia żądania tylko z identyfikatorami wątków nie zadziałałaby.

Usługa EventSource ma automatyczną heurystyczną, w której definiowanie zdarzenia o nazwie _Something_Start następuje natychmiast po innym zdarzeniu o nazwie _Something_Stop jest uznawane za rozpoczęcie i zatrzymanie jednostki pracy. Rejestrowanie zdarzenia rozpoczęcia dla nowej jednostki pracy powoduje utworzenie nowego identyfikatora działania i rozpoczęcie rejestrowania wszystkich zdarzeń w tym samym wątku za pomocą tego identyfikatora działania do momentu zarejestrowania zdarzenia zatrzymania. Identyfikator jest również automatycznie zgodny z przepływem sterowania asynchronicznego w przypadku używania elementów async i await. Mimo że zalecamy używanie sufiksów uruchamiania/zatrzymywania nazewnictwa, możesz nazwać zdarzenia, które chcesz, jawnie dodając do nich adnotacje przy użyciu EventAttribute.Opcode właściwości . Ustaw pierwsze zdarzenie na EventOpcode.Start , a drugi na EventOpcode.Stop.

Żądania dzienników, które wykonują równoległą pracę

Czasami pojedyncze żądanie może wykonywać różne części jego pracy równolegle i chcesz zgrupować wszystkie zdarzenia dziennika i podparty. Poniższy przykład symuluje żądanie, które wykonuje równolegle dwa zapytania bazy danych, a następnie wykonuje pewne przetwarzanie w wyniku każdego zapytania. Chcesz odizolować pracę dla każdego zapytania, ale także zrozumieć, które zapytania należą do tego samego żądania, gdy wiele współbieżnych żądań może być uruchomionych. Jest to modelowane jako drzewo, w którym każde żądanie najwyższego poziomu jest katalogiem głównym, a następnie podporty pracy są gałęziami. Każdy węzeł w drzewie pobiera własny identyfikator działania, a pierwsze zdarzenie zarejestrowane przy użyciu nowego podrzędnego identyfikatora aktywności rejestruje dodatkowe pole o nazwie Related Activity ID (Powiązany identyfikator działania), aby opisać jego element nadrzędny.

Uruchom następujący kod:

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();
            }
        }
    }
}

W tym przykładzie są wyświetlane dane wyjściowe, takie jak:

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

W tym przykładzie uruchomiono tylko jedno żądanie najwyższego poziomu, które zostało przypisane identyfikator 00000011-...działania . Następnie każde QueryStart zdarzenie rozpoczęło nową gałąź żądania z identyfikatorami 00001011-... działań i 00002011-... odpowiednio. Można zidentyfikować te identyfikatory są elementami podrzędnymi oryginalnego żądania, ponieważ oba zdarzenia początkowe zarejestrowały ich element nadrzędny 00000011-... w polu Powiązany identyfikator działania.

Ponieważ żądania z złożonymi drzewami elementów podrzędnych będą generować wiele różnych identyfikatorów działań, te identyfikatory są zwykle najlepiej analizowane przez narzędzia, a nie próby odtworzenia drzewa ręcznie. Narzędzie PerfView to jedno z narzędzi, które wie, jak korelować zdarzenia z adnotacjami przy użyciu tych identyfikatorów.