Udostępnij za pośrednictwem

Identyfikatory działań usługi EventSource

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

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 wystąpił błąd" związany z żądaniem A. Jednak współbieżność aplikacji nadal rośnie coraz bardziej wyrafinowana. Obecnie powszechne jest użycie async i await, aby pojedyncze żądanie mogło być częściowo obsługiwane przez wiele różnych wątków zanim praca zostanie ukończona. 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.

Uwaga / Notatka

Koncepcja identyfikatora działania, o której mowa w tym miejscu, nie jest taka sama jak nazwa System.Diagnostics.Tracing.Activity, pomimo podobnego nazewnictwa.

Ś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

Uwaga / Notatka

Istnieje znany problem polegający na tym, że debuger programu Visual Studio może spowodować wygenerowanie nieprawidłowych identyfikatorów działań. Nie uruchamiaj tego przykładu w debugerze albo ustaw punkt przerwania na początku Main i oceń wyrażenie 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' w oknie natychmiastowym przed kontynuowaniem pracy nad problemem.

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

EventSource ma automatyczną heurystykę, w której zdefiniowanie zdarzenia o nazwie _Something_Start po zdarzeniu _Something_Stop jest uznawane za rozpoczęcie i zakończenie 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 automatycznie podąża za asynchronicznym przepływem sterowania przy użyciu async i await. Chociaż zalecamy korzystanie z sufiksów nazewnictwa Start/Stop, możesz nazwać zdarzenia dowolnie, pod warunkiem że jawnie je zaadnotujesz przy użyciu właściwości EventAttribute.Opcode. Ustaw pierwsze zdarzenie na EventOpcode.Start , a drugi na EventOpcode.Stop.

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

Czasami pojedyncze żądanie może wykonywać różne części swojej pracy równolegle, a Ty chcesz zgrupować wszystkie zdarzenia dziennika i podczęści. 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 korzeniem, a następnie części pracy są gałęziami. Każdy węzeł w drzewie otrzymuje własny identyfikator aktywności, a pierwsze zdarzenie zarejestrowane przy użyciu nowego podrzędnego identyfikatora aktywności rejestruje dodatkowe pole o nazwie Related Activity ID (Powiązany identyfikator aktywności), 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óremu przypisano Identyfikator działania 00000011-.... Następnie każde QueryStart zdarzenie rozpoczęło nową gałąź żądania z identyfikatorami działań 00001011-... i 00002011-... odpowiednio. Można zidentyfikować te identyfikatory jako elementy podrzędne oryginalnego żądania, ponieważ oba zdarzenia początkowe zarejestrowały ich element nadrzędny 00000011-... w polu Identyfikator powiązanej aktywności.

Uwaga / Notatka

Być może zauważysz, że wartości liczbowe identyfikatorów mają pewne jasne wzorce między elementami nadrzędnymi i podrzędnymi i nie są losowe. Chociaż może ona pomóc w wizualnym wykrywaniu relacji w prostych przypadkach, najlepiej, aby narzędzia nie polegały na tym i traktowały identyfikatory jako nieprzezroczyste. Wraz ze wzrostem poziomu zagnieżdżania wzorzec bajtów ulegnie zmianie. Korzystanie z pola Identyfikatora Działania Powiązanego to najlepszy sposób na zapewnienie niezawodnego działania narzędzi, bez względu na poziom zagnieżdżenia.

Ponieważ żądania z złożonymi drzewami elementów podrzędnych będą generować wiele różnych identyfikatorów działań, te identyfikatory zazwyczaj najlepiej jest analizować za pomocą narzędzi, zamiast próbować odtwarzać drzewo ręcznie. Narzędzie PerfView to jedno z narzędzi, które wie, jak korelować zdarzenia z adnotacjami przy użyciu tych identyfikatorów.