EventSource-aktivitets-ID:t
Den här artikeln gäller för: ✔️ .NET Core 3.1 och senare versioner✔️ .NET Framework 4.5 och senare versioner
Den här guiden förklarar aktivitets-ID:t, en valfri identifierare som kan loggas med varje händelse som genereras med hjälp av System.Diagnostics.Tracing.EventSource. En introduktion finns i Komma igång med EventSource.
Utmaningen med att logga samtidigt arbete
För länge sedan kan ett typiskt program ha varit enkelt och enkeltrådat, vilket gör loggning enkelt. Du kan skriva varje steg till en loggfil i ordning och sedan läsa tillbaka loggen exakt i den ordning den skrevs för att förstå vad som hände. Om appen hanterade begäranden hanterades endast en begäran i taget. Alla loggmeddelanden för begäran A skrivs ut i ordning, sedan alla meddelanden för B och så vidare. När appar blir flertrådade fungerar inte strategin längre eftersom flera begäranden hanteras samtidigt. Men om varje begäran tilldelas till en enda tråd som bearbetar den helt kan du lösa problemet genom att registrera ett tråd-ID för varje loggmeddelande. En app med flera trådar kan till exempel logga:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Genom att läsa tråd-ID:n vet du att tråd 12 bearbetade begäran A och tråd 190 bearbetade begäran B, därför meddelandet "uh-oh error happened" relaterade till begäran A. Programkonkurrency har dock fortsatt att växa allt mer sofistikerat. Det är nu vanligt att använda async och await så att en enskild begäran kan hanteras delvis på många olika trådar innan arbetet är klart. Tråd-ID:n räcker inte längre för att korrelera alla meddelanden som skapas för en begäran. Aktivitets-ID:t löser det här problemet. De tillhandahåller en finare kornidentifierare som kan spåra enskilda begäranden eller delar av begäranden, oavsett om arbetet är utspritt över olika trådar.
Kommentar
Det aktivitets-ID som avses här är inte detsamma som System.Diagnostics.Tracing.Activity, trots liknande namngivning.
Spåra arbete med hjälp av ett aktivitets-ID
Du kan köra koden nedan för att se Aktivitetsspårning i praktiken.
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();
}
}
}
}
När du kör den här koden skrivs ut utdata:
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
Kommentar
Det finns ett känt problem där Visual Studio-felsökningsprogrammet kan orsaka att ogiltiga aktivitets-ID:er genereras. Kör antingen inte det här exemplet under felsökningsprogrammet eller ange en brytpunkt i början av Main och utvärdera uttrycket "System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false" i det omedelbara fönstret innan du fortsätter att kringgå problemet.
Med hjälp av aktivitets-ID:n kan du se att alla meddelanden för arbetsobjektet A har ID 00000011-... och att alla meddelanden för arbetsobjekt B har ID 00000012-.... Båda arbetsobjekten arbetade först med tråd 21256, men sedan fortsatte var och en av dem sitt arbete med separata trådpooltrådar 11348 och 14728 så att försöka spåra begäran endast med tråd-ID:n skulle inte ha fungerat.
EventSource har en automatisk heuristisk där definitionen av en händelse med namnet _Something_Start följt omedelbart av en annan händelse med namnet _Something_Stop anses vara start och stopp för en arbetsenhet. När du loggar starthändelsen för en ny arbetsenhet skapas ett nytt aktivitets-ID och börjar logga alla händelser i samma tråd med aktivitets-ID:t tills stopphändelsen loggas. ID:t följer också automatiskt asynkront kontrollflöde när du använder async och await. Även om vi rekommenderar att du använder suffixen Start/Sluta namnge kan du namnge händelserna som du vill genom att uttryckligen kommentera dem med hjälp av EventAttribute.Opcode egenskapen . Ange den första händelsen till EventOpcode.Start och den andra till EventOpcode.Stop.
Loggbegäranden som utför parallellt arbete
Ibland kan en enskild begäran utföra olika delar av sitt arbete parallellt och du vill gruppera alla logghändelser och underdelarna. Exemplet nedan simulerar en begäran som utför två databasfrågor parallellt och sedan utför viss bearbetning av resultatet av varje fråga. Du vill isolera arbetet för varje fråga, men också förstå vilka frågor som tillhör samma begäran när många samtidiga begäranden kan köras. Detta modelleras som ett träd där varje begäran på den översta nivån är en rot och sedan underportioner av arbete är grenar. Varje nod i trädet får ett eget aktivitets-ID och den första händelsen som loggas med det nya underordnade aktivitets-ID:t loggar ett extra fält med namnet Relaterat aktivitets-ID för att beskriva dess överordnade.
Kör följande 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();
}
}
}
}
I det här exemplet skrivs ut utdata som:
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
I det här exemplet kördes bara en begäran på den översta nivån, som tilldelades aktivitets-ID 00000011-.... Sedan började varje QueryStart händelse en ny gren av begäran med aktivitets-ID 00001011-... :n respektive 00002011-... . Du kan identifiera att dessa ID:n är underordnade den ursprungliga begäran eftersom båda starthändelserna loggade deras överordnade 00000011-... i fältet Relaterat aktivitets-ID.
Kommentar
Du kanske har märkt att de numeriska värdena för ID:n har några tydliga mönster mellan överordnade och underordnade och inte är slumpmässiga. Även om det kan hjälpa dig att upptäcka relationen visuellt i enkla fall är det bäst att verktygen inte förlitar sig på detta och behandlar ID:erna som ogenomskinliga identifierare. När kapslingsnivån växer djupare ändras bytemönstret. Att använda fältet Relaterat aktivitets-ID är det bästa sättet att se till att verktygen fungerar tillförlitligt oavsett kapslingsnivå.
Eftersom begäranden med komplexa träd av underarbetesobjekt genererar många olika aktivitets-ID:er, tolkas vanligtvis dessa ID:er bäst av verktyg i stället för att försöka rekonstruera trädet för hand. PerfView är ett verktyg som vet hur man korrelerar händelser som kommenterats med dessa ID:er.
