Partager via

ID d’activité EventSource

  • Article

Cet article s’applique à : ✔️ .NET Core 3.1 et versions ultérieures✔️ .NET Framework 4.5 et versions ultérieures

Ce guide décrit 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 avec EventSource.

Le défi de la journalisation du travail simultané

Il y a longtemps de cela, les applications étaient classiquement simples et monothread, ce qui rendait la journalisation simple. On pouvait écrire chaque étape dans un fichier journal dans l’ordre, puis lire le journal exactement dans le même ordre pour comprendre ce qui s’était passé. Si l’application gérait des demandes, celles-ci étaient traitées une par une. Tous les messages de journal de la demande A étaient imprimés dans l’ordre, suivis de tous les messages pour B, et ainsi de suite. Une fois les applications devenues multithread, cette stratégie n’a plus fonctionné, car plusieurs demandes étaient gérées en même temps. Toutefois, si chaque demande était assignée à un seul thread qui la traitait entièrement, vous pouviez résoudre le problème en enregistrant un ID de thread pour chaque message de journal. Par exemple, une application multithread pouvait journaliser les informations suivantes :

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 saviez que le thread 12 traitait la demande A, et le thread 190 la demande B. Par conséquent, le message « uh-oh error happened » concernait la demande A. Toutefois, la concurrence des applications a continué de croître et de se complexifier. Il est désormais courant d’utiliser async et await de sorte qu’une seule demande puisse être gérée partiellement sur de nombreux threads différents avant que le travail ne soit terminé. Les ID de thread ne sont plus suffisants pour mettre en corrélation tous les messages générés sur une demande. Les ID d’activité permettent de résoudre ce problème. Ils fournissent un identificateur plus fin capable de suivre des demandes individuelles, ou des parties de demandes, même si le travail soit réparti entre différents threads.

Notes

Le concept d’ID d’activité mentionné ici n’est pas identique à System.Diagnostics.Tracing.Activity, malgré un nom similaire.

Suivi du travail à l’aide d’un ID d’activité

Vous pouvez exécuter le code ci-dessous pour voir le Suivi de l’activité 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();
            }
        }
    }
}

Une fois exécuté, ce code imprime la sortie suivante :

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

Notes

Il existe un problème connu selon lequel 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 possèdent un ID 00000011-..., et tous les messages pour l’élément de travail B un ID 00000012-.... Les deux éléments de travail ont d’abord opéré sur le thread 21256, mais chacun d’eux a ensuite poursuivi son travail sur des threads de pools de threads distincts (11348 et 14728). Par conséquent, il n’aurait pas été possible de suivre la demande avec seulement des ID de thread.

EventSource possède une heuristique automatique selon laquelle un événement nommé _Something_Start suivi immédiatement d’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ébut d’une nouvelle unité de travail a pour effet de créer un ID d’activité et de commencer l’enregistrement de 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 lorsque async et await sont utilisés. Bien qu’il soit recommandé d’employer les suffixes d’affectation de noms Start et Stop, vous pouvez nommer les événements comme vous le souhaitez en les annotant explicitement à l’aide de la propriété EventAttribute.Opcode. Définissez le premier événement sur EventOpcode.Start et le second sur EventOpcode.Stop.

Journalisation des demandes qui effectuent un travail parallèle

Il arrive qu’une seule demande effectue différentes parties de son travail en parallèle. L’objectif est alors de regrouper tous les événements de journal et toutes les sous-parties. L’exemple suivant simule une demande qui effectue deux requêtes de base de données en parallèle, puis un traitement sur le résultat de chaque requête. Vous souhaitez isoler le travail pour chaque requête, mais également comprendre quelles requêtes appartiennent à la même demande lorsque de nombreuses demandes simultanées sont en cours d’exécution. Ces informations sont modélisées sous la forme d’une arborescence dont les demandes de niveau supérieur constituent les racines, et les sous-parties de travail les branches. Chaque nœud de l’arborescence possède son propre ID d’activité. Par ailleurs, 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 suivante :

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 demande de niveau supérieur, qui possède l’ID d’activité 00000011-.... Ensuite, chaque événement QueryStart a commencé une nouvelle branche de la demande avec les ID d’activité 00001011-... et 00002011-.... Il est possible d’identifier que ces ID représentent les enfants de la demande d’origine, car les deux événements de début ont enregistré leur parent 00000011-... dans le champ ID d’activité associé.

Notes

Comme vous l’avez peut-être remarqué, la valeur numérique des ID présente un modèle clair entre le parent et l’enfant et n’est pas aléatoire. Bien que cela puisse aider à repérer visuellement la relation dans des cas simples, il est préférable que les outils ne s’appuient pas sur ce modèle et traitent les ID comme des identificateurs opaques. À mesure que le niveau d’imbrication augmente, le modèle d’octets change. Le champ ID d’activité associé constitue 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 demandes présentant des arborescences complexes de sous-éléments de travail génèrent de nombreux ID d’activité différents, il est généralement plus efficace d’analyser ces ID avec des outils plutôt que d’essayer de reconstruire l’arborescence à la main. L’outil PerfView sait mettre en corrélation les événements annotés avec ces ID.