Event Tracing for Windows (ETW) et .NET Core

Event Tracing for Windows est un framework pour gérer les traces de diagnostic sur Windows

Il est mature depuis de nombreuses années et est intimement lié au système d’exploitation. Il est supporté depuis longtemps sur le framework .NET (à des niveaux d’évolution différents au fil de ses versions).

Voici un extrait issu d’une documentation de Microsoft[1]:

Event tracing for Windows (ETW) is a high-performance, low-overhead, scalable tracing system provided by Windows operating systems. It supplements the profiling and debugging support provided by the .NET Framework and can be used to troubleshoot a variety of scenarios.

Le support d’ETW arrive progressivement sur .NET Core, grâce à de nouveaux packages Nuget. Un état des lieux m’a paru être une bonne idée pour ma propre veille techno. Cet article n’est qu’un survol de ETW. Je tente de rester simple mais aussi concret sur des cas d’utilisation applicables sur des versions récentes de .NET Core (2.2) et .NET Framework (a priori 4.6). Si j’ai réussi à dégrossir le sujet, mon objectif est accompli.

La mise en oeuvre ETW n’est pas aussi simple qu’une librairie plus commune

Comme Log4Net et NLog pour des traces non structurées (de simples chaînes de caractères, donc très facile à développer), et comme Serilog pour des traces structurées.

C’est parce que ETW n’est pas directement comparable à une librairie pour les logs applicatifs.

La force d’une librairie comme NLog et Log4Net (personnellement je préfère NLog) est de pouvoir configurer l’écriture des logs applicatifs très simplement vers différents canaux (fichiers, console, email…) à partir d’une seule interface au niveau du code. Autrement dit, le code ne sait pas que les traces générées seront écrites dans un fichier ou envoyées par email. Et cette « destinée » des traces reste typiquement modifiable a posteriori via un fichier de configuration. C’est à la fois flexible et simple car la librairie ne dépend pas d’une infrastructure extérieure comme ETW.

Serilog, très populaire ces dernières années, est une solution intermédiaire qui facilite l’exploitation des logs via des outils, par exemple avec la suite ElasticSearch et Kibana – mais qui est donc plus élaboré à mettre en oeuvre pour en tirer réellement parti.

ETW a contrario ne gère pas directement la destination des traces (qui sont des événements avec des propriétés typées). C’est davantage une forme de bus spécialisé dans les traces de diagnostics, qui dépend d’une infrastructure extérieure au processus, différente d’une plateforme à une autre (d’où un support natif et complet sur Windows et partiel ailleurs).

Le framework est conçu autour des principaux éléments suivants[2]:

des événements structurés (ce ne sont pas de simples chaînes de caractères mais plutôt un groupe de propriétés typées) qui forment un véritable contrat entre producteurs et consommateurs.
des producteurs (émetteurs d’événements, appelés Source ou Provider, correspond à la classe .NET nommée EventSource)
des consommateurs (récepteurs d’événements, appelés Listeners ou Consumers, correspond à la classe .NET (mal) nommée ETWTraceEventSource)
des contrôleurs (qui activent / désactivent l’émission effective et le branchement des récepteurs, correspond à la classe .NET nommée TraceEventSession).

L’idée est que si aucun consommateur n’est relié à un producteur, l’événement émis est ignoré et ne coute (presque) rien. De plus, le contrôleur peut agir depuis l’extérieur du processus, pendant son fonctionnement. Il y a donc un contrôle beaucoup plus dynamique qu’avec une librairie de traces plus classique, ce qui peut être intéressant pour le diagnostic d’un système en production.

Il y a deux mises en oeuvre typiques:

Tous les acteurs (producteurs, consommateurs, contrôleurs) sont orchestrés en temps réel au sein du même processus. C’est par exemple le cas d’une application qui utilise ETW pour gérer l’affichage de ses propres événements dans la console ou l’écriture de fichiers de traces.
Le(s) producteur(s) (providers) sont au sein d’un processus source, les consommateurs et contrôleurs sont ensembles dans un autre processus. C’est le cas d’une application qui n’écoute pas ses propres traces (pas d’affichage dans la console, pas de persistence dans des fichiers…). Les traces peuvent être écoutées en opt-in depuis l’extérieur du processus, soit en temps réel (= callback d’une méthode), soit vers un fichier (que vous pouvez exploiter a posteriori). La documentation de ETW parle de temps réel lorsque c’est votre code qui consomme les événements. Si vous branchez un fichier (au format propriétaire et binaire d’extension .ETL), ce n’est plus dit en temps réel car vous exploiterez les traces de manière différée en lisant ce fichier (avec la classe TraceLog, après la fin de la collecte). Question de perspective.

