ID aktivit EventSource
Tento článek se vztahuje na: ✔️ .NET Core 3.1 a novější verze ✔️ .NET Framework 4.5 a novější verze
Tato příručka vysvětluje ID aktivit, volitelný identifikátor, který lze protokolovat s každou událostí vygenerovanou pomocí System.Diagnostics.Tracing.EventSource. Úvod najdete v tématu Začínáme s EventSource.
Výzva protokolování souběžné práce
Před dlouhou dobou může být typická aplikace jednoduchá a jednovláknová, což usnadňuje protokolování. Každý krok můžete zapsat do souboru protokolu v daném pořadí a pak protokol přečíst přesně v pořadí, ve kterém byl zapsán, abyste pochopili, co se stalo. Pokud aplikace zpracovávala požadavky, pak se najednou zpracovala jenom jedna žádost. Všechny zprávy protokolu pro žádost A se vytisknou v pořadí, pak všechny zprávy pro B a tak dále. Když se aplikace stanou více vlákny, která strategie přestane fungovat, protože současně zpracovává více požadavků. Pokud je ale každý požadavek přiřazený k jednomu vláknu, které ho zpracovává úplně, můžete problém vyřešit tak, že zaznamenáte ID vlákna pro každou zprávu protokolu. Aplikace s více vlákny může například protokolovat:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Čtením ID vláken víte, že vlákno 12 zpracovávalo požadavek A a vlákno 190 zpracovávalo požadavek B, a proto zpráva "uh-oh došlo k chybě" související s žádostí A. Souběžnost aplikací ale stále roste stále propracovanější. Teď je běžné používat async a await proto je možné jeden požadavek zpracovat částečně na mnoha různých vláknech před dokončením práce. ID vláken už nestačí ke korelaci všech zpráv vytvořených pro jeden požadavek. ID aktivit tento problém řeší. Poskytují jemně odstupňovaný identifikátor, který může sledovat jednotlivé požadavky nebo části požadavků bez ohledu na to, jestli je práce rozložena mezi různá vlákna.
Poznámka:
Koncept ID aktivity, na který se odkazuje, není stejný jako System.Diagnostics.Tracing.Activity, i přes podobné pojmenování.
Sledování práce pomocí ID aktivity
Spuštěním následujícího kódu můžete zobrazit sledování aktivit v akci.
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();
}
}
}
}
Při spuštění tento kód vytiskne výstup:
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
Poznámka:
Existuje známý problém, kdy ladicí program sady Visual Studio může způsobit vygenerování neplatných ID aktivit. Tuto ukázku nespustíte pod ladicím programem nebo nastavte zarážku na začátku main a vyhodnoťte výraz System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false v bezprostředním okně, než budete pokračovat v řešení problému.
Pomocí ID aktivit můžete vidět, že všechny zprávy pro pracovní položku A mají ID 00000011-... a všechny zprávy pro pracovní položku B mají ID 00000012-.... Obě pracovní položky nejprve fungovaly na vlákně 21256, ale pak každá z nich pokračovala v práci na samostatných vláknech fondu vláken 11348 a 14728, takže pokus sledovat požadavek pouze s ID vláken by nefungoval.
EventSource má automatickou heuristiku, kdy definování události s názvem _Something_Start následované okamžitou jinou událostí s názvem _Something_Stop se považuje za začátek a zastavení jednotky práce. Protokolování počáteční události pro novou jednotku práce vytvoří nové ID aktivity a začne protokolovat všechny události ve stejném vlákně s TÍMTO ID aktivity, dokud se událost zastavení nezaprotokoluje. ID také automaticky sleduje asynchronní tok řízení při použití async a await. I když doporučujeme používat přípony pro pojmenování Start/Stop, můžete události pojmenovat libovolným způsobem tak, že je explicitně označíte pomocí EventAttribute.Opcode vlastnosti. Nastavte první událost na EventOpcode.Start hodnotu a druhou na EventOpcode.Stophodnotu .
Požadavky protokolu, které fungují paralelně
Někdy může jeden požadavek paralelně provádět různé části své práce a vy chcete seskupit všechny události protokolu a dílčí části. Následující příklad simuluje požadavek, který paralelně provede dva databázové dotazy a pak provede zpracování výsledku každého dotazu. Chcete izolovat práci pro každý dotaz, ale také pochopit, které dotazy patří do stejného požadavku, když může být spuštěno mnoho souběžných požadavků. Modeluje se jako strom, kde každý požadavek nejvyšší úrovně je kořenem a potom podportiony práce jsou větve. Každý uzel ve stromu získá vlastní ID aktivity a první událost zaprotokolovaná s novým ID podřízené aktivity zaznamená další pole s názvem Související ID aktivity, které popisuje jeho nadřazený objekt.
Spusťte následující kód:
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();
}
}
}
}
Tento příklad vytiskne výstup, například:
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
Tento příklad spustil pouze jeden požadavek nejvyšší úrovně, který byl přiřazen ID 00000011-...aktivity . Pak každá QueryStart událost zahájila novou větev požadavku s ID 00001011-... aktivit a 00002011-... v uvedeném pořadí. Tato ID jsou podřízená původnímu požadavku, protože obě počáteční události protokolovaly nadřazené položky 00000011-... v poli ID související aktivity.
Poznámka:
Možná jste si všimli, že číselné hodnoty ID mají určité jasné vzory mezi nadřazeným a podřízeným objektem a nejsou náhodné. I když může pomoct vizuálně odhalit relaci v jednoduchých případech, je nejvhodnější pro nástroje, které na to nespoléhají a považují ID za neprůrazné identifikátory. S tím, jak úroveň vnoření roste hlouběji, se změní vzor bajtů. Použití pole Související ID aktivity je nejlepším způsobem, jak zajistit spolehlivé fungování nástrojů bez ohledu na úroveň vnoření.
Vzhledem k tomu, že požadavky se složitými stromy položek dílčích úkolů generují mnoho různých ID aktivit, jsou tato ID obvykle nejvhodnější analyzovat nástroji a nepokouší se strom rekonstruovat ručně. PerfView je jeden nástroj, který ví, jak korelovat události anotované s těmito ID.
