Gebeurtenisbronactiviteit-id's
Dit artikel is van toepassing op: ✔️ .NET Core 3.1 en latere versies ✔️ .NET Framework 4.5 en latere versies
In deze handleiding worden activiteit-id's uitgelegd, een optionele id die kan worden geregistreerd met elke gebeurtenis die wordt gegenereerd met behulp van System.Diagnostics.Tracing.EventSource. Zie Aan de slag met EventSource voor een inleiding.
De uitdaging van gelijktijdige logboekregistratie
Lang geleden is een typische toepassing mogelijk eenvoudig en één threaded, waardoor logboekregistratie eenvoudig is. U kunt elke stap in een logboekbestand op volgorde schrijven en het logboek vervolgens exact lezen in de volgorde waarin het is geschreven om te begrijpen wat er is gebeurd. Als de app aanvragen heeft verwerkt, is er slechts één aanvraag tegelijk verwerkt. Alle logboekberichten voor aanvraag A worden op volgorde afgedrukt, vervolgens alle berichten voor B, enzovoort. Wanneer apps meerdere threads worden, werkt die strategie niet meer omdat meerdere aanvragen tegelijkertijd worden verwerkt. Als elke aanvraag echter wordt toegewezen aan één thread die deze volledig verwerkt, kunt u het probleem oplossen door een thread-id voor elk logboekbericht op te nemen. Een app met meerdere threads kan bijvoorbeeld het volgende registreren:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Door de thread-id's te lezen weet u dat thread 12 aanvraag A verwerkt en thread 190 aanvraag B verwerkt, waardoor het bericht 'uh-oh fout is opgetreden' met betrekking tot aanvraag A. De gelijktijdigheid van toepassingen is echter steeds geavanceerder geworden. Het is nu gebruikelijk om te gebruiken async en await zodat één aanvraag gedeeltelijk kan worden verwerkt op veel verschillende threads voordat het werk is voltooid. Thread-id's zijn niet langer voldoende om alle berichten die voor één aanvraag worden geproduceerd, te correleren. Met activiteits-id's wordt dit probleem opgelost. Ze bieden een nauwkeurigere id waarmee afzonderlijke aanvragen of delen van aanvragen kunnen worden bijgehouden, ongeacht of het werk wordt verspreid over verschillende threads.
Notitie
Het hier genoemde concept activiteits-id is niet hetzelfde als het System.Diagnostics.Tracing.Activity, ondanks de vergelijkbare naamgeving.
Werk bijhouden met behulp van een activiteits-id
U kunt de onderstaande code uitvoeren om activiteiten bij te houden in actie.
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();
}
}
}
}
Wanneer deze code wordt uitgevoerd, wordt de uitvoer afgedrukt:
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
Notitie
Er is een bekend probleem waarbij visual Studio-foutopsporingsprogramma ertoe kan leiden dat ongeldige activiteits-id's worden gegenereerd. Voer dit voorbeeld niet uit onder het foutopsporingsprogramma of stel een onderbrekingspunt in aan het begin van Main en evalueer de expressie System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false in het directe venster voordat u verdergaat met het probleem.
Met behulp van de activiteit-id's kunt u zien dat alle berichten voor werkitem A id hebben 00000011-... en alle berichten voor werkitem B id hebben 00000012-.... Beide werkitems werkten eerst aan thread 21256, maar daarna hebben ze hun werk voortgezet op afzonderlijke threadpoolthreads 11348 en 14728, dus het bijhouden van de aanvraag alleen met thread-id's zou niet hebben gewerkt.
EventSource heeft een automatische heuristiek waarbij het definiëren van een gebeurtenis met de naam _Something_Start onmiddellijk gevolgd door een andere gebeurtenis met de naam _Something_Stop wordt beschouwd als het begin en einde van een werkeenheid. Als u de begingebeurtenis voor een nieuwe werkeenheid aanmeldt, wordt een nieuwe activiteits-id gemaakt en worden alle gebeurtenissen in dezelfde thread geregistreerd met die activiteits-id totdat de stopgebeurtenis is geregistreerd. De id volgt ook automatisch de asynchrone controlestroom bij gebruik async en await. Hoewel u wordt aangeraden de achtervoegsels voor naamgeving starten/stoppen te gebruiken, kunt u de gebeurtenissen een naam geven die u leuk vindt door ze expliciet aantekeningen te maken met behulp van de EventAttribute.Opcode eigenschap. Stel de eerste gebeurtenis in op EventOpcode.Start en de tweede op EventOpcode.Stop.
Logboekaanvragen die parallel werken
Soms kan één aanvraag verschillende onderdelen van het werk parallel uitvoeren en wilt u alle logboekgebeurtenissen en de subonderdelen groeperen. In het onderstaande voorbeeld wordt een aanvraag gesimuleerd die twee databasequery's parallel uitvoert en vervolgens een verwerking uitvoert op het resultaat van elke query. U wilt het werk voor elke query isoleren, maar ook begrijpen welke query's deel uitmaken van dezelfde aanvraag wanneer veel gelijktijdige aanvragen kunnen worden uitgevoerd. Dit is gemodelleerd als een structuur waarin elke aanvraag op het hoogste niveau een hoofdmap is en vervolgens subporties van werk vertakkingen zijn. Elk knooppunt in de structuur krijgt een eigen activiteits-id en de eerste gebeurtenis die is geregistreerd met de nieuwe onderliggende activiteit-id registreert een extra veld met de naam Gerelateerde activiteits-id om het bovenliggende item te beschrijven.
Voer de volgende code uit:
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();
}
}
}
}
In dit voorbeeld wordt uitvoer afgedrukt, zoals:
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
In dit voorbeeld is slechts één aanvraag op het hoogste niveau uitgevoerd, waaraan activiteits-id 00000011-...is toegewezen. Vervolgens begon elke QueryStart gebeurtenis een nieuwe vertakking van de aanvraag met respectievelijk activiteit-id's 00001011-...00002011-... . U kunt deze id's identificeren als onderliggende items van de oorspronkelijke aanvraag, omdat beide begingebeurtenissen hun bovenliggende 00000011-... item hebben geregistreerd in het veld Gerelateerde activiteits-id.
Notitie
Mogelijk hebt u gezien dat de numerieke waarden van de id's enkele duidelijke patronen hebben tussen bovenliggende en onderliggende waarden en niet willekeurig zijn. Hoewel het kan helpen bij het visueel herkennen van de relatie in eenvoudige gevallen, is het het beste voor hulpprogramma's die niet op deze manier kunnen vertrouwen en de id's als ondoorzichtige id's kunnen behandelen. Naarmate het nestniveau dieper groeit, verandert het bytepatroon. Het gebruik van het veld Gerelateerde activiteits-id is de beste manier om ervoor te zorgen dat hulpprogramma's betrouwbaar werken, ongeacht het nestniveau.
Omdat aanvragen met complexe structuur van subwerkitems veel verschillende activiteits-id's genereren, worden deze id's meestal het beste geparseerd door hulpprogramma's in plaats van de structuur met de hand te reconstrueren. PerfView is één hulpprogramma dat weet hoe gebeurtenissen met een aantekening met deze id's moeten worden gecorreleerd.