Bien que l’architecture d’ETW soit une forme spécialisée de bus, il est déconseillé aux plus créatifs d’entre-nous de l’utiliser comme mécanisme de communication car il n’y a pas de garantie de délivrance des événements (ni des commandes envoyées par les contrôleurs vers les providers)[3].

ETW ne remplace pas les logs applicatifs

Par logs applicatifs, j’entends la pratique répandue de persister les traces applicatives sous forme textuelle, dans un fichier .log en général ou bien dans la console qu’on peut ensuite router vers un fichier, en fonction du type d’application.

Si ETW ne gère pas directement la destination des traces, et donc l’écriture de traces dans un fichier ou dans la console par exemple, il est possible de mettre en oeuvre ce routage sur la base d’ETW.

Du point de vue des créateurs de ETW (point de vue que j’imagine), le principe serait le suivant:

l’application émet des événements de diagnostic via ETW.
l’application consomme ses propres traces pour les répéter vers un logger comme Serilog ou NLog.

On peut ainsi obtenir les logs applicatifs souhaités, ayant pour source ETW. C’est perfectionné et flexible. Comme il s’agit d’une collecte in-process, c’est déjà bien supporté sur .NET Core.

Noter enfin qu’un modèle alternatif est plus répandu: l’application émet ses traces vers un logger « classique » comme Serilog ou NLog (via une interface pour ne pas dépendre directement de la librairie tierce), et les traces sont ensuite émises vers un EventSource pour ETW. Ce serait le point de vue (que j’imagine) des créateurs de ces librairies. Evidemment, on a moins de maîtrise sur le contrat final des événements émis vers ETW de cette façon car vous n’orchestrez plus vraiment ETW mais Serilog. Il me semble que le modèle le plus perfectionné est le premier avec ETW comme source: émission directe des événements via un EventSource auquel on peut brancher un EventListener in-process pour répéter vers une librairie de logs tel que NLog ou Serilog selon les besoins. C’est aussi moins pratique à développer car vous orchestrez surtout ETW (plus verbeux et sujet à erreurs) et Serilog dans une moindre mesure. Rien n’empêche techniquement de mixer les deux, au prix d’une complexité accrue (la compréhension générale sera plus difficile). Au final, cela dépend surtout de la façon dont vous souhaitez exploiter les traces. L’intégration de Serilog avec Elastic Search et Kibana est par exemple très accessible si Kibana est effectivement votre cible. L’expérience utilisateur entre l’exploitation de traces structurées dans un dashboard Kibana et de traces non structurées dans un fichier de logs plus « old school » est aussi très différente. Pendant le développement de l’application, vous préférerez a priori les logs non structurés, plus rapides à développer et à lire, sans dépendre de toute une infrastructure comme ELK. Kibana est pensé pour le monitoring d’une application pendant son exploitation en production. Il est bien sûr possible et même facile de générer des traces non structurées (faciles à lire dans un fichier texte ou la console) à partir de traces structurées (donc de Serilog ou ETW). Cela requiert simplement plus de travail (c’est essentiellement un adaptateur entre deux mécanismes de traces). A cause de cette charge de travail sûrement sous-estimée en amont, la plupart des projets que j’ai rencontré ne vont pas au bout des choses pour couvrir ces deux besoins de façon uniforme.

Devrait-on toujours utiliser ETW ?

Comme presque toute question avec le mot « toujours », la réponse pour moi est non. Cela n’est qu’une opinion. Des experts reconnus comme Ben Watson, auteur du livre Writing High-Performance .NET Code, y conseille expressément de toujours utiliser ETW.

Même sans l’utiliser pour les traces de ses applications, savoir utiliser ce framework est un avantage car il donne accès à énormément de données de diagnostic sur Windows et sur un grand nombre de composants tiers (jusque là sur Windows – et potentiellement à terme sur Linux grâce à son intégration dans .NET Core).

Pour l’application la plus classique, la mise en oeuvre de ETW me paraît plus compliquée que nécessaire. Si vous êtes heureux avec NLog, continuez à l’utiliser, c’est simple et efficace. A contrario, une grande entreprise peut souhaiter que tous ses programmes utilisent la même technique pour les traces, et donc ETW, quels que soit l’envergure et les besoins réels de chaque programme. Qui peut le plus peut le moins, mais cela peut représenter un surcoût qu’il faudra parfois savoir expliquer.

Pour moi, NLog, Serilog et ETW répondent à des problèmes légèrement différents qui se recoupent. NLog (ou équivalent) est le plus simple et le moins structuré. Il devrait être le premier choix s’il répond aux besoins. Serilog apporte une structure qui facilite l’analyse des logs via des outils (si vous n’exploitez pas de manière automatisée ces logs, autant rester sur des logs non structurés). Enfin ETW apporte l’interopérabilité hors processus (malheureusement pas encore parfaitement cross-platform).

