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.
Uwaga
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
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 lub ustaw punkt przerwania na początku main i oceń wyrażenie "System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false" w bezpośrednim oknie przed kontynuowaniem pracy nad problemem.
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.
Uwaga
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 wizualnie wykryciu relacji w prostych przypadkach, najlepiej jest, aby narzędzia nie polegały na tym i traktować identyfikatory jako nieprzezroczyste identyfikatory. Wraz ze wzrostem poziomu zagnieżdżania wzorzec bajtów ulegnie zmianie. Użycie pola Identyfikator działania powiązanego jest najlepszym sposobem zapewnienia niezawodnej pracy narzędzi niezależnie od poziomu zagnieżdż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.
