ID attività EventSource
Questo articolo si applica a: ✔️ .NET Core 3.1 e versioni successive ✔️ .NET Framework 4.5 e versioni successive
Questa guida illustra gli ID attività, un identificatore facoltativo che può essere registrato con ogni evento generato tramite System.Diagnostics.Tracing.EventSource. Per un'introduzione, fai riferimento a Introduzione a EventSource.
La sfida di registrare il lavoro simultaneo
Molto tempo fa, una tipica applicazione potrebbe essere stata semplice e a thread singolo, cosa che rende la registrazione semplice. È possibile scrivere ogni passaggio in un file di log in ordine e quindi leggere di nuovo il log esattamente nell'ordine in cui è stato scritto per comprendere cosa è successo. Se l'app ha gestito le richieste, è stata gestita una sola richiesta alla volta. Tutti i messaggi di log per la richiesta A verranno stampati in ordine, quindi tutti i messaggi per B e così via. Quando le app diventano multithread questa strategia non funziona più perché più richieste vengono gestite contemporaneamente. Tuttavia, se ogni richiesta viene assegnata a un singolo thread che la elabora interamente, è possibile risolvere il problema registrando un ID thread per ogni messaggio di log. Ad esempio, un'app multithread potrebbe registrare:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Leggendo gli ID del thread si sa che il thread 12 stava elaborando la richiesta A e il thread 190 stava elaborando la richiesta B, quindi il messaggio “Oh-oh si è verificato un errore” era correlato alla richiesta A. Tuttavia, la concorrenza delle applicazioni ha continuato a diventare sempre più complessa. È ora comune usare async e await in modo che una singola richiesta possa essere gestita parzialmente in molti thread diversi prima del completamento del lavoro. Gli ID thread non sono più sufficienti per correlare tutti i messaggi generati per una richiesta. Gli ID attività risolvono questo problema. Forniscono un identificatore granulare più accurato in grado di tenere traccia delle singole richieste o di parti delle richieste, indipendentemente dal fatto che il lavoro venga distribuito in thread diversi.
Nota
Il concetto di ID attività indicato qui non è uguale a System.Diagnostics.Tracing.Activity, nonostante la denominazione simile.
Rilevamento del lavoro con un ID attività
È possibile eseguire il codice seguente per visualizzare il rilevamento delle attività in azione.
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();
}
}
}
}
Quando viene eseguito, questo codice stampa l'output:
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
Nota
Esiste un problema noto per cui il debugger di Visual Studio può causare la generazione di ID attività non validi. Non eseguire questo esempio nel debugger o imposta un punto di interruzione all'inizio di Main e valuta l'espressione 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' nella finestra immediata prima di continuare a risolvere il problema.
Usando gli ID attività è possibile vedere che tutti i messaggi per l'elemento di lavoro A hanno ID 00000011-... e tutti i messaggi per l'elemento di lavoro B hanno ID 00000012-.... Entrambi gli elementi di lavoro hanno prima eseguito alcune operazioni sul thread 21256, ma ognuno di essi ha continuato il proprio lavoro su thread di pool di thread separati 11348 e 14728, quindi il tentativo di tenere traccia della richiesta solo con ID thread non avrebbe funzionato.
EventSource ha un'euristica automatica in cui la definizione di un evento denominato _Something_Start seguito immediatamente vicino a un altro evento denominato _Something_Stop viene considerato l'inizio e l'arresto di un'unità di lavoro. La registrazione dell'evento di avvio per una nuova unità di lavoro crea un nuovo ID attività e inizia a registrare tutti gli eventi nello stesso thread con tale ID attività fino a quando non viene registrato l'evento di arresto. L'ID segue automaticamente anche il flusso di controllo asincrono quando si usa async e await. Sebbene sia consigliabile usare i suffissi di denominazione Start/Stop, è possibile denominare gli eventi in modo esplicito annotandoli usando la proprietà EventAttribute.Opcode. Impostare il primo evento su EventOpcode.Start e il secondo su EventOpcode.Stop.
Richieste di log che eseguono operazioni parallele
A volte una singola richiesta può eseguire parti diverse del lavoro in parallelo ed è possibile raggruppare tutti gli eventi del log e le sottoparti. L'esempio seguente simula una richiesta che esegue due query di database in parallelo e quindi esegue alcune elaborazioni sul risultato di ogni query. Si vuole isolare il lavoro per ogni query, ma anche comprendere quali query appartengono alla stessa richiesta quando è possibile eseguire molte richieste simultanee. Il modello è una struttura ad albero in cui ogni richiesta di primo livello è una radice e quindi le sottoporzioni di lavoro sono rami. Ogni nodo dell'albero ottiene il proprio ID attività e il primo evento registrato con il nuovo ID attività figlio registra un campo aggiuntivo denominato ID attività correlato per descrivere il relativo elemento padre.
Eseguire il codice seguente:
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 questo esempio viene stampato l'output, ad esempio:
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 questo esempio è stata eseguita una sola richiesta di primo livello, a cui è stato assegnato l'ID attività 00000011-.... Quindi ogni evento QueryStart ha iniziato un nuovo ramo della richiesta rispettivamente con ID attività 00001011-... e 00002011-.... È possibile identificare questi ID come elementi figlio della richiesta originale perché entrambi gli eventi di avvio hanno registrato il padre 00000011-... nel campo ID attività correlata.
Nota
È possibile che i valori numerici degli ID abbiano alcuni modelli chiari tra padre e figlio e non siano casuali. Anche se può aiutare a individuare visivamente la relazione in casi semplici, è preferibile che gli strumenti non si basino su questo e considerino gli ID come identificatori opachi. Man mano che il livello di annidamento va più in profondità, il modello di byte cambia. L'uso del campo ID attività correlata è il modo migliore per garantire che gli strumenti funzionino in modo affidabile indipendentemente dal livello di annidamento.
Poiché le richieste con alberi complessi di elementi del sottolavoro genereranno molti ID attività diversi, questi ID sono in genere meglio analizzati dagli strumenti rispetto a quando si tenta di ricostruire l'albero a mano. PerfView è uno strumento che sa correlare gli eventi annotati con questi ID.