Là où ETW peut faire la différence est par exemple un plugin ou une librairie utilisés par d’autres applications. L’application peut ainsi choisir d’écouter les événements émis par le composant tiers. On peut même activer cette réception indépendamment du code applicatif.
Même dans ce cas de figure, ETW est plus long à mettre en oeuvre comparé à une interface plus classique à laquelle l’application devra se brancher. Par exemple la librairie JSON.NET (Newtonsoft) expose une interface ITraceWriter que l’application peut implémenter pour recevoir les traces émises par la librairie. C’est à mon avis beaucoup plus simple si cela répond aux besoins.

ETW est plus flexible et perfectionné, et donc aussi plus couteux à mettre à oeuvre (à la fois côté producteur et côté consommateur). Une différence clé, je pense, est qu’il est possible d’écouter les événements émis par une librairie sans aucun développement, ni configuration, sur l’application qui l’utilise. Pour un plugin ou pour une application avec une longue vie en perspective, et si en particulier on ne maîtrise pas entièrement celle-ci, c’est un avantage pour ses utilisateurs.

Enfin un autre avantage de ETW, du fait qu’il soit conçu autour d’événements structurés (qui forment un contrat) et qu’il soit intégré à Windows, est qu’il est devenu un standard qui facilite son intégration avec tout un écosystème de librairies et d’applications (comme Serilog à ceci près qu’il n’est pas natif à Windows).

Etat des lieux des assemblages et packages nuget pour ETW

En 2019, voici la liste des librairies les plus susceptibles d’intérêt pour ETW[4].

System.Diagnostics.Tracing (BCL): l’assemblage standard à référencer pour émettre des événements depuis .NET Framework et .NET Standard (donc .NET Core).
Microsoft.Diagnostics.Tracing.EventSource (nuget): version en avance de phase de System.Diagnostics.Tracing (car en avance sur l’assemblage du SDK) toujours pour produire des événements, mais uniquement pour .NET Framework. Egalement utile pour émettre des événements sur une version ancienne de .NET Framework qui ne contenait pas encore EventSource dans la BCL ou certaines nouvelles fonctionnalités.
Microsoft.Diagnostics.Tracing.TraceEvent (nuget): package à utiliser consommer des événements (.NET Framework et .NET Standard).

A ce propos, ne confondez pas EventSource/EventListener (ETW) et TraceSource/TraceListener également inclus dans la BCL. Ce dernier était conçu initialement pour les traces internes au framework .NET avant l’arrivée de ETW, et est un système de traces non structurées contrairement à ETW. Avant ETW, TraceSource était surtout utilisé pour consommer les traces internes du framework .NET vers un système de traces tiers comme NLog[5] ou Serilog[6], et peu pour générer ses propres traces (bien que possible, ce mécanisme est moins pratique à utiliser).

En conclusion

Pour émettre des événements: avec .NET Standard, utilisez l’assemblage standard du SDK System.Diagnostics.Tracing ; avec .NET Framework vous avez le choix entre utiliser le package Microsoft.Diagnostics.Tracing.EventSource pour avoir accès aux fonctionnalités les plus récentes ou rester sur les fonctionnalités standards de la BCL sans ajouter de dépendance supplémentaire.

Pour contrôler et consommer des événements ETW, utilisez le package Microsoft.Diagnostics.Tracing.TraceEvent.

Implémenter un EventSource

D’un point de vue plateforme (Windows, Linux, macOS) et runtime (.NET Framework et .NET Core), c’est la partie « simple », l’idée étant que la source (le provider) soit développée de la même façon.

Le principe consiste à dériver de la classe abstraite EventSource en respectant des conventions strictes.

Mon exemple plus bas s’appuie sur .NET Core sans avoir à référencer de dépendance particulière car la classe EventSource est incluse dans la BCL. Ce devrait être strictement identique avec une version récente de .NET Framework (a priori dès .NET 4.6).

Je ne vais pas détailler toutes ces conventions ici car c’est un sujet très riche à détailler. L’idée est que l’on crée une méthode par événement, avec les paramètres du type souhaité, que l’on route vers la méthode de base WriteEvent. Il est important que l’ordre et le type des paramètres soient les mêmes entre la méthode que vous implémentez et l’appel à la méthode de base WriteEvent. En interne, un schéma sera créé (appelé manifeste) à partir de la signature de vos méthodes. Si l’appel à la méthode de base WriteEvent ne respecte pas strictement ce schéma, cela posera problème. Egalement, vous risquez de rencontrer des problèmes si vous définissez des méthodes qui ne sont pas des événements (il faut alors les marquer avec l’attribut NonEventAttribute, ou mieux, placer ces méthodes dans une autre classe).

