Notes
L’accès à cette page nécessite une autorisation. Vous pouvez essayer de vous connecter ou de modifier des répertoires.
L’accès à cette page nécessite une autorisation. Vous pouvez essayer de modifier des répertoires.
Cet article s’applique à : ✔️ .NET Core 3.1 et versions ultérieures ✔️ .NET Framework 4.5 et versions ultérieures
Ce guide explique les ID d’activité, un identificateur facultatif qui peut être journalisé avec chaque événement généré à l’aide de System.Diagnostics.Tracing.EventSource. Pour une introduction, consultez Prise en main d’EventSource.
Le défi de la journalisation du travail en parallèle
Il y a longtemps, une application classique pouvait être simple et mono-thread, ce qui facilite la journalisation. Vous pouvez écrire chaque étape dans un fichier journal dans l’ordre, puis lire le journal exactement dans l’ordre dans lequel il a été écrit pour comprendre ce qui s’est passé. Si l’application a traité les requêtes, une seule requête a été traitée à la fois. Tous les messages de journal pour la demande A sont imprimés dans l’ordre, puis tous les messages pour B, et ainsi de suite. Lorsque les applications deviennent multithreads, cette stratégie ne fonctionne plus, car plusieurs requêtes sont gérées en même temps. Toutefois, si chaque requête est affectée à un thread unique qui le traite entièrement, vous pouvez résoudre le problème en enregistrant un ID de thread pour chaque message de journal. Par exemple, une application multithread peut enregistrer :
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
En lisant les ID de thread, vous savez que le thread 12 était en train de traiter la demande A et le thread 190 était en train de traiter la demande B. Par conséquent, le message « erreuruh-oh s’est produite » est lié à la requête A. Toutefois, l’accès concurrentiel des applications a continué de croître de manière de plus en plus sophistiquée. Il est désormais courant d’utiliser async et await de sorte qu’une requête unique puisse être gérée partiellement sur de nombreux threads différents avant la fin du travail. Les ID de thread ne sont plus suffisants pour mettre en corrélation tous les messages générés pour une demande. Les ID d’activité résolvent ce problème. Ils fournissent un identificateur de grain plus fin qui peut suivre des requêtes individuelles ou des parties de requêtes, indépendamment du fait que le travail est réparti sur différents threads.
Remarque
Le concept d’ID d’activité mentionné ici n’est pas identique à System.Diagnostics.Tracing.Activity, malgré le nommage similaire.
Suivi du travail à l’aide d’un ID d’activité
Vous pouvez exécuter le code ci-dessous pour afficher le suivi des activités en action.
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();
}
}
}
}
Lors de l’exécution, ce code imprime la sortie :
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
Remarque
Il existe un problème connu où le débogueur Visual Studio peut entraîner la génération d’ID d’activité non valides. N’exécutez pas cet exemple sous le débogueur ou définissez un point d’arrêt au début de Main et évaluez l’expression « System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false » dans la fenêtre immédiate avant de continuer à contourner le problème.
À l’aide des ID d’activité, vous pouvez voir que tous les messages de l’élément de travail A ont un ID 00000011-... et tous les messages de l’élément de travail B ont l’ID 00000012-.... Les deux éléments de travail ont d'abord effectué un certain travail sur le thread numéro 21256, mais chacun d'entre eux a continué leur travail sur des threads distincts 11348 et 14728. Essayer de suivre la requête uniquement avec les identifiants de thread n'aurait pas fonctionné.
EventSource a une heuristique automatique où la définition d’un événement nommé _Something_Start suivi immédiatement par un autre événement nommé _Something_Stop est considéré comme le début et l’arrêt d’une unité de travail. La journalisation de l’événement de démarrage d’une nouvelle unité de travail crée un ID d’activité et commence à journaliser tous les événements sur le même thread avec cet ID d’activité jusqu’à ce que l’événement d’arrêt soit journalisé. L’ID suit également automatiquement le flux de contrôle asynchrone lors de l’utilisation de async et await. Bien que nous vous recommandons d’utiliser les suffixes de nommage Start/Stop, vous pouvez nommer les événements comme vous le souhaitez en les annotant explicitement à l’aide de la EventAttribute.Opcode propriété. Définissez le premier événement sur EventOpcode.Start et le deuxième sur EventOpcode.Stop.
Enregistrer les requêtes qui exécutent des travaux parallèles
Parfois, une seule requête peut effectuer différentes parties de son travail en parallèle, et vous souhaitez regrouper tous les événements de journal et les sous-parties. L’exemple ci-dessous simule une requête qui effectue deux requêtes de base de données en parallèle, puis effectue un traitement sur le résultat de chaque requête. Vous souhaitez isoler le travail de chaque requête, mais également comprendre quelles requêtes appartiennent à la même requête lorsque de nombreuses requêtes simultanées peuvent être en cours d’exécution. Il s’agit d’une arborescence dans laquelle chaque requête de niveau supérieur est une racine et les sous-parties de travail sont des branches. Chaque nœud de l’arborescence obtient son propre ID d’activité et le premier événement enregistré avec le nouvel ID d’activité enfant enregistre un champ supplémentaire appelé ID d’activité associé pour décrire son parent.
Exécutez le code ci-dessous :
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();
}
}
}
}
Cet exemple imprime la sortie, par exemple :
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
Cet exemple n’a exécuté qu’une seule requête de niveau supérieur, qui a été affectée à l’ID 00000011-...d’activité . Ensuite, chaque QueryStart événement a commencé une nouvelle branche de la requête avec les ID d'activité 00001011-... et 00002011-..., respectivement. Vous pouvez identifier ces ID qui sont des enfants de la demande d'origine, car les deux événements initiateurs ont enregistré leur ID parent 00000011-... dans le champ ID d’activité associé.
Remarque
Vous avez peut-être remarqué que les valeurs numériques des ID ont des modèles clairs entre le parent et l’enfant et ne sont pas aléatoires. Bien qu’il puisse aider à repérer visuellement la relation dans des cas simples, il est préférable que les outils ne s’appuient pas sur cela et traitent les ID comme des identificateurs opaques. À mesure que le niveau d’imbrication augmente, le modèle d’octets change. L’utilisation du champ ID d’activité associé est la meilleure façon de garantir que les outils fonctionnent de manière fiable, quel que soit le niveau d’imbrication.
Étant donné que les requêtes avec des arborescences complexes d’éléments de sous-travail génèrent de nombreux ID d’activité différents, il vaut mieux analyser ces ID à l'aide d’outils plutôt que d'essayer de reconstruire l’arbre manuellement. PerfView est un outil qui sait comment mettre en corrélation les événements annotés avec ces ID.
Collaborer avec nous sur GitHub
La source de ce contenu se trouve sur GitHub, où vous pouvez également créer et examiner les problèmes et les demandes de tirage. Pour plus d’informations, consultez notre guide du contributeur.