De façon plus évidente, il est important que chaque méthode expose un attribut EventAttribute avec un identifiant unique à cette méthode (qui représente l’événement).

A noter également: depuis .NET Framework 4.6, il est possible d’implémenter directement une interface depuis son implémentation de la classe abstraite EventSource (ce qui peut être pratique pour, par exemple faire en sorte qu’une librairie comme JSON.NET qui expose une interface génère ses traces via ETW). Auparavant, il fallait recourir à un code plus élaboré pour pouvoir émettre des événements via une interface car l’implémentation de la classe dérivée ne devait implémenter que la classe de base EventSource et aucune interface. Il peut y avoir d’autres différences. L’implémentation présentée ici tire donc partie de ces améliorations afin de rester relativement simple, et risque de ne pas fonctionner sur une ancienne version de .NET Framework.


    using System.Diagnostics.Tracing;

    public interface IMyAppEventSource
    {
        void Info(string message);

        void SomeSpecificDbEvent(int primaryKey, string tableName);
    }

    [EventSource(Name = "Company-Division-AppName-MyAppEventSource")]
    public sealed class MyAppEventSource : EventSource, IMyAppEventSource
    {
        internal static readonly MyAppEventSource Instance = new MyAppEventSource();

        private MyAppEventSource() { }

        [Event(1, Opcode = EventOpcode.Info)]
        public void Info(string message) 
        { 
            WriteEvent(eventId: 1, arg1: message); 
        }

        [Event(2)]
        public void AccessByPrimaryKey(int primaryKey, string tableName)
        {
            if (IsEnabled()) WriteEvent(eventId: 2, arg1: primaryKey, arg2: tableName);
        }
    }

L’utilisation typique est ensuite d’inscrire dans le conteneur IoC de l’application l’interface IMyAppEventSource avec l’implémentation exposée dans la propriété statique MyAppEventSource.Instance, et d’injecter l’interface IMyAppEventSource dans tout composant ayant besoin d’émettre des événements. La propriété statique MyAppEventSource.Instance n’est pas (plus?) indispensable mais c’était une convention, avant l’avènement de l’IoC. Avec ou sans instance statique, il faut gérer chaque source comme un singleton.

Il est également recommandée de limiter le nombre de sources par application. Le reste est à l’appréciation personnelle de chacun: une source par application avec beaucoup d’événements ou une source par composant avec moins d’événements. Il est également possible d’associer des EventKeywords arbitraires aux événements afin de faciliter leur catégorisation si vous définissez beaucoup d’événements différents. Cela montre à mon avis que le framework est conçu préférentiellement pour peu de sources avec beaucoup d’événements par source, plutôt que l’inverse. La recommandation de la documentation officielle est une source par unité déployable[7], donc par programme, librairie ou plugin.

Notez sur l’événement n°2 le test EventSource.IsEnabled(): ici pas vraiment utile, c’est pour illustrer la possibilité offerte par ETW de tester si l’événement sera consommé. Dans le cas présent, l’intérêt n’est pas significatif et la mise en oeuvre correcte quand cela a du sens est plus compliquée que cet exemple: soit c’est l’appelant qui évalue cette propriété (à exposer dans l’interface dans ce cas – c’est la méthode du pauvre), soit avec un délégué, ce qui oblige à encapsuler l’EventSource dans une autre classe pour gérer cette logique.

C’est un exemple simple, et il y a notamment beaucoup d’autres paramètres possibles sur l’attribut EventAttribute pour donner une sémantique plus explicite aux événements. On voit déjà avec cet exemple assez minimaliste que l’implémentation est nettement plus fastidieuse et sujette à erreur qu’émettre des traces sous forme de chaînes avec une librairie de traces non structurées. Le simple fait de devoir faire une méthode par type de trace (par événement) présente un coût non négligeable. Ce coût est à la fois payé au design initial, mais également lors des évolutions car chaque événement est un contrat: si vous souhaitez le modifier, il est conseillé de créer un nouvel événement. Pour en savoir plus sur la gestion des versions des événements, consultez la section dédiée dans le guide officiel Trace Event Programmers Guide.

Une solution pour réduire ce coût serait d’utiliser un outil de génération de code à partir d’une interface (celle que vous souhaitez utiliser dans votre code). Cependant, c’est une approche plus hasardeuse qu’il n’y parait pour plusieurs raisons:

Tout développeur sait que le code généré est moins agréable à lire (en revanche, écrire le générateur de code est souvent perçu comme plutôt cool à faire!).
ETW est très perfectionné, un générateur de code à partir d’un modèle simple (comme une interface éventuellement avec quelques attributs) ne pourra exploiter qu’un ensemble très limité des fonctionnalités de ETW. Dès lors qu’on voudra perfectionner sa source, le modèle requis par le générateur deviendra moins simple, limitant de ce fait l’intérêt apporté par la génération de code.
Le générateur de code devra être maintenu dans le temps: en cas de mauvaise maintenance (exemple: dépendance à une certaine version de MSBuild ou de Roslyn installée séparément sur la machine), on se retrouvera à maintenir une solution dégradée (maintenir sans générateur la source d’événements précédemment générée ou bien ne pas bénéficier d’évolutions sur la source parce que le générateur n’évolue pas aussi vite que le framework).

Cela me laisse penser qu’il est préférable de mettre en place des tests de validation de la source conçue « à la main », plutôt qu’employer un générateur de code. Ces tests, s’ils doivent être développés, sont finalement relativement simples à spécifier, les règles à respecter ne sont pas si nombreuses surtout si on les réduit à celle qu’on utilise effectivement (mais elles restent malheureusement faciles à transgresser – d’où l’intérêt d’une validation automatique). La maintenance de ces tests sera moins critique que celle du générateur. D’autre part, le développement d’une génération de code est probablement bien plus difficile (même si c’est plus amusant) que celui de tests (à qualité égale). Et bonne nouvelle: l’outil EventRegister existe déjà pour cette validation.

Valider un EventSource

Le package Microsoft.Diagnostics.Tracing.EventRegister à référencer dans l’assemblage qui définit vos sources rend automatique la validation de celles-ci lors de la compilation. Ce package n’ajoute pas de dépendance supplémentaire pour le déploiement, il ne s’agit que d’une tâche MsBuild.

Il est ainsi relativement aisé de développer ses sources en ayant un retour d’erreur en quasi temps réel. Sans cela, le projet compilerait mais vous pourriez ne voir aucun événement car les erreurs sont par défaut ignorées par ETW. Pour tester cette validation, essayez de définir deux événements avec le même EventId dans l’attibut EventAttribute.

Malheureusement, toutes les règles à respecter ne sont pas validées à ce jour par cet outil (version testée: 1.1.28). On peut espérer qu’il évolue. Par exemple, si vous ne respectez pas l’ordre, le nombre et le type de paramètres entre vos méthodes et l’appel à la méthode WriteEvent, des problèmes se poseront mais EventRegister ne révèle aucune erreur. De même, aucune erreur n’est révélée si la valeur EventId passée à la méthode WriteEvent n’est pas la même que celle marquée sur votre méthode avec l’attribut EventAttribute. La solution à ce jour est de développer vos propres tests en complément de cet outil.

Consommer un EventSource

D’un point de vue plateforme (Windows, Linux, macOS), c’est la partie compliquée. Sur Windows, les choses sont stables car elles existent depuis longtemps. Sur les autres plateformes, les développements de l’infrastructure requise sont encore en cours.

Il faut commencer par référencer le package Microsoft.Diagnostics.Tracing.TraceEvent, compatible .NET Framework et .NET Standard.

Pour rappel, les composants utiles pour consommer sont:

un contrôleur
un consommateur

Le contrôleur est représenté par la classe TraceEventSession. Le consommateur par la classe ETWTraceEventSource. Il devrait y avoir un seul consommateur par session. Mais rien n’empêche de mettre en oeuvre deux sessions qui écoutent la même source si c’est nécessaire, avec des réglages différents (par exemple des filtres écoutant des événements différents sur la même source).

Le cas le plus simple est l’écoute in-process: producteurs et consommateurs sont au sein du même processus. Dans ce cas, il suffit de mettre en oeuvre la classe EventListener qui encapsule le contrôleur et le consommateur. Ce cas est aussi le mieux supporté sur une plateforme non Windows à l’heure actuelle.

Pour une écoute out-of-process, c’est plus élaboré: il faut mettre en oeuvre TraceEventSession avec ETWTraceEventSource.

Noter que le code présenté dans la suite me sert à illustrer les méthodes à utiliser pour l’écoute basique des événements, de manière courte et concise. Davantage de travail sera nécessaire pour utiliser ce mécanisme de manière efficace dans un véritable projet. En particulier, pour faire correctement les choses, il vous faudra développer un ou plusieurs parseurs pour les événements que vous créez (typiquement un parseur par EventSource), en implémentant la classe abstraite TraceEventParser[10]. Dans l’exemple out-of-process un peu plus bas, à la ligne source.Dynamic.All, nous utilisons implicitement le parseur générique DynamicTraceEventParser qui est évidemment plus limité. Il existe un outil TraceParserGen peu documenté pour générer une implémentation de TraceEventParser à partir d’un EventSource (plus exactement grâce au manifeste généré à partir de celui-ci). Là encore, la solution de génréation de code n’est pas parfaite[11]. Des informations intéressantes se trouvent également dans les commentaires du code source de la classe TraceEvent! L’idée générale est de construire une instance de votre parseur à partir d’une instance de ETWTraceEventSource (le récepteur d’un EventSource). Le parseur expose typiquement un ou plusieurs événements auxquels on s’abonne pour obtenir les événements parsés. Etonnamment, l’implémentation d’un tel parseur est actuellement très mal documentée.

Ecoute in-process avec un EventListener (temps réel)


    using System;
    using System.Linq;
    using System.Diagnostics.Tracing;

    sealed class InprocListener : EventListener
    {
        protected override void OnEventSourceCreated(EventSource eventSource)
        {
            base.OnEventSourceCreated(eventSource);

            if (eventSource.Name == "Company-Division-AppName-MyAppEventSource")
            {
                EnableEvents(eventSource, EventLevel.Informational);
            }
        }

        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {
            base.OnEventWritten(eventData);

            string dump = string.Empty;

            for (int i = 0; i < eventData.Payload.Count; i++)
            {
                string payloadValue = eventData.Payload[i] != null ? eventData.Payload[i].ToString() : string.Empty;
                dump += $"{eventData.PayloadNames[i]}='{payloadValue}'";
            }

            Console.WriteLine($"{eventData.EventName}{dump}");
        }
    }

Le callback OnEventSourceCreated permet d’activer de manière dynamique toute source d’événements interne au processus (cette source peut être l’une des vôtres ou une source exposée par le runtime .NET).

Le callback OnEventWritten est invoqué chaque fois qu’un événement issu d’une source précédemment activée est reçu.

Note: n’activez pas toutes les sources détectées car un défaut de design de .NET Core fait que vous pourriez consommer par erreur des événements de la source spéciale RuntimeEventSource (les événements sont des copies internes au framework non prévues pour être exposées, susceptibles de contenir des valeurs incohérentes)[8].

Ecoute out-of-process en temps réel avec TraceEventSession et ETWTraceEventSource

A savoir: le processus qui orchestre TraceEventSession pour contrôler l’écoute d’un autre processus doit avoir les privilèges d’administrateur, sauf s’il active l’écoute d’un provider dynamique (c’est-à-dire non installé sur le système, contrairement à un provider dit statique). Sur un système non Windows, les droits d’administrateur sont actuellement toujours requis.


    using System;
    using System.Threading;
    using Microsoft.Diagnostics.Tracing;
    using Microsoft.Diagnostics.Tracing.Session;

    static class RealTimeListener
    {
        public static void ListenAndBlock()
        {
            const string sessionName = "MySession";
            using (var session = new TraceEventSession(sessionName))
            {
                // Set up Ctrl-C to stop the session
                Console.CancelKeyPress += (s, e) => session.Dispose();

                session.EnableProvider("Company-Division-AppName-MyAppEventSource");

                ETWTraceEventSource source = session.Source;

                source.Dynamic.All += (evt) => Console.WriteLine(evt.ToString());

                using (new Timer((o) =>
                {
                    Console.WriteLine("Listening. Press a key to stop.");

                    Console.ReadKey(intercept: true);
                    source.Dispose();
                }, null, 2000, Timeout.Infinite))
                {
                    // source.Process() blocks current thread until source.Dispose() is called.
                    // That's why we use a timer to dispose from another thread.
                    // --> It's is definitely bad quality code, only for demonstration purpose!
                    source.Process();
                }
                
                Console.WriteLine("Stopping...");
            } 
        }
    }

Ecoute out-of-process vers un fichier ETL avec TraceEventSession

Le fichier .ETL qui sera écrit pourra être lu après la collecte grâce à la classe TraceLog qui va générer un nouveau fichier .ETLX si celui-ci n’existe pas déjà. La réutilisation du fichier .ETLX rendra la lecture des événements plus performantes (c’est une forme d’indexation des événements).

Ce scénario est très utile pour un diagnostic sur un système en production.

Pour la collecte vers un fichier .ETL:


    using System;
    using Microsoft.Diagnostics.Tracing.Session;

    static class EtlFileWriterListener
    {
        public static void CollectAndBlock(string filename)
        {
            const string sessionName = "MySession";

            using (var session = new TraceEventSession(sessionName, filename))
            {
                session.EnableProvider("Company-Division-AppName-MyAppEventSource");
                 
                Console.WriteLine("Listening. Press a key to stop.");
                Console.ReadKey(intercept: true);
                Console.WriteLine("Stopping...");
            }
        }
    }

Pour parser un fichier .ETL (exemple très minimaliste):


    using System;
    using Microsoft.Diagnostics.Tracing;
    using Microsoft.Diagnostics.Tracing.Etlx;

    static class EtlFileReader
    {
        public static void ReadAndPrint(string filename)
        {
            using (TraceLog traceLog = TraceLog.OpenOrConvert(filename))
            {
                foreach (TraceEvent data in traceLog.Events)
                {
                    Console.WriteLine("{0}", data);
                }
            }
        }
    }

Contrôle de flux: perte d’événements possible

Si la source émet des événements plus rapidement que les consommateurs ne peuvent traiter, les événements sont perdus. En effet, il ne serait pas judicieux de bloquer la source, ni de provoquer une surcharge de la mémoire. Evidemment les consommateurs sont asynchrones, et un buffer existe pour supporter les pics (il y a d’ailleurs un délai de latence typique d’une à trois secondes[3]).

La documentation de Microsoft recommande à ce sujet de ne pas émettre plus de 10 000 événements par seconde pour une « machine typique ». Ce niveau entraînerait déjà une consommation de ressources significative (de l’ordre de 5% sur cette « machine typique »)[3].

Toujours en terme de performances, il est conseillé d’éviter si possible la méthode générique WriteEvent(int eventId, params object[] args) qui serait 10 à 20 fois plus couteuse qu’une des méthodes avec des paramètres de type primitif. Cela n’aura pas d’incidence réelle si la fréquence de ces événements est faible[9].

Ecoute avec l’outil PerfView.exe

La dernière version de PerfView est téléchargeable sur Github. PerfView est une application pour Windows qui fonctionne à la fois en ligne de commande et avec une interface graphique, et qui exploitent les classes décrites plus haut pour contrôler et consommer les événements ETW.

L’interface ressemble à un cockpit de Boeing. C’est un sujet très riche, et je ne montre ici qu’un exemple pour commencer à l’utiliser et observer vos propres événements.

Une fois PerfView lancé, cliquez sur le menu Collect, et encore une fois le sous-menu Collect (les droits d’administration sont requis).

Dans la fenêtre qui s’ouvre, déroulez les options avancées. Dans le champ Additional Providers, saisissez le nom de votre EventSource préfixé par un astérisque. Cela doit donner *Company-Division-AppName-MyAppEventSource pour l’exemple décrit plus haut. L’astérisque est nécessaire car le provider (notre source) n’est pas inscrite (installée) au niveau de la machine. Cela serait possible, mais c’est assez rare de le faire et plus contraignant (concerne surtout les sources standards de l’OS ou des logiciels de Microsoft).

Cliquez ensuite sur Start Collection pour lancer l’écoute (vous pouvez démarrer la source avant ou après, cela n’a pas d’importance).

Cliquez sur Stop Collection pour terminer l’écoute. Le fichier collecté va ensuite être traité (cela peut prendre un certain temps). Quand c’est fait, la fenêtre principale affiche un noeud Events. Double-cliquez dessus pour ouvrir la fenêtre des événements collectés. Vous devriez trouver votre source dans la liste de gauche. Il suffit de la sélectionner (on peut même sélectionner plus sources en même temps) et cliquer sur le bouton Update (ou appuyer sur la touche Entrée). Les événements collectés s’affichent dans la partie droite.

L’utilisation de PerfView requiert un temps d’apprentissage. On trouve de nombreux articles sur internet. Par exemple sur le blog de Vance Morrison (qui est aussi l’un des principaux auteurs de la documentation officielle et architecte de ETW).

Support partiel sur .NET Core

Il faut savoir que le support d’ETW reste incomplet sur .NET Core 2.2, même sur Windows, et davantage encore avec .NET Core sur un système non Windows. Le sujet est relativement peu documenté.

Sur .NET Core, les choses continuent d’évoluer autour de l’infrastructure commune EventPipe (concept .NET Core) qui route les événements vers ETW sur Windows, vers LTTng sur Linux, et vers Instruments/DTrace sur macOS.

Pour suivre les prochaines évolutions apportées par .NET Core 3, cet article est utile. Une vision plus globale pour .NET Core est également décrite dans ce document et ce document. Enfin, Matt Warren a rédigé une synthèse datant d’août 2018 sur son blog. C’est un chantier de grande envergure car il requiert une coordination des évolutions émanant des différentes plateformes (notamment LTTng) pour un jour espérer fournir les mêmes fonctionnalités sur chacune. Il me semble probable que le support sera toujours plus réduit sur macOS que sur LTTng (c’est déjà le cas aujourd’hui et je n’ai trouvé aucun élément allant dans le sens d’un support de même niveau à plus long terme).

Le support le plus complet sur .NET Core est la collecte in-process avec la classe abstraite EventListener décrite plus haut.

La façon la mieux supportée de collecter de manière out-of-process sur Linux est actuellement avec le script PerfCollect. Ce dernier collecte dans un fichier .ETL qui pourra être exploité sur Windows avec l’outil PerfView ou à l’aide de la classe TraceLog décrite plus haut.

Autres métadonnées associées aux événements

Côté EventSource, il est possible d’enrichir les événements de métadonnées descriptives.

Severity Level

Il s’agit du niveau de détail des traces. Un consommateur qui filtre le niveau Informational (qui est le niveau par défaut) recevra ce niveau ainsi que les niveaux plus critiques (tels que Warning et Error), mais ne recevra pas ceux du niveau Verbose.

Keywords (flags)

Les Keywords servent à filtrer des catégories (groupes) d’événements.

Il est conseillé de ne pas les utiliser sur des événements dont la fréquence est inférieure à 100 événements par seconde, et de les utiliser sur les événements émis à une fréquence supérieure à 1000 événements par seconde. Dans tous les cas, si un scénario de diagnostic est identifié grâce au filtrage de keywords, il reste recommandé de les utiliser quelle que soit la fréquence des événements. L’idée générale est d’avoir une interface simple lorsque les keywords n’apporte pas de plus-value identifiable à l’avance[7].

OpCode (parfois appelé class)

Les opcodes servent à exprimer une caractéristique standardisée à certains événements, tel que le démarrage ou la fin d’une tâche, ou encore le caractère informatif d’un message. Ils ne sont pas utiles pour filtrer l’écoute (utiliser pour cela les keywords).

A mon sens, c’est un concept avancé qu’il est inutile d’exploiter dans la majorité des cas.

Task

Les tasks servent à catégoriser les événements, mais ne sont pas utiles pour filtrer l’écoute (utiliser pour cela les keywords). Ce concept est utile pour associer un nom élaboré aux événements (qui ont par défaut le nom de la méthode qui les émet).

A mon sens, c’est un concept avancé qu’il est inutile d’exploiter dans la majorité des cas.

Activity

Les activities servent à grouper certains événements, typiquement avec un début et une fin, et donc typiquement utilisés avec un opcode.

A mon sens, c’est un concept avancé qu’il est inutile d’exploiter dans la majorité des cas.

Channel

Les channels fonctionnent comme des files d’événements, et sont typiquement utilisés pour séparer leur traitement (par exemple pour avoir une notion de priorisation des traitements). Ce mécanisme par exemple est utilisé pour le routage vers les différents journaux d’événements de Windows. Si non spécifié, tous les événements sont placés dans la même file par défaut.

Les channels ne sont supportés qu’avec des providers (sources) inscrites (installées) sur la machine, ce qui est plus contraignant. Ils sont donc relativement peu utilisés en dehors des providers de Microsoft.

LocalizationResources

Permet la localisation (traductions) grâce aux ressources embarquées (un fichier de ressources par culture).

Pour conclure

Ma conclusion est que même si ETW est mature sur Windows, la complexité requise pour l’exploiter efficacement (du point de vue d’un nouveau développement), le simple fait que le parsing des nouveaux événements est très mal documenté (en dehors du parseur dynamique qui n’est clairement pas une solution idéale), et le support encore partiel sur .NET Core, font que j’aurai tendance à privilégier d’abord NLog pour des traces non structurées (le plus facile) ou Serilog pour des traces structurées (plus élaboré, mais encore très largement plus simple que ETW).

A partir de chacune de ces deux solutions, il est possible de répéter les traces vers ETW. Pour NLog, un package existe déjà (NLog.Etw). Pour Serilog, il n’existe pas à ma connaissance de solution toute prête, mais développer l’équivalent d’un adatapteur (sink dans la terminologie Serilog) non structuré vers ETW me semble assez trivial. L’avantage est que vous n’avez pas vous-même à orchestrer ETW. En contrepartie vous avez peu de contrôle sur cette partie et au final le résultat dans ETW sont des traces non structurées.

Pour des besoins plus avancés, il est possible de mettre en oeuvre un mix de ces solutions. Ce n’est pas forcément élégant, mais cela me semble le plus pragmatique dans l’état actuel des choses. ETW a du sens notamment pour garantir qu’une librairie ou un plugin soit facilement diagnosticable sans le concours de l’application hôte qui devrait « brancher » son mécanisme de logs à une interface de la librairie (et sans dépendre d’un mécanisme de logs tiers depuis la librairie – EventSource étant inclu dans la BCL, ce n’est pas une dépendance visible).