I. Introduction

Lorsque j'ai découvert SQL Server il y a maintenant quelques années, j'ai aussi découvert son générateur de profils SQL Profiler. Je dois dire que j'adore cette façon de visualiser en temps réel les requêtes SQL exécutées par une application. C'est un outil pour le débogage et l'optimisation vraiment extraordinaire. Grâce à lui lorsqu'on teste une application, dès qu'on clique sur un bouton, on peut immédiatement voir les requêtes SQL qui s'exécutent. On voit par exemple qu'un même SELECT s'exécute quatre fois de suite (tiens, il y a une optimisation à faire !). Ou encore qu'on exécute une série de requêtes lorsqu'on ferme une fiche (qu'est-ce qu'on va faire dans la base de données alors que les traitements sont terminés ?). On découvre ainsi des comportements parfois totalement insoupçonnés.

Quelques années après j'ai dû travailler avec des bases de données Oracle. Et là j'ai été très déçu. En effet, si Oracle est capable de générer des traces bien plus précises et détaillées que SQL Server, elles sont beaucoup moins faciles à exploiter. Il faut d'abord enregistrer une trace dans un fichier. On ne peut l'analyser que dans un deuxième temps. Rien à voir avec la visualisation en temps réel de SQL Profiler. Oracle ne fournit pas d'outils aussi simples et performants que SQL Profiler. Qu'à cela ne tienne, on n'a qu'à écrire le notre ! Inversons le principe de fonctionnement : au lieu de tracer les requêtes qui s'exécutent sur le SGBD, nous allons instrumenter nos applications pour qu'elles génèrent la trace en temps réel.

Voici un petit exemple de ce que pourra donner le profiler :

Image non disponible

Bien évidemment, cette trace ne doit s'activer qu'à la demande. Qu'elle soit active ou non, elle ne doit pas pénaliser les performances de l'application.

En fait, le principal problème est comment générer et collecter cette trace en temps réel, sans affecter les performances ? C'est là qu'intervient Event Tracing for Windows (ETW).

Dans cet article nous allons étudier brièvement l'architecture ETW. Nous allons nous en servir pour réaliser un clone de SQL Profiler. Nous développerons des fonctions utilitaires permettant d'instrumenter facilement une application. Enfin nous verrons également comment écrire un client générique capable de collecter les traces générées par le système d'exploitation.

I.A. Pré-requis

  • ETW n'est disponible qu'à partir de Windows 2000.
  • La trace temps réel peut être démarrée sous Windows 2000 mais ne fonctionne pas correctement. En fait, la documentation récente de Microsoft dit même qu'elle n'est possible qu'à partir de Windows XP.
  • Pour démarrer une trace temps réel, il faut avoir les droits administrateurs. Dans la pratique ça restreint son usage au débogage ou à l'administration.
  • Sous Windows Vista, il faut avoir les droits administrateurs pour créer une trace, même pour une trace fichier.

I-B. Télécharger les sources de l'article

ftp://ftp-developpez.com/fsoriano/archives/etw/delphi/fichiers/etw-sources.zip

Vous pouvez télécharger l'article complet au format docx ici.

L'ensemble des codes sources utilisés pour cet article compile avec Turbo Delphi Explorer.

I-C. Présentation d'ETW

Event Tracing for Windows est une API bas niveau développée par Microsoft pour instrumenter des drivers de périphérique, mais aussi de simples applications utilisateurs. C'est la principale méthode préconisée dans le DDK de Windows pour le débogage de drivers.

Le principe de fonctionnement est le suivant :

Image non disponible

L'application à tracer implémente un ou plusieurs fournisseurs d'événements (Event provider qu'on appellera également Provider ou Logger). Lorsque ces derniers veulent écrire dans la trace, ils génèrent un événement qui sera placé dans une file d'attente (la trace) gérée par ETW.

L'application qui lit la trace est un client. Elle se connecte sur la trace et ETW lui envoie les événements mémorisés un à un. L'application cliente reçoit chaque événement sous la forme d'une structure binaire. Elle doit alors interpréter sa signification et le décoder pour l'afficher ou l'enregistrer en fonction des besoins.

Une troisième application crée la trace et active les providers. C'est le rôle du contrôleur. Ce dernier crée la trace, la configure et l'arrête. C'est lui qui décide si les événements doivent être traités en temps réel ou au contraire s'ils doivent être écrits dans un fichier. Dans ce dernier cas, c'est également lui qui décide du nom et de l'emplacement du fichier.

Remarques

  • En principe, ces trois composants sont implémentés dans des applications différentes. Mais une seule et même application peut très bien jouer les trois rôles.
  • Windows possède en standard une application cliente. Il s'agit de la commande tracerpt. Cette dernière permet d'ouvrir une trace binaire et de la mettre en forme dans un fichier texte.
  • Windows intègre également un contrôleur standard. Il s'agit du moniteur de performance (perfmon.msc). On le trouve dans panneau de configuration\Outils d'administration\Performances. On peut démarrer et arrêter une trace en créant un nouveau « journal de traçage ». On peut également effectuer les mêmes opérations en ligne de commande avec logman.
  • Windows possède également des providers. En fait, beaucoup de services Windows sont instrumentés avec ETW. Ces providers peuvent être activés individuellement dans une trace. Par exemple, on peut tracer en détails le traitement d'une requête http dans IIS6. On obtient alors un log beaucoup plus détaillé que les logs habituels du serveur web.
  • Windows possède un provider spécial : Le « NT Kernel Logger ». Il s'agit du provider intégré au noyau du système d'exploitation. Il permet de voir en détail tout ce que fait le système (accès disque, mémoire, base de registres...).

Lorsqu'on crée une trace, on peut créer une trace fichier. Dans ce cas, les événements sont écrits dans un buffer. Lorsque le buffer est plein, ETW l'enregistre dans un fichier. Les fichiers de trace ETW portent l'extension etl. Mais on peut également créer une trace temps réel. Les buffers une fois remplis sont alors envoyés immédiatement au client.

Cette architecture présente un certain nombre d'avantages, dont notamment :

  • Pour le provider l'essentiel des traitements est effectué par un processus différent. L'impact sur l'application qui génère la trace est donc minime. Elle n'est pas ralentie par un accès disque. Les événements peuvent être générés plus vite que le client ne les traite.
  • La trace est configurée et mise en place par le contrôleur. Il s'agit donc d'une application externe à l'application tracée. On gagne ainsi énormément en souplesse. Il est possible de démarrer une trace n'importe quand, alors que l'application tracée est elle-même déjà lancée sans qu'il ne soit nécessaire de la redémarrer. C'est très pratique si on veut déboguer un service Windows par exemple.
  • Enfin, et c'est le principal point qui nous intéresse, la trace peut être lue au fur et à mesure qu'elle est écrite par une autre application. C'est comme ça qu'on pourra réaliser un client qui lit la trace en temps réel.

II. Construire les bases

Nous venons de voir grosso modo le principe de fonctionnement d'ETW. L'API est relativement complexe à mettre en oeuvre directement. Aussi nous allons commencer par l'encapsuler dans des objets.

II.A. Import du fichier EvnTrace.h

ETW est implémentée dans la DLL AdvApi32.dll. Les prototypes d'appels des fonctions sont déclarés dans le fichier en-tête EvnTrace.h du kit de développement Windows.

Malheureusement, il n'existe pas d'unité dans Delphi permettant d'appeler ETW. Il va donc falloir l'écrire nous-mêmes. Le résultat se trouve dans uETW.pas.

J'ai un peu simplifié la définition des structures. En effet je n'ai pas repris toutes les alternatives des UNION. Je me suis contenté de déclarer les structures telles qu'elles seront utilisées...

Les fonctions de la DLL sont importées de façon explicite (la DLL est chargée avec LoadLibrary, les références sur les fonctions sont obtenues avec GetProcAddress). De cette façon on évite d'avoir une erreur si la DLL n'est pas présente sur le système (Windows 9x...)

II.B. Le Provider

Le provider va être encapsulé dans la classe TGenericLogger de l'unité uLogger. Cette dernière effectuera tous les appels à ETW. Au final, on n'aura plus qu'à appeler une simple méthode pour générer une trace.

Le provider fait parti de l'application à tracer. Depuis Windows Vista, il existe deux types de provider. Les providers classiques et ceux définis avec un Manifest. Les derniers n'étant supportés que par Windows Vista, nous nous contenterons de définir un provider classique.

TGenericLogger est déclaré de la façon suivante :

 
Sélectionnez

type
  TGenericLogger = class(TObject)
  private
    FEventEnabled : boolean;
    FEnableLevel : integer;
    FEnableFlags : cardinal;
    FTraceSession : TRACEHANDLE;
    FRegistrationHandle : TRACEHANDLE;
    FProviderGUID : TGUID;
    FEventClass : TGUID;
    FRegistrationEventClass : TRACE_GUID_REGISTRATION;
  protected
    // Indique si le message de niveau Level doit être écrit dans la trace en
    // cours. Cette fonction teste si une trace a été activée ainsi que son
    // niveau d'activation.
    function MessageEnabled(Level : byte) : boolean;

    // Active la génération des événements.
    procedure EnableEvents(Header : pointer);

    // Désactive la génération des événements.
    procedure DisableEvents(Header : pointer);

    // Handle de la session de trace active.
    property TraceSession : TRACEHANDLE read FTraceSession;

    // Handle d'enregistrement du provider.
    property RegistrationHandle : TRACEHANDLE read FRegistrationHandle;
  public
    // Déclare le provider auprès de ETW.
    // <aProviderGUID> : GUID du provider.
    // <aEventClass> : GUID de la classe des événements générés par le provider.
    constructor Create(aProviderGUID : TGUID; aEventClass : TGUID);

    // Détruit la classe et annule l'enregistrement du provider auprès de ETW.
    destructor Destroy; override;

    // Ecrit le message <msg> dans la trace.
    procedure Trace(msg : string); overload;

    // Ecrit le message <msg> dans la trace.
    // Le message sera mémorisé avec le type d'événement <EventType>, pour le
    // niveau de trace <msgLevel>, avec une information de durée <OperationTime>
    procedure Trace(EventType : integer; msg : string;
      msgLevel : integer = TRACE_LEVEL_INFORMATION;
      OperationTime : int64=0); overload;

    // Ecrit le début d'une opération dans la trace :
    // Le message <msg> est écrit dans la trace, avec le type d'événement
    // <EventType> et le niveau de trace <msgLevel>.
    // En sortie, currentTime est initialisée avec un TimeStamp correspondant à
    // l'heure courante au moment de l'appel.
    procedure TraceBegin(EventType : integer; msg : string;
      var currentTime : int64;
      msgLevel : integer = TRACE_LEVEL_INFORMATION);

    // Ecrit la fin d'une opération dans la trace :
    // Le message <msg> est écrit dans la trace, avec le type d'événement
    // <EventType> et le niveau de trace <msgLevel>.
    // TraceEnd doit avoir été précédé d'un appel à TraceBegin pour définir le
    // début de l'opération. <currentTime> doit contenir la valeur retournée par
    // le paramètre <currentTime> de TraceBegin.
    // TraceEnd calcule alors le temps écoulé (en ms) entre TraceEnd et
    // TraceBegin et écrit ce temps passé dans le champ OperationTime de la
    // trace.
    // En sortie, currentTime contient le temps écoulé depuis l'appel à
    // TraceBegin
    procedure TraceEnd(EventType : integer; msg : string; var currentTime : int64;
      msgLevel : integer = TRACE_LEVEL_INFORMATION);

    // Ecrit l'exception <e> dans la trace, avec le niveau de trace <msgLevel>
    procedure TraceException(e : exception;
      msgLevel : integer = TRACE_LEVEL_ERROR);

    // Identifiant du provider.
    property ProviderGUID : TGUID read FPRoviderGUID;

    // Classe de l'événement généré par le provider.
    property EventClass : TGUID read FEventClass;

    // Indique si la trace est actuellement active
    property EventEnabled : boolean read FEventEnabled write FEventEnabled;

    // Indique le niveau de trace qui a été défini au moment de l'activation
    // de la trace.
    property EnableLevel : integer read FEnableLevel;

    // Indique les flags définis au moment de l'activation de la trace
    property EnableFlags : cardinal read FEnableFlags;
  end;

II.B.1. Enregistrement auprès d'ETW

L'enregistrement du provider auprès d'ETW est un préalable à toute trace. Cette opération fait partie de l'initialisation de la classe. Elle est réalisée par son constructeur :

 
Sélectionnez

// Déclare le provider auprès de ETW.
// <aProviderGUID> : GUID du provider.
// <aEventClass> : GUID de la classe d'événements généré par le provider.
constructor TGenericLogger.Create(aProviderGUID: TGUID; aEventClass : TGUID);
begin
  FProviderGUID := aProviderGUID;
  FEventClass := aEventClass;
  FRegistrationEventClass.Guid := @FEventClass;
  FRegistrationEventClass.RegHandle := 0;

  // la déclaration du provider consiste à appeler RegisterTraceGuids.
  if RegisterTraceGuids(@TraceControlCallBack, // Méthode callback pour
                                               // contrôler la trace
    Self, // On définit le pointeur sur l'instance comme contexte utilisateur.
    @FProviderGUID, // Pointeur sur l'identifiant du provider
    1, // Nombre d'événements déclarés
    @FRegistrationEventClass, // Pointeur sur la liste des classes d'événements
                              // générés par le provider
    nil, // On ne définit pas d'informations MOF
    nil, // On ne définit pas d'informations MOF
    FRegistrationHandle)<>ERROR_SUCCESS
  then RaiseLastOSError;
end;

Pour effectuer cet enregistrement, on a besoin de deux paramètres :

  • Le ProviderGUID : Il s'agit du GUID identifiant le provider.
  • Un EventClassGUID : Il s'agit du GUID identifiant la classe des événements écrits dans la trace. Il est possible de définir plusieurs classes d'événements pour un même provider. Pour nos besoins nous nous contenterons d'une seule classe, avec une structure d'événement unique.

L'enregistrement du provider s'effectue avec la fonction RegisterTraceGuids :

  • Le premier paramètre à fournir à RegisterTraceGuids est un pointeur sur une fonction callback permettant de contrôler la trace. Cette dernière sera appelée par ETW pour notifier le provider du démarrage ou de l'arrêt de la trace.
  • Le deuxième paramètre est un pointeur qu'on peut définir librement. Il sera transmis à la fonction callback chaque fois qu'elle sera appelée. ETW est une API bas niveau qui n'utilise pas la programmation objet. On va donc se servir de ce paramètre pour transmettre l'instance du provider à la fonction callback.
  • Le troisième paramètre indique le GUID du provider.
  • Les quatrième et cinquième paramètres servent à définir un tableau indiquant la liste des EventClassGUID que le provider est susceptible de générer.
  • Les sixième et septième paramètres sont réservés. On les renseigne à NIL.
  • Enfin en retour, RegisterTraceGuids retourne un handle d'enregistrement dans le dernier paramètre.

II.B.2. TraceControlCallBack

 
Sélectionnez

// Cette fonction est appelée automatiquement par ETW pour controler la trace :
// <RequestCode> indique le type d'opération désirée :
// - WMI_ENABLE_EVENTS : Nous informe que le provider vient d'être activé.
// - WMI_DISABLE_EVENTS : Nous informe que le provider vient d'être arrêté.
// <RequestContext> Contient un pointeur sur les données utilisateur fournies
//                  au moment de l'enregistrement de la trace avec
//                  RegisterTraceGuid.
//                  On l'utilise pour connaitre l'instance de TGenericLogger
//                  concernée.
// <BufferSize> Spécifique Vista. On l'ignore.
// <Buffer> pointe sur une structure WNODE_HEADER contenant des informations
//          sur la trace concernée.
// En retour cette fonction doit renvoyer ERROR_SUCCESS pour indiquer que tout
// s'est bien passé.
function TraceControlCallBack(RequestCode : WMIDPREQUESTCODE;
    RequestContext : pointer;
    BufferSize : cardinal;
    Buffer : pointer) : cardinal; stdcall;
begin
  // En fonction de l'opération demandée, on active ou désactive la trace.
  case RequestCode of
    WMI_ENABLE_EVENTS: TGenericLogger(RequestContext).EnableEvents(Buffer);
    WMI_DISABLE_EVENTS: TGenericLogger(RequestContext).DisableEvents(Buffer);
  end;
  result := ERROR_SUCCESS;
end;

TraceControlCallback est appelée par ETW pour notifier le provider du démarrage ou de l'arrêt de la trace.

Lorsque la trace est démarrée, le provider doit lire le niveau de trace avec GetTraceLoggerHandle, GetTraceEnableLevel et GetTraceEnableFlags.

En effet, en général on définit des traces de différents niveaux (CRITICAL, DEBUG, WARNING, INFO, VERBOSE, ...). Lorsqu'on démarre une trace, on veut un niveau de détail plus ou moins fin selon les besoins.

Pour gérer ce mode de fonctionnement, lorsque la trace est démarrée, le provider doit lire le niveau activé. Avant de générer chaque événement il faut commencer par vérifier si le niveau actif est compatible avec celui de l'événement.

Les méthodes EnableEvents et DisableEvents sont écrites pour initialiser les propriétés EventEnabled, EnableLevel, EnableFlags et TraceSession. Lors de l'arrêt de la trace, on se contente de réinitialiser ces valeurs.

II.B.3. Ecrire dans la trace

Pour écrire dans la trace, on va générer un événement avec la fonction TraceEvent.

II.B.3.a. Structure d'un événement

Chaque événement doit être une structure binaire commençant par un en-tête EVENT_TRACE_RECORD.

Il existe deux façons de définir un événement :

  • Soit on crée une structure complète, avec son en-tête et toutes informations à écrire dans la trace.
  • Soit on crée une structure simplifiée composée uniquement de l'en-tête et d'un tableau de pointeurs indiquant les variables à écrire à la suite de l'en-tête.

Si on utilise la première méthode, il faut commencer par allouer une structure de taille suffisante. La taille de l'enregistrement peut varier, surtout si on veut écrire des chaînes de caractères. Il faut ensuite recopier manuellement les données dans cette structure avant de la transmettre à ETW. A son tour ETW va la recopier dans ses buffers internes avant de rendre la main. Ainsi cette méthode nécessite des allocations mémoires et plusieurs recopies des informations.

Si on utilise la deuxième méthode, la structure définissant l'événement possède une taille fixe. En effet l'en-tête est fixe et la taille du tableau de pointeurs dépend du nombre de champs de l'événement et pas de leur valeur. De plus comme on ne renseigne que des références aux valeurs, on n'effectue pas de recopie de données. Lorsqu'on transmet l'événement à ETW, la structure sera lue et remise en forme pour recopier les données dans les buffers de la trace.

Cette dernière technique est donc à privilégier si on doit tracer des événements volumineux ou de taille variable. C'est celle qu'on va utiliser.

La taille maximale théorique d'un événement est de 64Ko selon la documentation Microsoft. Mais il ne faut pas que la taille d'un seul événement excède celle d'un buffer.

Les événements que nous allons générer seront composés des informations suivantes :

  • OperationTime : Ce champ nous permettra de tracer des durées de traitement. On génère un message au début du traitement, un message à la fin et on indique dans ce champ le temps écoulé entre les deux. En principe ce temps peut être calculé directement à partir des dates des messages de la trace. Cependant il n'est pas toujours évident de retrouver le message de début dans la trace. Par soucis de facilité, on mesure les temps dans l'application et on les communique à la trace.
  • TextData : C'est le principal champ qui nous intéresse. Il s'agit de la chaîne de caractères qu'on veut écrire dans la trace.

A ces données utilisateur s'ajoutent celles définies dans l'en-tête :

  • Horodatage de l'événement : définit automatiquement par ETW.
  • EventClassGUID : Le GUID de la classe d'événement. Il permet d'identifier la structure de l'événement généré.
  • EventType : Va de paire avec EventClassGUID, l'EventType définit un sous type pour la classe d'événement.

La structure transmise à ETW est la suivante :

 
Sélectionnez

type
  TGenericEvent = packed record
    Header : EVENT_TRACE_HEADER; // en-tête du message
    Data : array[0..1] of MOF_FIELD; // Informations à écrire dans la trace.
  end;

II.B.3.b. Ecriture de l'événement

 
Sélectionnez

// Ecrit le message <msg> dans la trace.
// Le message sera mémorisé avec le type d'événement <EventType>, pour le
// niveau de trace <msgLevel>, avec une information de durée <OperationTime>
procedure TGenericLogger.Trace(EventType: integer; msg: string;
    msgLevel: integer;
    OperationTime: int64);
    const EmptyStr : char = #0;
    var Event : TGenericEvent;
    EventSize : cardinal;
begin
  // Il faut commencer par tester si la trace a été activée et si le niveau de
  // trace défini est compatible avec le message à tracer. Sinon on
  // n'enregistre pas le message dans la trace.
  if MessageEnabled(msgLevel)
  then begin
    // Initialisation d'une structure TGenericEvent qui sera écrite dans la
    // trace.
    EventSize := Sizeof(Event);
    fillchar(Event, EventSize, 0);

    // Initialisation de l'en-tête de l'événement.
    Event.Header.Size := EventSize; // Taille de la structure.

    // On indique que le champs Guid a été défini et qu'on utilise un tableau
    // de structure MOF_FIELD pour définir les informations écrites dans la
    // trace.
    Event.Header.Flags := WNODE_FLAG_TRACED_GUID or WNODE_FLAG_USE_MOF_PTR;

    // On définit les identifiants de l'événement qui sera généré dans la trace.
    // Ces identfiants permettront au programme client de décoder les
    // informations définies dans Data.
    Event.Header.Guid := FEventClass; // Définition de la classe d'événement
    Event.Header.Version := 0; // Numéro de version de l'événement
    Event.Header.Type_ := EventType; // Définition du type de l'événement

    Event.Header.Level := msgLevel; // Niveau de trace de l'événement.

    // Une fois l'en-tête définie, on définit les informations à écrire dans la
    // trace.
    // On veut écrire un enregistrement composé des champs <OperationTime,
    // msg> Pour celà, on initialise l'adresse et la longueur de chaque champ.
    Event.Data[0].DataPtr := @OperationTime;
    Event.Data[0].Length := sizeof(OperationTime);
    if msg<>''
    then begin
      Event.Data[1].DataPtr := @msg[1];
      Event.Data[1].Length := length(msg)+1; // Longueur de la chaîne plus zéro
                                             // terminal.
    end
    else begin
      // Si msg est une chaine vide, msg est en réalité un pointeur qui vaut nil
      // Il ne s'agit donc plus d'une chaine asciiz et la chaine ne s'enregistre
      // pas correctement. Il faut donc qu'on écrive explicitement un zéro
      // terminal.
      Event.Data[1].DataPtr := @EmptyStr;
      Event.Data[1].Length := 1;
    end;

    // Enfin on écrit le message dans la trace.
    TraceEvent(TraceSession, @Event);
  end;
end;

L'écriture de l'événement s'effectue avec la fonction TraceEvent. On indique simplement le handle de la trace dans laquelle on veut écrire (celle qui a été démarrée bien sûr) ainsi que la structure à écrire.

On ne peut pas générer d'événement si aucune trace n'a été démarrée. Sinon on ne connaît pas le handle de trace. Aussi avant de générer un message, on doit commencer par tester si la trace a été activée. De toute façon, ce n'est pas la peine de perdre du temps à générer l'événement si aucune trace n'a été activée...

II.B.4. Provider générique

La classe TGenericLogger est à présent terminée. Il suffit de l'instancier pour obtenir un provider prêt à l'emploi.

Par commodité, on va également définir une instance générique en singleton qui sera automatiquement créée chaque fois qu'une application référence l'unité uLogger.pas.

Cette instance utilise les identifiants suivants :

 
Sélectionnez

const
  // Identifiant du provider générique.
  DefaultLogger : TGUID = '{708A0B60-6786-460B-96A1-2C569C7B0B4C}';

  // Identifiant des classes de messages générés par le Logger générique.
  DefaultEventClass : TGUID = '{D3E38F07-FB65-4456-82B4-053A40FF72BD}';

DefaultLogger est le GUID du provider. DefaultEventClass est le GUID de la classe d'événements.

Ce provider est susceptible d'écrire quatre types d'événements :

 
Sélectionnez

const
  EVENT_INFO = 0;
  EVENT_START = 1;
  EVENT_END = 2;
  EVENT_ERROR = 3;
  • EVENT_INFO : Message de trace générique, écrit par un appel à la méthode Trace.
  • EVENT_START : Message indiquant le début d'une opération (début d'une méthode par exemple), écrit avec la méthode TraceBegin.
  • EVENT_END : Message indiquant la fin d'une opération et la durée écoulée depuis le début, écrit avec la méthode TraceEnd.
  • EVENT_ERROR : Message d'erreur indiquant le contenu d'une exception (TraceException).

La fonction GenericLogger retourne l'instance unique du provider.

Ainsi pour écrire un message dans la trace, il suffit de :

 
Sélectionnez

uses uLogger;
...
begin
  ...
  GenericLogger.Trace('Message à écrire dans la trace.');
  ...
end;

II.B.5. Provider SQL

Maintenant nous savons comment écrire un message dans la trace en général.

Revenons à l'objectif initial qui est d'écrire un profiler SQL. Nous allons avoir besoin de générer tout une série d'événements pour la couche d'accès aux données. On pourrait le faire avec le provider générique.

Avec un provider dédié pour les accès SQL on aura cependant plus de flexibilité sur la gestion de la trace. On pourra notamment distinguer les événements issus de la couche d'accès aux données des événements générés par le reste de l'application.

Naturellement, l'essentiel du travail a déjà été fait avec le provider générique. Le provider SQL va simplement définir un nouveau ProviderGUID ainsi que quelques méthodes utilitaires pour générer les événements. Les types d'événements à tracer seront les suivants :

  • Connexion : Ce simple événement suffit, aucun paramètre nécessaire.
  • Déconnexion : Idem.
  • Début d'une transaction : Idem.
  • Validation d'une transaction : Idem.
  • Rollback d'une transaction : Idem.
  • Début d'exécution d'une requête : On doit indiquer la requête qui va être exécutée. Si cette dernière est une requête paramétrée, on doit également indiquer les valeurs des paramètres.
  • Fin de l'exécution d'une requête : On doit indiquer la requête qui a été exécutée. Si cette dernière est une requête paramétrée, on doit à nouveau indiquer les valeurs des paramètres. S'il y a des paramètres de sorti, ces derniers ont pu changer.
  • Messages d'erreurs du SGBD : Il faut au minimum indiquer le message d'erreur, voir si possible le code d'erreur du SGBD.
  • Messages d'information du SGBD : il faut indiquer le message.

Pour faciliter le traitement de la trace et son affichage dans le client, on a intérêt à garder une structure unique d'événement quel que soit l'événement. C'est pourquoi, on se contentera à chaque fois d'écrire une chaîne de caractères dans la trace.

La déclaration du provider SQL devient la suivante :

 
Sélectionnez

const
  // Identifiant du provider SQL.
  SQLLoggerGUID : TGUID = '{E356181E-4059-4BBA-BA4A-87280762A798}';
  
  // Identifiant des classes de messages générés par le provider SQL.
  SQLEventClass : TGUID = '{815AA09D-DBC9-45FE-982E-0243FDF363ED}';
  
// Constantes pour les types d'événements
const
  EVENT_SQL_INFO = 0; // Message d'information
  EVENT_SQL_START = 1; // Début d'exécution d'une requête SQL
  EVENT_SQL_END = 2; // Fin d'exécution d'une requête SQL
  EVENT_SQL_ERROR = 3; // Erreur survenue avec une requête SQL
  EVENT_BEGINTRAN = 4; // Début d'une transaction.
  EVENT_ROLLBACKTRAN = 5; // Rollback d'une transaction.
  EVENT_COMMITTRAN = 6; // Commit d'une transaction.
  EVENT_SQL_FORMAT_START = 7; // Début de la mise en forme des paramètres
  EVENT_SQL_FORMAT_END = 8; // Fin de la mise en forme des paramètres.
  EVENT_SQL_CONNECT = 9; // Connexion au SGBD
  EVENT_SQL_DISCONNECT = 10; // Déconnexion du SGBD

// TSQLLogger implémente un provider ETW pour générer des traces d'exécution de
// requêtes SQL.
type
  TSQLLogger = class(TGenericLogger)
  private
    // Retourne la valeur du paramètre <Param> sous la forme d'une chaîne de
    // caractères.
    function ParamStr(Param : TParam) : string;

    // Ecrit la valeur des paramètres <Params> de la requête <SQL> dans la
    // trace. Cette écriture s'effectue sous la forme de la requête <SQL> dans
    // laquelle les spécificateurs de paramètres ont été remplacés par la valeur
    // du paramètre correspondant.
    procedure FormatParams(SQL : string; params : TParams);
  public
    // Trace le début d'exécution de la requête <SQL>.
    // En sortie, <Time> contient le timestamp du début d'exécution de la
    // requête <Params> doit contenir la valeur des paramètres de la requête.
    // Ces derniers peuvent être définis soit sous la forme d'un ? soit sous la
    // forme :NomdeParametre.
    // <msgLevel> doit indiquer le niveau de trace du message.
    // Si la trace est activée au niveau VERBOSE, les valeurs des paramètres de
    // la requête seront écrites dans la trace.
    procedure TraceSQLBegin(SQL : string; var Time : int64; Params : TParams=nil;
      msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace la fin d'exécution de la requête <SQL>.
    // <Time> doit contenir le timestamp du début d'exécution de la requête
    // renvoyé par TraceSQLBegin.
    // En sorti, <Time> contiendra le temps écoulé depuis l'appel à
    // TraceSQLBegin.
    // <Params> doit contenir la valeur des paramètres de la requête.
    // Ces derniers peuvent être définis soit sous la forme d'un ? soit sous la
    // forme :NomdeParametre.
    // <msgLevel> doit indiquer le niveau de trace du message.
    // Si la trace est activée au niveau VERBOSE, les valeurs des paramètres de
    // la requête seront écrites dans la trace.
    procedure TraceSQLEnd(SQL : string; var Time : int64; Params : TParams=nil;
      msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace le début d'une transaction SQL.
    // En sortie, <Time> contient le timestamp du début de la transaction
    // <msgLevel> indique le niveau de trace du message.
    procedure TraceStartTransaction(var Time : int64;
      msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace la validation d'une transaction SQL.
    // <Time> doit contenir le timestamp du début de la transaction renvoyé par
    // TraceStartTransaction.
    // <msgLevel> indique le niveau de trace du message.
    procedure TraceCommitTransaction(Time : int64;
      msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace le rollback d'une transaction SQL.
    // <Time> doit contenir le timestamp du début de la transaction renvoyé par
    // TraceStartTransaction.
    // <msgLevel> indique le niveau de trace du message.
    procedure TraceRollbackTransaction(Time : int64;
      msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace la connexion au SGBD.
    procedure TraceConnect(msgLevel : byte = TRACE_LEVEL_INFORMATION);

    // Trace la déconnexion du SGBD.
    procedure TraceDisconnect(msgLevel : byte = TRACE_LEVEL_INFORMATION);
  end;

Comme pour le provider générique, il est géré en singleton. La fonction SQLLogger retourne l'instance unique à utiliser pour écrire dans la trace.

Signalons cependant une particularité des méthodes TraceSQLBegin et TraceSQLEnd. En effet, on demande à ces dernières d'écrire les valeurs des paramètres SQL lorsqu'on utilise une requête paramétrée.

Avec les requêtes paramétrées, la requête à tracer est une requête du style :

 
Sélectionnez

select * from MaTable where Id = ?

Ou encore :

 
Sélectionnez

select * from MaTable where Id = :MonId

L'exécution de la requête s'effectue de cette façon et la valeur du paramètre est transmise au SGBD séparément. Si on se contente d'écrire ça dans la trace, il nous manque une information parfois vitale : La valeur du paramètre.

Il faut donc substituer cette valeur à son spécificateur. Cependant la trace doit toujours indiquer la requête brute, afin de bien faire apparaître qu'on utilise une requête paramétrée, tout en indiquant les valeurs des paramètres.

Ces deux informations sont écrites en plusieurs lignes dans la trace :

La première ligne trace la requête brute.
Une deuxième ligne trace la même requête en ayant remplacé les paramètres de la requête brute.
Ainsi pour tracer la requête précédente, on aura :

SQL Trace START select * from MaTable where Id = ?
SQL Trace PARAMETER START  
SQL Trace PARAMETER END select * from MaTable where Id = 1

La substitution des paramètres pour la trace risque de prendre un certain temps. C'est pourquoi cette dernière n'est effectuée que si le provider détecte que la trace est active et que le niveau VERBOSE a été demandé.

II.B.6. Publication du schéma des événements

Cette opération n'est pas nécessaire si on utilise un client propriétaire pour traiter les traces. Mais si on veut utiliser un client générique et que ce dernier puisse interpréter nos événements il faut publier des informations pour décrire la structure de l'événement.

Cette opération s'effectue à l'aide de WMI et plus exactement d'un fichier MOF, proche des déclarations d'interfaces MIDL des objets COM.

Notre fichier (logger.mof) sera le suivant :

 
Sélectionnez

#pragma namespace("\\\\.\\root\\wmi")
[dynamic: ToInstance, Description("Generic Trace"),
  Guid("{708A0B60-6786-460B-96A1-2C569C7B0B4C}")]
class DefaultProvider : EventTrace
{
};
[dynamic: ToInstance, Description("MSGEVENT"): Amended,
  Guid("{D3E38F07-FB65-4456-82B4-053A40FF72BD}"),
  DisplayName("MSG"),
  EventVersion(0)]
class DefaultEventClass : DefaultProvider
{
};

[dynamic: ToInstance, Description("MSG"): Amended,
  EventType{0, 1, 2, 3},
  EventTypeName{"INFO",
                "START",
                "END",
                "ERROR"}]
class DefaultEventClass_EventType1 : DefaultEventClass
{
  [WmiDataId(1), Extension("Noprint"), Description("OperationTime"): Amended, read]
  sint64 OperationTime;

  [WmiDataId(2), Description("TextData"): Amended, read,
  StringTermination("NullTerminated")]
  string TextData;
};

Le fichier MOF doit définir trois classes :

  • Une classe pour le provider. Cette dernière doit obligatoirement dériver de la classe EventTrace. Elle doit préciser le Guid du provider et lui associer un nom publique avec Description. Dans l'exemple précédent on définit la classe DefaultProvider, avec le Guid {708A0B60-6786-460B-96A1-2C569C7B0B4C} qui est celui défini pour DefaultLogger et la description « Generic Trace ».
  • Une classe pour chaque EventClass du provider. Cette dernière doit dériver de celle du provider. On lui associe l'EventClassGUID de l'événement concerné, ici DefaultEventClass soit {708A0B60-6786-460B-96A1-2C569C7B0B4C}. Ainsi qu'une description « MSGEVENT». Cependant si on veut que TraceRpt affiche le nom de l'événement correctement, il faut le définir avec DisplayName.
  • Une classe par type d'événement, pour chaque classe d'événements. Elle doit dériver de la classe de l'événement décrit. On indique avec EventType le type d'événement concerné. Une même classe peut être utilisée pour plusieurs types d'événements, dans ce cas on indique la liste des types d'événements concernés sous la forme d'un tableau. Dans notre exemple, tous les événements ont la même structure. EventTypeName permet de nommer les types d'événements. Il ne reste plus qu'à déclarer les champs formant l'événement, sous la forme de propriétés.

Une fois le fichier mof écrit, il faut le compiler et le publier dans WMI avec la commande :

 
Sélectionnez

Mofcomp Logger.mof

Pour le provider SQL, le fichier mof est le suivant :

 
Sélectionnez

#pragma namespace("\\\\.\\root\\wmi")
[dynamic: ToInstance, Description("SQL Trace"),
  Guid("{E356181E-4059-4BBA-BA4A-87280762A798}")]
class SQLLogger : EventTrace
{
};

[dynamic: ToInstance, Description("SQL Trace"): Amended,
  Guid("{815AA09D-DBC9-45FE-982E-0243FDF363ED}"),
  DisplayName("SQL Trace")]
class SQLLoggerClass : SQLLogger
{
};

[dynamic: ToInstance, Description("Trace SQL"): Amended,
  EventType{0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10},
  EventTypeName{"INFO",
                "START",
                "END",
                "ERROR",
                "BEGIN TRAN",
                "ROLLBACK",
                "COMMIT",
                "PARAMETER START",
                "PARAMETER END",
                "LOGIN",
                "LOGOUT"}]
class SQLLoggerClass_EventType1 : SQLLoggerClass
{
  [WmiDataId(1), Extension("NoPrint"), Description("OperationTime"): Amended, read]
  sint64 OperationTime;
  [WmiDataId(2),Description("TextData"): Amended, read, StringTermination("NullTerminated")]
  string TextData;
};

II.C. Le Contrôleur

A présent nous savons comment générer des événements depuis une application. Il nous reste à voir comment créer et démarrer une trace.

Nous allons écrire la classe TETWTraceControler à cet effet.

ETW permet de configurer la trace très finement. Pour TETWTraceControler nous allons simplifier cette configuration en figeant une partie des paramètres. Pour démarrer une trace, nous nous contenterons d'un nom de trace et d'un nom de fichier. Si le nom du fichier de trace n'est pas précisé, on démarrera une trace temps réel.

Une fois la trace démarrée, il faut activer les providers voulus un par un.

Au minimum, le contrôleur doit assurer quatre opérations :

  • Démarrer la trace.
  • Arrêter la trace
  • Activer un provider
  • Désactiver un provider

Les deux premiers traitements seront implémentés dans le constructeur et le destructeur de la classe.

La déclaration de TETWTraceControler est la suivante :

 
Sélectionnez

// TETWTraceControler
// Cette classe représente une session de trace active.
// On démarre une trace en instanciant la classe.
// Lorsque l'instance est détruite, la trace est automatiquement stoppée.
TETWTraceControler = class(TObject)
private
  FRunningSession : TRACEHANDLE;// Handle de la trace en cours.
  FName : string; // Nom utilisé pour créer la trace.
  FFileName : string; // Nom du fichier de trace si on trace dans un
                      // fichier.
  FControlGuid : TGUID; // GUID utilisé pour créer la trace.
  FTrcProps : TTraceProperties; // Propriétés de la trace en cours.
  FEnabledProviders : TStrings; // Liste des providers activés pour la trace.
public
  // Crée et initialise une nouvelle instance de la classe TETWTraceControler.
  // Cette opération a pour effet de démarrer une nouvelle trace dans ETW.
  // <aName> désigne le nom de la trace. Les noms doivent être uniques.
  // <aFileName> indique le nom du fichier dans lequel la trace doit être
  // écrite. Si aucun nom de fichier n'est précisé, une trace
  // temps réel est lancée.
  // Une fois la trace démarrée, il faut activer les providers avec
  // EnableProvider.
  constructor Create(aName : string; aFileName : string);

  // Détruit la classe et libère les resources associées. La trace est alors
  // arrêtée.
  destructor Destroy; override;

  // Désactive le provider <Guid> pour la session de trace. Ce dernier n'écrit
  // plus d'événement dans la trace.
  procedure DisableProvider(Guid : TGUID);

  // Active le provider <Guid> pour la session de trace, avec le niveau de
  // trace <EnableLevel> et les flags <EnableFlags>.
  // Attention, avec ETW, un provider ne peut être activé que pour une seule
  // trace à la fois. On obtiendra une erreur si le provider est déjà actif
  // dans une autre trace.
  procedure EnableProvider(Guid : TGUID; EnableLevel : byte;
    EnableFlags : cardinal);

  // Provoque l'écriture immédiate des buffers dans la trace. Pour une trace
  // temps réel, celà permet d'envoyer les événements au client avant que les
  // buffers ne soient plein.
  // Par contre, il est préférable de ne pas faire de Flush avec une trace
  // fichier car ce sont les buffers complets qui sont écrits sur disque, même
  // s'ils ne sont pas pleins.
  procedure Flush;

  // Décode la chaîne de caractères <provider> pour en extraire le GUID d'un
  // provider ainsi que son état d'activation.
  // <provider> est une chaîne retournée par EnumerateRegisteredProviders.
  // <providerGUID> : en sortie, ce paramètre contient le GUID du provider.
  // <Enabled> : En sortie, indique si le provider est actuellement en cours
  // d'utilisation dans une trace. Un provider ne peut être activé
  // que dans une seule trace à la fois.
  class procedure DecodeProviderInfo(provider : string;
    var providerGUID : string;
    var Enabled : boolean);

  // Retourne dans <aList> la liste des providers disponibles dans ETW, c'est
  // à dire, ceux qui se sont déclarés avec RegisterTraceGuids.
  class procedure EnumerateRegisteredProviders(aList : TStrings);

  // Retourne dans <aList> la liste des traces en cours d'exécution sur la
  // machine.
  // La liste est renvoyé sous la forme : SessionName + #9 + FileName
  class procedure EnumerateRunningTraces(aList : TStrings);
end;

II.C.1. Démarrer une trace

Le constructeur doit créer et démarrer la trace.

Pour cela, on initialise la structure FTrcProps pour spécifier tous les paramètres de la trace, puis on appelle la fonction StartTrace.

Le code est le suivant :

 
Sélectionnez

// Crée et initialise une nouvelle instance de la classe TETWTraceControler.
// Cette opération a pour effet de créer une nouvelle session de trace dans
// ETW, et de démarrer la trace.
// <aName> désigne le nom de la trace. Les noms doivent être uniques.
// <aFileName> indique le nom du fichier dans lequel la trace doit être écrite.
//             si aucun nom de fichier n'est précisé, une trace temps réel
//             est lancée.
// Une fois la trace démarrée, il faut activer les providers avec EnableProvider.
constructor TETWTraceControler.Create(aName: string; aFileName : string);
begin
  // On mémorise les paramètres d'appel.
  FName := aName;
  FFileName := aFileName;
  FControlGuid := ETWTraceControlerGuid;
  // Il faut toujours commencer par initialiser la structure à 0.
  fillchar(FTrcProps, sizeof(FTrcProps), 0);
  FTrcProps.Props.Wnode.BufferSize := sizeof(FTrcProps); // On définit la taille
  // de la structure.
  FTrcProps.Props.Wnode.Flags := WNODE_FLAG_TRACED_GUID; // Valeur obligatoire.
  FTrcProps.Props.Wnode.ClientContext := 1; // Les TimeStamp seront définis
  // avec les compteurs de performance
  // windows.
  FTrcProps.Props.Wnode.Guid := FControlGuid; // Identifiant de la session.
  FTrcProps.Props.BufferSize := 64; // Taille des buffers en Ko.
  FTrcProps.Props.MinimumBuffers := 8; // Nombre de buffer à pré allouer.
  FTrcProps.Props.MaximumBuffers := 16; // Nombre maximum de buffers.
  
  // LoggerNameOffset doit être initialisé avec l'offset de SessionName
  // par rapport à la structure EVENT_TRACE_PROPERTIES. Ca aurait  être
  // sizeof(FTrcProps.Props). Cependant, avec cette valeur, StartTrace renvoie
  // toujours ERROR_INVALID_PARAMETER.
  // Par contre une valeur de 128 (>à la position normale) est acceptée.
  // Il s'agit peut être d'un problème d'alignement des adresses en mémoire.
  // C'est pourquoi j'ai ajouté un champ Filler pour aligner SessionName sur
  // l'offset 128.
  FTrcProps.Props.LoggerNameOffset := sizeof(FTrcProps.Props) +
    sizeof(FTrcProps.filler);
  FTrcProps.Props.LogFileNameOffset := FTrcProps.Props.LoggerNameOffset +
    sizeof(FTrcProps.SessionName);

  // On définit le nom du fichier de trace.
  // Attention, pour TETWTraceControler, un nom de fichier vide signifie une trace
  // temps réel. Cependant avec ETW, il est possible de définir une trace temps
  // réel et un nom de fichier. En principe, ETW envoie alors les événements au
  // client en temps réel, tout en les écrivant sur disque.
  strcopy(@FTrcProps.FileName[0], PChar(FFileName));

  if aFileName = '' // Pas de nom de fichier, on crée une trace temps réel.
  then begin
    FTrcProps.Props.LogFileMode := EVENT_TRACE_REAL_TIME_MODE or
      EVENT_TRACE_USE_PAGED_MEMORY;
    FTrcProps.Props.LogFileNameOffset := FTrcProps.Props.LoggerNameOffset +
      sizeof(FTrcProps.SessionName);
      
    FTrcProps.Props.FlushTimer := 1; // Les buffers doivent être écrits toutes
    // les secondes.
  end
  else begin
    // On a un nom de fichier, on crée une trace fichier.
    FTrcProps.Props.LogFileMode := EVENT_TRACE_FILE_MODE_CIRCULAR or
      EVENT_TRACE_USE_PAGED_MEMORY;
    FTrcProps.Props.MaximumFileSize := 100;
  end;
  
  // Commence par essayer d'arrêter la trace pour le cas  il existerait déjà
  // une trace avec le même nom. C'est par exemple le cas si on a démarré une
  // trace temps réel et que le contrôleur n'a pas été fermé proprement.
  StopTrace(0, PChar(FName), @FTrcProps);
  
  // On demande à ETW de démarrer la trace.
  if StartTrace(FRunningSession, PChar(FName), @FTrcProps)<>ERROR_SUCCESS
    then raiseLastOSError;

  FEnabledProviders := TStringList.Create;
end;

FTrcProps est une structure définie de la façon suivante :

 
Sélectionnez

TTraceProperties = packed record
  Props : EVENT_TRACE_PROPERTIES;
  filler : array[0..11] of char;
  SessionName : array[0..511] of char;
  FileName : array[0..511] of char;
end;

En fait, il s'agit d'une structure EVENT_TRACE_PROPERTIES à laquelle on ajoute une zone pour recevoir le nom de la trace, et une zone pour indiquer le nom du fichier de trace. Selon la documentation Microsoft, SessionName et FileName devraient suivre immédiatement après la fin de EVENT_TRACE_PROPERTIES. Cependant, dans la pratique si on fait ça, on obtient une erreur INVALID_PARAMETERS lorsqu'on spécifie un nom de fichier. On ne rencontre plus cette erreur si on ajoute quelques octets de calage (Filler) avant SessionName. Sans ces octets, EVENT_TRACE_PROPERTIES possède une taille de 116. Avec Filler, SessionName a un offset de 128. Il s'agit sûrement d'un problème d'alignement des adresses en mémoire, et peut-être d'un problème de traduction de la structure EVENT_TRACE_PROPERTIES en pascal.

Les informations importantes à initialiser sont les suivantes :

  • Wnode.bufferSize : Comme pour la plupart des fonctions de l'API Win32, le premier champ de la structure doit indiquer la taille totale de la structure.
  • Wnode.ClientContext : Ce champ est très mal nommé. En réalité il sert à indiquer le type d'horloge qu'on souhaite utiliser pour l'horodatage des événements. Avec la valeur 0, ETW utilise l'horloge système, c'est-à-dire les ticks bien connus. Cette dernière possède une résolution de 15ms à peu près, ce qui signifie qu'on ne peut pas mesurer de durée inférieure. Si on veut utiliser la trace pour profiler une application, cette résolution est très insuffisante. C'est pourquoi, on va utiliser les compteurs de performances en indiquant la valeur 1. En effet, de cette façon, on obtient une précision de 100 ns.
  • BufferSize : A ne pas confondre avec Wnode.bufferSize. Ce champ permet d'indiquer la taille des buffers intermédiaires utilisés par ETW pour stocker les événements avant de les écrire sur disque ou de les envoyer au client. ETW n'écrit un buffer que lorsque ce dernier est plein, ou sur tempo. Nous allons fixer cette valeur arbitrairement à 64 Ko.
  • MinimumBuffers : indique le nombre de buffers qu'ETW doit pré allouer au moment du démarrage de la trace. Ce nombre doit être au minimum égal au nombre de processeurs de la machine plus deux. Nous allons le définir à 8.
  • MaximumBuffers : indique le nombre maximum de buffers utilisés par ETW. Si les événements sont générés plus vite que les buffers n'arrivent à s'écrire sur disque ou que le client ne les consomme, ETW alloue des buffers supplémentaires pour les mémoriser. Lorsque la limite maximale est atteinte, des événements pourront être perdus. Pour l'usage qu'on veut en faire, il est très peu probable qu'on perde le moindre événement, quel que soit le paramétrage des buffers. Nous fixerons cette limite à 16.
  • LoggerNameOffset : Cette valeur doit indiquer l'offset de la zone prévue pour contenir le nom de la trace. Dans notre cas, il s'agit de l'offset de SessionName.
  • LogFileNameOffset : Cette valeur doit indiquer l'offset de la zone pour le nom du fichier. Dans notre cas, il s'agit de FileName.

Les autres paramètres dépendent du type de trace qu'on veut lancer.

Pour une trace temps réel :

  • LogFileMode : Pour une trace temps réel, ce champ doit avoir le flag EVENT_TRACE_REAL_TIME_MODE. On active également le flag EVENT_TRACE_USE_PAGED_MEMORY pour respecter les préconisations Microsoft. En effet, la documentation préconise de toujours l'activer sauf si on a des contraintes mémoires particulières. En clair, si on ne trace pas un driver de périphérique il faut l'activer sans se poser de questions.
  • FlushTimer : Ce champ indique un timer en secondes au bout duquel le buffer doit être écrit même s'il n'est pas plein. Pour une trace temps réel, on l'initialise à 1 pour que les événements soient envoyés au client au moins une fois par seconde. Pour une trace fichier, ça signifierait avec une taille de buffer de 64 Ko qu'on écrirait au minimum 64Ko/s dans la trace. Pour une trace fichier, il faudrait plutôt utiliser une grande valeur.

Pour une trace fichier :

  • LogFileMode : Il faut indiquer le mode de gestion du fichier. Différents cas peuvent s'envisager, gestion circulaire, limité à une taille maximale avec bascule sur un autre fichier... Nous définirons une gestion circulaire plus simple à gérer avec le flag EVENT_TRACE_FILE_MODE_CIRCULAR.
  • MaximumFileSize : Comme le mode circulaire est utilisé, il faut obligatoirement définir une taille maximale de fichier. Cette taille se définit en Mo.

Il ne reste plus qu'à appeler StartTrace pour créer la trace.

Par commodité, on commence par vérifier si une trace avec le même nom n'existe pas déjà en essayant de l'arrêter avec StopTrace. En effet les traces sont gérées de façon globale par Windows. Si l'application qui héberge le contrôleur crashe violemment (ou qu'on fait un petit CTRL+F2 dans Delphi) et que la trace n'est pas arrêtée proprement, elle reste active dans Windows jusqu'au prochain reboot et interdit la création d'une trace avec le même nom (voir même de toute autre trace s'il s'agit d'une trace temps réel).

II.C.2. Arrêter une trace

Le destructeur doit arrêter la trace. La méthode préconisée est d'envoyer le code de contrôle EVENT_TRACE_CONTROL_STOP à la trace avec ControlTrace. On pourrait aussi utiliser StopTrace mais cette fonction est dépréciée.

Avant d'arrêter la trace, il faut commencer par désactiver tous les providers qui ont été activés. Comme on ne peut pas faire confiance au développeur pour arrêter les providers, TETWTraceControler maintient une liste des providers activés et les arrête automatiquement avant d'arrêter la trace.

Le code du destructeur est le suivant :

 
Sélectionnez

// Détruit la classe et libère les ressources associées. La trace est alors
// arrêtée.
destructor TETWTraceControler.Destroy;
var i : integer;
begin
  // On commence par désactiver tous les providers qui ont été activés.
  if Assigned(FEnabledProviders)
  then begin
    // On parcourt la liste à l'envers car DisableProvider va retirer le
    // provider de la liste au fur et à mesure que ces derniers sont désactivés.
    for i := FEnabledProviders.Count -1 downto 0 do
    begin
      DisableProvider(StringToGuid(FEnabledProviders[i]));
    end;
    FEnabledProviders.Free;
  end;
  // Arrête la trace en lui envoyant l'événement EVENT_TRACE_CONTROL_STOP
  // FTrcProps a été initialisé au moment de la création de la trace.
  ControlTrace(FRunningSession, nil, @FTrcProps, EVENT_TRACE_CONTROL_STOP);
end;

II.C.3. Activer/Désactiver un Provider

Une fois la trace démarrée, les providers doivent être activés ou désactivés individuellement. Un provider ne génère pas d'événements pour une trace tant qu'il n'a pas été activé.

De plus un provider ne peut être activé que pour une seule trace à la fois. Par contre, il est possible de l'activer avant que ce dernier ne se soit déclaré disponible avec RegisterTraceGuid. Ainsi on peut démarrer une trace et activer ses providers avant que l'application tracée ne soit lancée.

L'activation/désactivation d'un provider s'effectue avec la fonction EnableTrace, en indiquant le GUID du provider, son niveau d'activation et ses flags d'activation.

Le code des méthodes EnableProvider et DisableProvider est le suivant :

 
Sélectionnez

// Désactive le provider <Guid> pour la session de trace. Ce dernier n'écrit
// plus d'événement dans la trace.
procedure TETWTraceControler.DisableProvider(Guid: TGUID);
var idx : integer;
begin
  // Arrêt du provider dans ETW.
  if EnableTrace(TRACE_OFF, 0, 0, @GUID, FRunningSession)<>ERROR_SUCCESS
  then RaiseLastOSError;
  
  // On doit à présent retirer le provider de la liste des providers actifs.
  idx := FEnabledProviders.IndexOf(GuidToString(Guid));
  if idx<>-1
  then FEnabledProviders.Delete(idx);
end;

// Active le provider <Guid> pour la session de trace, avec le niveau de trace
// <EnableLevel> et les flags <EnableFlags>.
procedure TETWTraceControler.EnableProvider(Guid : TGUID; EnableLevel : byte;
  EnableFlags : cardinal);
begin
  // On commence par vérifier si le provider n'a pas déjà été activé.
  if FEnabledProviders.IndexOf(GuidToString(Guid)) = -1
  then begin
    // Activation du provider.
    if EnableTrace(TRACE_ON, EnableFlags, EnableLevel,
      @GUID, FRunningSession)<>ERROR_SUCCESS
    then RaiseLastOSError;

    // On ajoute le provider à la liste des providers déjà activés.
    FEnabledProviders.Add(GuidToString(Guid));
  end;
end;

II.C.4. Enumérer la liste des providers disponibles

Il est possible d'énumérer tous les providers qui se sont déclarés avec RegisterTraceGuids.

Il suffit pour cela d'appeler la fonction EnumerateTraceGuids en lui fournissant un tableau de structures TRACE_GUID_PROPERTIES. EnumerateTraceGuids remplira alors ce tableau avec le GUID de chaque provider ainsi que son état d'activation actuel.

Si le tableau fournit à EnumerateTraceGuids est trop petit (il y a plus de providers que prévu), EnumerateTraceGuids retourne ERROR_MORE_DATA et il faut recommencer avec un tableau plus grand pour obtenir une liste complète.

Pour simplifier l'appel à EnumerateTraceGuids, TETWTraceControler fournit la méthode de classe EnumerateRegisteredProviders qui retourne cette liste de providers sous la forme d'un TStrings :

 
Sélectionnez

// Retourne dans <aList> la liste des providers disponibles dans ETW, c'est
// à dire, ceux qui se sont déclarés avec RegisterTraceGuids.
class procedure TETWTraceControler.EnumerateRegisteredProviders(
  aList: TStrings);
var nbProviders : cardinal;
    Properties : array of TRACE_GUID_PROPERTIES;
    PropertiesPtr : array of PTRACE_GUID_PROPERTIES;
    MaxProv : cardinal;
    i : integer;
    result : cardinal;
    s : string;

    // Initialise les tableaux <Properties> et <PropertiesPtr> pour stocker un
    // maximum de <nbProv>.
    procedure InitTabs(nbProv : integer);
    var i : integer;
    begin
      // Properties est un tableau linéaire de structures TRACE_GUID_PROPERTIES.
      // PropertiesPtr est un tableau qui pointe sur les éléments de Properties
      // un à un.
      SetLength(Properties, nbProv);
      SetLength(PropertiesPtr, nbProv);

      // On commence par initialiser les tableaux à 0.
      fillchar(Properties[0], sizeof(TRACE_GUID_PROPERTIES) * nbProv, 0);

      // Il ne reste plus qu'à initialiser chaque élément de PropertiesPtr pour les
      // faire pointer sur un élément de Properties.
      for i := 0 to nbProv -1 do
      begin
        PropertiesPtr[i] := @Properties[i];
      end;
    end;

begin
  Assert(Assigned(aList)); // aList doit avoir été initialisé créé par
                           // l'appelant.
  aList.Clear;

  // Par défaut, on prévoie de lire 50 providers.
  MaxProv := 50;
  nbProviders := MaxProv;

  // On prépare un tableau pour MaxProv fournisseurs au maximum.
  InitTabs(MaxProv);

  // On demande à ETW d'énumérer les providers déclarés.
  // EnumerateTraceGuids va remplir le tableau Properties avec la liste des
  // providers disponibles. <MaxProv> indique la taille maximal du tableau.
  // En retour <nbProviders> contiendra le nombre total de provider déclaré dans
  // ETW.
  // Si le tableau Properties est trop petit (il y a plus 50 providers déclaré)
  // EnumerateTraceGuids renverra le code de retour ERROR_MORE_DATA. Dans ce cas
  // il faut recommencer l'opération avec un tableau plus grand.
  result := EnumerateTraceGuids(PropertiesPtr, MaxProv, nbProviders);
  case result of
    ERROR_SUCCESS:; // Tout est Ok.
    ERROR_MORE_DATA: // Il y a plus de provider que prévu, il faut agrandir le
                     // tableau.
      begin
        MaxProv := nbProviders;
        InitTabs(MaxProv); // On redéfinit les tableaux. Cette fois on connait le
        // nombre exact de providers qui seront renvoyés.
        // Il ne reste plus qu'à refaire la lecture.
        if EnumerateTraceGuids(PropertiesPtr, MaxProv, nbProviders)<>ERROR_SUCCESS
        then raiseLastOSError;
      end;
    else RaiseLastOSError;
  end;

  // Les informations ont été obtenues dans Properties. On met le résultat en
  // forme pour remplir <aList>.
  for i := 0 to nbProviders-1 do
  begin
    s := GuidToString(Properties[i].Guid);
    if Properties[i].IsEnable<>0
    then s := s + '=1'
    else s := s + '=0';
    aList.Add(s);
  end;
end;

II.D. Le Client

Le client peut être le composant le plus complexe à réaliser si on veut exploiter pleinement toutes les fonctionnalités d'ETW.

Dans un premier temps nous nous contenterons de traiter des événements dont on connaît parfaitement la structure. Nous verrons comment décoder un événement générique à partir de sa publication MOF dans la partie V.

L'implémentation du client est découpée en trois classes :

  • TEventTrace : Cette classe est la classe de base pour tous les événements qu'on peut lire dans la trace. Elle modélise les informations communes à tous, c'est-à-dire les informations de l'en-tête.
  • TSQLEvent : Cette classe dérive de TEventTrace pour décoder les événements générés par TSQLLogger.
  • TETWClient : C'est la classe principale pour lire la trace. Elle permet d'ouvrir une trace existante (trace fichier ou trace temps réel) et de lire ses événements. Elle génère une collection d'objets TEventTrace, un pour chaque événement de la trace.

Commençons par examiner TETWClient :

 
Sélectionnez

type
  // TETWClient
  // Cette classe permet de lire une trace existante et traiter ses événements.
  TETWClient = class(TObject)
  private
    FWorkerThread : TThread;
    FTrace : EVENT_TRACE_LOGFILE; // en-tête de la trace qui a été ouverte.
    FList : TList; // Liste des événements de la trace.
    FSession : TRACEHANDLE; // Handle de la trace ouverte.
    FTraceMutex : Cardinal;
  protected
    // ProcessEvent est appelée par la fonction callback chaque fois qu'un
    // événement de la trace est lu. Cette méthode s'occupe de décoder
    // l'enregistrement et de le mémoriser.
    procedure ProcessEvent(pEvent : PEVENT_TRACE); virtual;

  public
    // Crée et initialise une nouvelle instance de la classe TETWClient :
    // Ouvre une trace existante et commence à lire ses événement. On peut lire
    // une trace fichier ou une trace temps réel.
    // Si on ouvre une trace fichier, le constructeur rend la main une fois que
    // tous les événements de la trace ont été lus.
    // Si on ouvre une trace temps réel, le constructeur rend immédiatement la
    // main, les événements seront lus au fur et à mesure de leur réception en
    // tâche de fond.
    // <Name> : Si on veut ouvrir une trace fichier, <Name> doit contenir le nom
    //          du fichier .etl à ouvrir. Si on veut ouvrir une trace temps réel,
    //          <Name> doit contenir le nom de la session de trace à ouvrir.
    // <IsRealTime> : Indique si on veut ouvrir une trace temps réel (true) ou
    //                une trace fichier (false).
    // ATTENTION: TETWClient ne peut traiter qu'une seule trace à la fois.
    //            Ca ne pose pas de problème avec les traces fichiers puisque
    //            le constructeur ne rend la main qu'une fois le traitement de
    //            la trace terminé.
    //            En revanche, si on lit une trace temps réel, on ne pourra pas
    //            lire d'autres traces tant que la trace n'aura pas été arrêtée !
    constructor Create(Name : string; IsRealTime : boolean);

    // Détruit la classe et libère les ressources.
    destructor Destroy; override;

    // Fonction utilitaire permettant de convertir les timestamps de la trace
    // en Date et Heure Delphi.
    function GetDateTime(ClockTime : int64) : TDateTime;

    // Efface les événements de la trace.
    procedure ClearTrace;

    // Ajoute l'événement Event dans la trace.
    procedure AddEvent(Event : TEventTrace);

    // Indique que l'on veut modifier la trace. Cette méthode permet d'obtenir
    // un accès exclusif à la trace.
    procedure Lock;

    // Indique que l'on a finit de modifier la trace.
    procedure UnLock;

    // Trie la trace par ordre chronologique.
    procedure SortTrace;

    // Liste des événements lus depuis la trace.
    property Trace : TList read FList;
  end;

II.D.1. Ouvrir une trace existante

Comme on peut le voir, la classe se résume pour ainsi dire à son constructeur et son destructeur.

Pourtant le travail du constructeur est relativement complexe :

 
Sélectionnez

constructor TETWClient.Create(Name: string; IsRealTime: boolean);
var result : cardinal;
begin
  // On ne peut traiter qu'une seule trace à la fois. Il faut donc commencer
  // par vérifier qu'aucune autre trace n'est en cours de traitement.
  if Assigned(ActiveClient)
  then raise Exception.Create('Il y a déjà une trace en cours de traitement.');

  // On prépare une structure EVENT_TRACE_LOGFILE pour ouvrir la trace.
  fillchar(FTrace, sizeof(FTrace), 0); // Initialise la structure à 0.

  if isRealTime
  then begin
    // Pour les traces temps réel, il faut initialiser LoggerName avec le nom
    // de la trace.
    FTrace.LoggerName := PChar(Name);

    // Le mode de traitement de la trace doit également être Temps réel.
    FTrace.LogFileMode := EVENT_TRACE_REAL_TIME_MODE;
  end
  else begin
    // Pour les traces fichiers, il faut indiquer le nom du fichier à traiter
    // dans LogFileName.
    FTrace.LogFileName := PChar(Name);
  end;

  // On définit la méthode Callback pour traiter les événements.
  FTrace.EventCallback := EventCallback;

  // Il ne reste plus qu'à ouvrir la trace.
  FSession := OpenTrace(@FTrace);
  if FSession = INVALID_HANDLE_VALUE
  then raiseLastOSError;

  // Pour les traces temps réel, l'information TimeZone n'est pas écrite dans
  // L'en-tête. Il faut la lire auprès du système.
  if IsRealTime
  then GetTimeZoneInformation(FTrace.LogfileHeader.TimeZone);

  // Remarque : Dans ETW, il est possible de lire plusieurs fichiers de trace
  //            en appelant plusieurs fois OpenTrace avec des fichiers
  //            différents.
  //            Les événements provenant de chaque fichier sont alors mélangés
  //            et ordonnés d'après leur timestamp pour être restitués dans
  //            l'ordre au client.
  //            Cependant notre implémentation ne traite qu'un seul fichier à
  //            la fois.

  FList := TList.Create; // Initialise la liste des événements de la trace.

  // Maintenant il faut lancer le traitement des événements. Pour une trace
  // temps réel, on délègue cette opération à un thread distinct. Pour une trace
  // fichier on effectue le traitement immédiatement.
  if IsRealTime
  then FWorkerThread := TWorkerThread.create(self)
  else begin
    // On commence par se définir comme la trace en cours de traitement.
    ActiveClient := self;
    try
      // L'appel de ProcessTrace demande à ETW de commencer à lire les
      // événements et d'appeler la méthode Callback.
      result := ProcessTrace(@FSession, // Session à traiter.
                             1,         // Une seule session à traiter.
                             nil,       // Pas de date de début.
                             nil);      // Ni de date de fin.
      if (result<>ERROR_SUCCESS) and (result<>ERROR_CANCELLED)
      then raiseLastOSError;
    finally
      // Le traitement de la trace est terminé.
      ActiveClient := nil;
    end;
  end;
end;

Le traitement d'une trace se déroule en trois temps :

  • Tout d'abord il faut ouvrir une ou plusieurs traces existantes : soit une trace temps réel identifiée à partir de son nom, soit une trace fichier à partir du nom du fichier. Cette opération s'effectue avec OpenTrace.
  • Ensuite on demande à ETW de traiter la trace. ETW lit alors toutes les traces ouvertes, les fusionne, trie les événements dans l'ordre chronologique et appelle une fonction callback du client pour chaque événement ainsi obtenu. C'est de cette façon que le client obtient les événements de la trace. Le traitement des traces démarre avec ProcessTrace.
  • Le client doit écrire une fonction callback pour traiter chaque événement un par un (dans la pratique on se contente de recopier l'événement dans une liste).

Nous nous contenterons d'ouvrir une seule trace à la fois. Voyons comment appeler OpenTrace :

Comme pour la plupart des fonctions de l'API Windows, il faut commencer par initialiser une structure avec les propriétés de la trace à ouvrir. Il s'agit d'une structure EVENT_TRACE_LOGFILE.

Les informations importantes à renseigner sont les suivantes :

  • LoggerName : Si on ouvre une trace temps réel, il faut indiquer le nom de la session de trace dans LoggerName.
  • LogFileName : Si on ouvre une trace fichier, LogFileName permet d'indiquer le nom du fichier de la trace. LogFileName et LoggerName sont mutuellement exclusifs. Si on renseigne l'un, il ne faut pas renseigner l'autre.
  • LogFileMode : Si on ouvre une trace temps réel, il faut initialiser ce champ avec EVENT_TRACE_REAL_TIME_MODE.
  • EventCallback : Ce champ permet d'indiquer un pointeur sur la fonction callback pour le traitement de la trace.

Il s'agit des informations minimales à définir. La plupart des champs de EVENT_TRACE_LOGFILE seront renseignés en sorti avec des informations sur la trace elle-même.

Il existe également une autre fonction callback : le BufferCallback. Cette fonction est appelée chaque fois qu'ETW a fini de traiter un buffer. Elle permet de calculer des statistiques sur la trace. Son intérêt est donc limité en ce qui nous concerne.

Il ne reste plus qu'à appeler OpenTrace. Si la fonction réussit, elle retourne un handle sur la trace qui a été ouverte.

Une fois OpenTrace exécutée avec succès on lance le traitement de la trace avec ProcessTrace.

ProcessTrace ne rend la main qu'une fois que tous les événements de la trace ont été traités. Pour une trace temps réel, ProcessTrace ne rend pas la main tant que la trace n'a pas été fermée.

C'est pourquoi dans le cas d'une trace temps réel, nous appelons ProcessTrace dans un thread séparé.

II.D.2. Traiter les événements

La fonction callback est très simple à écrire. Elle délègue simplement le traitement de l'événement à la méthode ProcessEvent de TETWClient.

Le seul problème c'est que cette fonction ne dispose d'aucun moyen pour identifier la trace qui a déclenché l'appel. Aussi, on est obligé de passer par une variable globale pour retrouver l'instance TETWClient en cours de traitement.

Cette variable globale nous impose de ne traiter qu'une seule trace à la fois.

Le code est le suivant :

 
Sélectionnez

// EventCallback est appelée par ETW chaque fois qu'un événement est lu depuis
// la trace. Cette fonction doit lire l'événement et le traiter.
// En fait, elle sert de relais pour appeler la méthode ProcessEvent de
// l'instance TETWClient qui veut lire la trace.
procedure EventCallBack(pEvent : PEVENT_TRACE); stdcall;
begin
  // On délègue simplement la gestion de l'événement à TETWClient.
  if Assigned(ActiveClient)
  then ActiveClient.ProcessEvent(pEvent);
end;

Puis la méthode ProcessEvent :

 
Sélectionnez

// ProcessEvent est appelée par la fonction callback chaque fois qu'un
// événement de la trace est lu. Cette méthode s'occupe de décoder
// l'enregistrement et de le mémoriser.
procedure TETWClient.ProcessEvent(pEvent: PEVENT_TRACE);
var
  Data : TEventTrace;
begin
  Data := nil;

  // On ne traite que les EventClass SQLEventClass ou DefaultEventClass
  if ((int64(pEvent^.Header.Guid.D1) = int64(SQLEventClass.D1)) and
    (int64(pEvent^.Header.Guid.D4) = int64(SQLEventClass.D4)))
  then Data := TSQLEvent.Create(pEvent);

  if ((int64(pEvent^.Header.Guid.D1) = int64(DefaultEventClass.D1)) and
    (int64(pEvent^.Header.Guid.D4) = int64(DefaultEventClass.D4)))
  then Data := TDefaultEvent.Create(pEvent);

  if Assigned(Data)
  then AddEvent(Data);
end;

La méthode ne traite que les événements DefaultEventClass générés par le GenericLogger, et les événements SQLEventClass générés par le logger SQL.

Les autres événements que pourrait contenir la trace sont ignorés.

Pour ajouter les événements dans la trace, on utilise la méthode AddEvent. Cette dernière a été écrite pour insérer les événements dans la trace, à la position qui correspond à l'ordre chronologique. Avec les traces temps réel, ETW nous envoie les buffers lorsqu'ils sont pleins ou lorsqu'on les vide. Or cet ordre ne respecte pas nécessairement l'ordre chronologique. Si on ne trie pas les événements, la trace obtenue est dans le désordre.

Attention, ce tri effectué à la volé est très consommateur en temps CPU. Si on veut traiter des événements rapides, ce tri risque de provoquer une perte d'événements.

II.D.3. Fermer une trace

Le destructeur doit bien évidemment libérer les ressources utilisées par l'objet. Cependant en plus de ce nettoyage classique, il doit également libérer les handles alloués lors de l'appel à OpenTrace.

Cette opération s'effectue simplement en appelant CloseTrace :

 
Sélectionnez

// Détruit la classe et libère les ressources.
destructor TETWClient.Destroy;
var i : integer;
begin
  // On s'assure que la variable globale ActiveClient ne pointe plus sur
  // l'instance en cours de destruction.
  if ActiveClient = self
  then ActiveClient := nil;

  // On libère le handle FSession obtenu lors de l'appel à OpenTrace.
  if FSession<>0
  then CloseTrace(FSession);
  if Assigned(FWorkerThread)
  then begin
    FWorkerThread.Free;
    FWorkerThread := nil;
  end;

  // Il ne reste plus qu'à détruire les données de la trace elle même.
  if Assigned(FList)
  then begin
    for i := 0 to FList.Count-1 do
    begin
      TObject(FList[i]).Free;
    end;
    FList.Free;
  end;
  inherited Destroy;
end;

II.D.4. La méthode GetDateTime

Les événements de la trace sont horodatés selon une horloge interne très précise (100 ns). On peut utiliser cet horodatage pour calculer la date et l'heure de l'événement.

En fait le calcul est assez simple à faire. Les timestamp correspondent au nombre d'intervalles de 100 nanosecondes écoulés depuis le 1er janvier 1601.

Les dates Delphi correspondent au nombre de jours écoulés depuis le 1er janvier 1900.

Pour faire la conversion, il suffit de convertir le timestamp en nombre de jours et d'appliquer le décalage entre les deux références. On obtient alors la date et l'heure précise de l'événement en temps universel.

Pour l'afficher ensuite correctement, il faut tenir compte de l'heure locale, c'est à dire appliquer le décalage horaire à l'heure ainsi obtenue.

Ce décalage nous est fournit dans l'en-tête de la trace. Il suffit de lire LogfileHeader.TimeZone.Bias. Il est exprimé en minutes.

Au final la conversion devient :

 
Sélectionnez

// Fonction utilitaire permettant de convertir les timestamps de la trace
// en Date et Heure Delphi.
function TETWClient.GetDateTime(ClockTime: int64): TDateTime;
var bias : int64;
begin
  // ClockTime désigne le nombre de nanosecondes écoulées depuis le 01/01/1601.
  // Les dates Delphi indiquent le nombre de jours écoulés depuis le 01/01/1900.
  // Cependant, le temps dans ClockTime est un temps UTC (temps universel).
  // Pour le convertir en date/heure classique, il faut tenir compte du
  // fuseau horaire. Heureusement, ces informations nous sont fournies dans
  // l'en-tête de la trace : Le décalage horaire en minutes nous est indiqué
  // dans TimeZone.Bias, selon la formule :
  // Temps UTC = Temps réel + Bias.
  bias := FTrace.LogfileHeader.TimeZone.Bias;

  // Il faut lire TimeZone.Bias dans un int64, puis le convertir en Nanosecondes
  // dans un deuxième temps. Si on fait la conversion dans la même ligne, Delphi
  // fait le calcul avec un integer et donc fait un overflow.
  bias := bias * 60*1000*10000;

  // Il ne reste plus qu'à faire la conversion.
  result := (ClockTime-bias-t0) / TimeDay;
end;

Avec :

 
Sélectionnez

// TimeDay : Durée d'une journée pour la conversion des timestamps
const TimeDay = 864000000000;
      T0 = 109205 * TimeDay; // Durée du décalage entre la référence des dates
                             // Delphi et la référence des dates ETW.

Nous avons ainsi réalisé un client simple complet.

Il ne reste plus qu'à faire l'IHM pour utiliser le tout.

III. Le Profiler SQL

Nous venons de développer tous les composants nécessaires à la mise en oeuvre d'ETW. On peut à présent revenir au problème initial, écrire un profiler SQL qui pourra fonctionner quel que soit le SGBD utilisé.

La seule chose qui nous reste à faire, c'est un programme qui réunit le tout :

Image non disponible

L'application se compose d'une seule fenêtre. Une barre d'outils permet de lancer trois commandes :

  • Démarrer la trace : Démarre une trace temps réel et active les deux providers GenericLogger et SQLLogger.
  • Arrêter la trace : Arrête simplement la trace.
  • Effacer la trace : Efface la liste des événements.

Une grille affiche les événements de la trace. Seuls les champs importants sont affichés :

  • La première colonne indique le numéro de la ligne dans la trace.
  • La deuxième colonne indique la classe de l'événement (SQL Trace pour SQLLogger, EVENT pour GenericLogger).
  • La troisième colonne indique le type de l'événement.
  • La quatrième colonne indique le temps écoulé depuis la ligne précédente, en ms.
  • Enfin la dernière colonne indique la requête SQL.

Un splitter permet de redimensionner la grille.

Lorsqu'on sélectionne un événement de type requête SQL, on affiche la requête complète dans un mémo.

Enfin une barre d'état affiche des informations sur les événements sélectionnés. En particulier le temps écoulé entre deux événements.

Pour démarrer la trace on écrit :

 
Sélectionnez

// Crée et démarre une trace temps réel.
FTraceControler := TETWTraceControler.Create(TraceSessionName, '');
// On active les deux providers DefaultLogger et SQLLogger.
FTraceControler.EnableProvider(DefaultLogger, TRACE_LEVEL_VERBOSE, 0);
FTraceControler.EnableProvider(SQLLoggerGUID, TRACE_LEVEL_VERBOSE, 0);

// On se connecte sur la trace temps réel qu'on vient de créer
try
  FTrace := TETWClient.Create(TraceSessionName, true);
  TmRefresh.Enabled := true; // On active le timer pour rafraichir la trace.
except
  Application.HandleException(self);
  FTraceControler.Free;
  FTraceControler := nil;
end;

Pour arrêter la trace :

 
Sélectionnez

// 0n détruit le controler pour arrêter la trace.
FTraceControler.Free;
FTraceControler := nil;

// Par contre, on garde le client pour pouvoir continuer à afficher la trace.
TmRefresh.Enabled := false; // Il n'est plus nécessaire de rafraichir la trace

Dès lors, la liste FTrace.Trace va automatiquement se remplir avec les événements reçus depuis ETW.

Ces derniers arrivent toutes les secondes ou chaque fois que les buffers internes sont pleins. Pour une trace temps réel, un délai d'une seconde est un peu long. C'est pourquoi on ajoute un timer qui fait un flush de la trace toutes les 100ms.

Il ne reste plus qu'à demander à la grille de se redessiner.

III.A. Affichage des événements dans la grille

Une trace peut contenir un grand nombre d'événements. ETW est conçu pour loguer des événements avec une fréquence élevée. Microsoft annonce une capacité de 20000 événements par seconde tout en générant une charge CPU inférieure à 5%.

Le minimum est donc de prévoir un dispositif d'affichage de la trace capable de tenir une telle cadence.

Pour que la trace soit exploitable, il faut un affichage de type grille. Maintenant la question est quel composant utiliser ?

On peut envisager différents choix :

  • Une TStringGrid : Dans ce cas, il faut définir la valeur de chaque cellule une par une et on n'a pas une grande maitrise sur le format d'affichage de la cellule.
  • Une TDBGrid : Il faudrait commencer par recopier les événements dans un DataSet. Par exemple en utilisant un TClientDataset. On a alors toutes les chances de ne pas tenir la cadence.
  • Un composant tiers : Il ne faut pas se faire d'illusion, il s'agira probablement d'une variante de l'un des deux composants précédents, certainement en plus lourd.

Non, pour tenir une telle cadence, il ne faut pas qu'on soit obligé de recopier les événements dans une autre structure de données. On doit donc être capable d'afficher les événements en allant les lire directement dans FTrace.Trace.

Dès lors, il ne reste plus qu'une seule solution : La TDrawGrid. En effet, avec une TDrawGrid, on n'a qu'une seule chose à faire :

 
Sélectionnez

Grd.RowCount := FTrace.Trace.Count + 2;

Ensuite, on se contente de dessiner les quelques lignes visibles à l'écran. Peu importe le nombre d'événements qui se rajoutent en tâche de fond. On ne traitera que ceux visibles à l'écran.

Nous venons de voir les principaux éléments du profiler. Le projet complet est fournit avec les sources de l'article. Il n'y a qu'à le compiler et lancer la trace. Cependant il ne faut pas oublier que ce profiler ne fait qu'afficher les événements générés avec ETW. Pour qu'il affiche les requêtes exécutées par une application, il faut instrumenter cette dernière pour générer la trace.

III.B. Comment instrumenter son code ?

L'idéal est d'avoir une couche d'accès aux données centralisée. On peut en profiter pour y ajouter les traces.

Dans ce cas, il y a plusieurs étapes importantes à tracer. Au minimum, il faut :

  • Le début d'exécution de chaque requête SQL (TraceSQLBegin).
  • La fin d'exécution de chaque requête (TraceSQLEnd).
  • En cas d'erreur, il faut tracer le message d'erreur (TraceException).
  • Selon les cas, il peut être également intéressant d'indiquer le temps de lecture des données, c'est-à-dire le temps passé à parcourir toutes les lignes renvoyées par la requête pour charger les données.

Donc au minimum, il faudrait respecter le modèle suivant :

 
Sélectionnez

SQLLogger.TraceSQLBegin(SQL, time); // Trace le début de la requête
try
  try
    adods.Active := false;
    adods.CommandText := SQL;
    adods.Active := true;
  except
    on e:exception do
    begin
      SQLLogger.TraceException(e); // Trace les erreurs d'exécution
      raise;
    end;
  end;
finally
  SQLLogger.TraceSQLEnd(SQL, time); // Trace la fin de la requête
end;

Ce principe peut être appliqué pour n'importe quel type de base de données, quels que soient les composants ou l'API utilisée pour y accéder.

III.C. Pour ADO (et dbGO)

Pour les applications existantes, selon leur architecture on ne peut pas forcément intervenir sur tous les accès à la base pour ajouter les traces. On risque d'en oublier ce qui fausserait les profils obtenus.

Avec ADO, il existe une autre solution. La connexion ADO déclenche des événements avant et après chaque exécution de requête. On peut intercepter ces événements pour ajouter nos traces.

Les événements utilisables sont les suivants :

  • WillExecute : Déclenche avant l'exécution de chaque requête. C'est l'endroit idéal pour un TraceSQLBegin.
  • ExecuteComplete : Déclenche après chaque exécution de requête. C'est l'endroit idéal pour un TraceSQLEnd.
  • InfoMessage : Déclenche en cas d'erreur ou si une requête remonte un message d'information (un PRINT sous SQL Server par exemple). Au minimum on peut faire un Trace pour indiquer le message.
  • BeginTransComplete : Déclenche après ouverture d'une nouvelle transaction. On peut y faire un TraceStartTransaction.
  • CommitTransComplete : Déclenche après la validation d'une transaction. On peut y faire un TraceCommitTransaction.
  • RollbackTransComplete : Déclenche après un rollback. On peut y faire un TraceRollbackTransaction.

III.D. Pour dbExpress

dbExpress a déjà prévu un mécanisme pour tracer tout ce qui se passe dans les couches dbExpress. C'est le rôle du composant TSQLMonitor.

On peut utiliser l'événement OnTrace et tracer les messages remontés avec Trace.

Cependant, les messages générés par TSQLMonitor sont très détaillés, sans qu'on puisse vraiment les filtrer et le résultat n'est pas très utilisable.

IV. Tests et Performances

IV.A. Tests avec les outils de Windows

IV.A.1. Test du provider : ETWTest

Nous allons définir une petite application qui génère des événements. Nous allons tester cette génération avec les outils inclus en standard dans Windows : perfmon et tracerpt.

IV.A.1.a. ETWTest

Notre application de test s'appelle ETWTest. Elle se compose d'une unique fenêtre permettant d'appeler les méthodes de trace :

Image non disponible

La barre d'état est rafraichie à l'aide d'un timer. Toutes les secondes on affiche l'état des propriétés EventEnabled, EnableLevel et EnableFlags de GenericLogger.

Les boutons Trace, TraceBegin, TraceEnd et TraceException permettent d'appeler les méthodes du même nom.

Lorsqu'on lance l'application, on peut constater que EventEnabled est à false, ce qui indique qu'aucune trace n'a été activée.

Laissons l'application lancée et lançons perfmon.msc

Sous Windows XP, on obtient l'écran suivant :

Image non disponible

Faisons un clic droit sur « Journaux de traçage » et lançons la commande « Nouveaux paramètres de journal... ».

Windows demande alors de saisir un nom pour la trace. Nous allons indiquer « Test ETW ».

Image non disponible

Après avoir validé, il faut indiquer les paramètres de la trace :

Image non disponible

La première chose à faire est d'indiquer les providers qu'on veut activer pour la trace. Cliquons sur « Ajouter... » pour ajouter un fournisseur étranger au système (en fait, tous les fournisseurs sont étrangers au système à l'exception du Kernel Logger).

Perfmon affiche alors les providers disponibles pour la session de trace.

Image non disponible

Sur un poste Windows XP, la liste des providers disponibles est très limitée. En revanche sur un serveur Windows 2003, on peut trouver de nombreux providers en fonction des services installés et démarrés.

En principe « Generic Trace » devrait apparaître dans la liste. Si ce n'est pas le cas, c'est soit que ETWTest n'est pas lancée, soit que vous n'avez pas installé le fichier logger.mof avec « mofcomp logger.mof ». En effet, perfmon n'affiche que les providers dont le schéma des événements a été publié.

Sélectionnons « Generic Trace » et validons. Le provider apparaît dans la liste des providers activés :

Image non disponible

Validons avec le bouton « OK ».

Perfmon crée la trace et démarre automatiquement son enregistrement :

Image non disponible

Maintenant fermons perfmon et retournons sur ETWTest.

Image non disponible

On remarque que cette fois, EventEnabled est passé à True, ce qui indique qu'une trace a été démarrée. On remarquera également que EnableLevel est à 0. Les traces créées avec perfmon ont toujours un niveau de 0.

Il ne reste plus qu'à essayer d'écrire quelques messages dans la trace :

  • Tapons « Message de test. » dans Message et cliquons sur Trace pour écrire le message dans la trace.
  • Changeons Message ID à « 1 - EVENT_START », message à « Debut opération » et cliquons sur TraceBegin.
  • Changeons Message ID à « 2 - EVENT_END », message à « Fin opération » et cliquons sur TraceEnd.
  • Enfin dernier test, tapons « une erreur est survenue » dans message et cliquons sur TraceException.

Normalement, les quatre opérations ont dû être écrites dans la trace. Il ne reste plus qu'à vérifier.

Relançons perfmon et cliquons sur le carré noir pour arrêter la trace.

La trace arrêtée devient rouge.

Image non disponible

Par défaut, Perfmon a écrit la trace dans C:\PerfLogs. La trace générée s'appelle « Test ETW_000001.etl ».

Il s'agit d'un fichier binaire qui n'est pas lisible directement. Pour pouvoir l'exploiter il faut le retravailler avec la commande « tracerpt fichier.etl ». Lançons un cmd.exe pour exécuter tracerpt :

Image non disponible

Tracerpt génère deux fichiers textes à partir de la trace. Le fichier dumpfile.csv contient la trace proprement dite, tandis que summary.txt contient un résumé des événements trouvés dans la trace.

Si on examine dumpfile.csv on doit trouver les opérations effectuées lors de l'enregistrement de la trace :

 
Sélectionnez

Event Name, Type, Clock-Time, User Data
       MSG, INFO, 128468301731718750, 0, "Message de test.", 0, 0
       MSG, START, 128468301822500000, 0, "Debut opération", 0, 0
       MSG, END, 128468301921250000, 9871, "Fin opération", 0, 0
       MSG, ERROR, 128468302072187500, 0, "Exception: une erreur est survenue", 0, 0

J'ai supprimé les colonnes TID, Kernel Time et User Time qui ne présentent pas un grand intérêt pour nous, ainsi que la ligne EventTrace.

La colonne Event Name indique le nom du provider, la deuxième le nom de l'EventType de l'événement généré.

La colonne Clock-Time indique l'heure système tandis que la colonne User Data contient les données de l'événement traduite sous forme d'une liste de valeurs. On retrouve les 2 champs de notre événement : durée de l'opération et libellé du message.

On peut calculer le temps écoulé en ms entre deux lignes avec la formule :

 
Sélectionnez

Duree = (ClockTime2-ClockTime1) / 10000

Par exemple, pour les événements END et START nous avons 128468301822500000 et 128468301921250000.

On peut calculer :

(128468301921250000-128468301822500000 / 10000 = 98750000 / 10000 = 9875

C'est le temps qu'on retrouve dans la colonne OperationTime pour l'événement END.

IV.B. Evaluation des performances

Microsoft annonce qu'ETW peut générer des événements à un rythme de 20 000 événements par seconde, tout en générant une charge CPU inférieure à 5%.

Cela revient à dire qu'on doit être capable de générer 400 000 événements par seconde.

Ce nombre est tellement hallucinant qu'il mérite qu'on fasse quelques tests pour le vérifier !

IV.B.1. Test 1 : La référence

Tout d'abord à titre de comparaison essayons de faire la même chose avec un fichier texte classique, tel qu'on le ferait pour générer une trace :

 
Sélectionnez

procedure TfrmTestETW.LogFile(msg: string);
var f: textfile;
begin
  assignfile(f, 'c:\log.txt');
  if fileexists('c:\log.txt')
  then append(f)
  else rewrite(f);

  writeln(f, datetimetostr(now) + ' ' + msg);
  closefile(f);
end;

C'est très basique, on ne peut pas faire pire, mais ce mode d'écriture est très simple et c'est souvent celui qui est utilisé pour écrire dans un fichier log.

On effectue le test qui consiste à écrire 10000 messages dans le log avec :

 
Sélectionnez

var i : integer;
    time : int64;
begin
  GenericLogger.TraceBegin(EVENT_START, 'Début du test fichier', time);
  for i := 0 to 9999 do
  begin
    LogFile('Message ' + IntToStr(i));
  end;
  GenericLogger.TraceEnd(EVENT_END, 'Fin du test fichier', time);
end;

L'écriture des 10000 lignes dure 2900ms sur la machine de test.

IV.B.2. Test 2 : Test avec Perfmon

Microsoft recommande de ne pas utiliser les traces temps réel avec Windows XP car il y a un risque de perdre des événements si le rythme de ces derniers est trop élevé.

Pour ETWSQLProfiler ce n'est pas gênant, vu les temps que prennent les requêtes SQL en général, le risque de perte est négligeable.

Cependant pour ce test, on va générer les événements à la vitesse maximale de la machine. On peut donc être certain d'en perdre au passage.

On va donc suivre les recommandations Microsoft et utiliser Perfmon pour générer une trace fichier.

Le test est le suivant :

 
Sélectionnez

for i := 0 to 9999 do
begin
  GenericLogger.Trace(0, 'Message ' + IntToStr(i));
end;

On lance la trace avec Perfmon. On traite le fichier avec tracerpt. Et la surprise ! ETW n'a enregistré que 4000 événements sur les 10000. Soit 60% de perte.

Autant dire que le résultat est plus que décevant. Cependant, la trace a été enregistrée avec les paramètres par défaut, c'est-à-dire buffers de 4Ko, 3 buffers au minimum et 25 au maximum.

Comme on pousse la machine dans ses limites, on peut essayer d'agrandir un peu les buffers.

Donc on recommence avec une taille de buffer de 64 Ko (onglet Avancé dans les paramètres de la trace perfmon).

Cette fois tous les événements sont bien présents. On calcule le temps écoulé entre le premier événement et le dernier. Et on trouve... 0ms !

Bon il faut être réaliste. Enregistrer 10000 événements sans que ça ne prenne la moindre milliseconde ce n'est pas possible. Il doit donc y avoir un problème quelque part.

En fait, le problème est le suivant : Perfmon génère des traces en utilisant l'horloge système qui est plus rapide à lire que les compteurs de performances. Cette dernière à une précision de l'ordre 15ms. Donc on a une incertitude de 15ms sur la date du premier événement. On a la même incertitude sur la date du dernier événement.

Au final, l'incertitude sur la durée mesurée est de 30ms.

Donc une mesure de 0ms signifie en fait une durée inférieure à 30ms.

IV.B.3. Test 3 : Test avec ETWSQLProfiler

Pour mieux se convaincre et vérifier le résultat précédent nous allons relancer le test avec ETWSQLProfiler. En effet, ce dernier va démarrer une trace temps réel en utilisant les compteurs de performances comme horloge.

On devrait perdre des événements mais ça nous permettra également de mesurer cette perte.

Donc on relance le test. Et surprise n°2 : Tous les événements sont bien présents. Le premier événement correspond à 'Message 0', le dernier 'Message 9999' et les numéros de lignes de la première colonne correspondent au numéro du message.

Il ne reste plus qu'à sélectionner tous les événements de la trace et EtwSQLProfiler va calculer la durée totale : 16,32 ms. 16ms pour 10000 événements, cela fait de l'ordre de la microseconde par événement et on n'a pas perdu un seul événement !

IV.B.4. Test 4 : Risque de perte d'événements

Microsoft l'annonce, avec une trace temps réel, on risque de perdre des événements. Le risque est tel que Microsoft déconseille les traces temps réel avant Windows Vista.

Pourtant, avec le test 3 on n'a pas perdu un seul événement. Tandis que lors du test 2, on avait perdu 60% des événements avec une trace fichier !

Le risque de perte dépend étroitement de la configuration des buffers, du rythme des événements, et de la taille des messages.

Faisons à nouveau un test, avec 1 000 000 d'événements sur la trace temps réel et cette fois ci, des messages vides identifiés uniquement à partir du type de l'événement.

La génération des événements semble durer moins d'une seconde. Lorsqu'on bascule sur EtwSQLProfiler pour voir le résultat, on constate qu'il est toujours en train de recevoir et de traiter des événements. Et qu'il en est au numéro 100 000 !

Autrement dit, EtwSQLProfiler est en train de rendre l'âme et n'arrive pas à tenir la cadence.

Pour l'aider un peu, j'ai refait le test en supprimant le tri de la trace dans TETWClient.AddEvent. Cette fois ci, EtwSqlProfiler termine immédiatement son traitement.

Il y a 982 774 événements dans la trace. Et la trace dure 1154 ms. Soit 850 000 événements par secondes. La perte s'élève à 1,7% du total.

Ainsi dans la pratique, le risque de perte d'événements est réel, cependant il faut vraiment pousser ETW dans ses limites pour commencer à perdre effectivement des événements. Lorsqu'on cherche à tracer l'exécution d'un traitement dans une application, il y a peu de chance qu'on atteigne un rythme suffisant pour perdre des événements.

IV.B.5. Test 5 : Dégradation des performances liée à la trace

Il nous reste un dernier test à faire. On a vu qu'on peut générer jusqu'à 850 000 événements par seconde, là où une trace fichier classique en génère péniblement 3500/s. La question qu'on peut se poser à présent est qu'en est-il lorsque la trace n'est pas activée !

Pour cela, refaisons le test précédent, sans lancer EtwSqlProfiler. Nous générons donc 1 000 000 d'événements sans aucun client pour les collecter.

La durée du traitement a été de 42ms (4,2.10-2s). Donc chaque appel à la méthode Trace a engendré un ralentissement de 4,2.10-2/106=4,2.10-8s.

Chaque écriture pour rien engendre donc une perte de temps de 42 nanosecondes !

Si on considère que dans la pratique on ne génèrera guère plus de 100 événements par seconde, cette dégradation des performances est totalement négligeable.

IV.B.6. Conclusion

Ces tests nous révèlent de nombreuses informations.

Tout d'abord, et c'est certainement la principale, les performances d'ETW sont vraiment excellentes. Elles sont encore bien meilleures que ce qu'annonce Microsoft.

Le surcoût engendré par l'instrumentation du code pour générer la trace est totalement négligeable.

Les résultats réellement constatés vont en sens inverse de ce que dit Microsoft. Une trace fichier peut perdre des événements tout comme une trace temps réel. On perd en réalité moins d'événements avec une trace temps réel qu'avec une trace fichier. Il faut cependant noter que la perte d'événements avec une trace temps réel dépend beaucoup du client qui les traite.

V. Pour aller plus loin, le client universel

ETWSQLProfiler ne met en oeuvre qu'une partie des fonctionnalités que nous avons vues.

Pour aller plus loin, il nous reste à voir comment utiliser les informations MOF pour décoder n'importe quel événement et ainsi pouvoir traiter n'importe quel type de trace.

Nous avons vu qu'il était possible de publier le schéma des événements pour que Tracerpt sache les décoder et les présenter.

Cette publication s'effectue à l'aide d'un fichier MOF et la commande mofcomp.

A présent, nous allons voir comment récupérer ces informations afin qu'on puisse décoder nous-mêmes n'importe quel événement qui arrive dans la trace.

Pour cela, il faut sortir de Etw pour utiliser un autre standard : WMI. En effet, MOF fait parti de WMI. Etw est intégré dans WMI (il est d'ailleurs possible de gérer les traces directement avec WMI). En fait MOF est le langage qui permet de décrire une classe WMI.

L'objectif de cet article n'est pas de faire un cours sur WMI. Aussi, nous nous contenterons de voir rapidement les principes permettant de retrouver les informations utiles dans WMI. Pour les détails on pourra se référer à la documentation WMI et aux sources de l'unité uETWWmiInfo.

V.A. Interrogation du schéma avec WMI

V.A.1. Se connecter à WMI

Pour utiliser WMI, nous nous servirons d'objets COM avec la bibliothèque de types : Microsoft WMI Scripting V1.2 Library. On doit tout d'abord se connecter au serveur local pour ouvrir le namespace root\wmi. On effectue cette opération grâce au code suivant :

 
Sélectionnez

uses WbemScripting_TLB;
var
  Locator : ISWbemLocator;
  Service : ISWbemServices;
begin
  Locator := CoSWbemLocator.Create;
  Service := Locator.ConnectServer('', 'root\wmi', '', '', '', '', 0, nil);

V.A.2. Enumérer la liste des Providers ETW

Souvenez-vous, au moment de la publication du schéma des événements, j'ai dit qu'il fallait déclarer trois classes qui héritent les unes des autres.

La première, qui dérive de la classe EventTrace désigne le Provider. Nous allons parcourir l'espace de nommage root\wmi pour retrouver toutes les classes Wmi déclarées.

Dans un premier temps, seules celles qui désignent un provider nous intéressent.

On commence donc par énumérer la liste des classes qui dérivent d'EventTrace :

 
Sélectionnez

objList := Service.SubclassesOf('EventTrace',
             wbemQueryFlagShallow, // On ne veut que les descendant direct.
             nil);

objList désigne alors la liste des classes trouvées. On peut parcourir la liste à l'aide d'un énumérateur :

 
Sélectionnez

var
  Enum : IEnumVariant;
  TempObj : OleVariant;
  Fetch : cardinal;
  WmiObj : ISWbemObject;
begin
  ...
  Enum := (objList._NewEnum) as IEnumVariant;
  while Enum.Next(1, TempObj, Fetch) = S_OK do
  begin
    WmiObj := IUnknown(TempObj) as ISWbemObject;
    ...
  end;

Dès lors, WmiObj contient une référence sur une interface ISWbemObject qui désigne la classe déclarée sur le provider.

Il ne reste plus qu'à lire les Qualifier guid et Description qui lui ont été associés pour connaître le nom du provider ainsi que son Guid :

 
Sélectionnez

FGuid := WmiObj.Qualifiers_.Item('Guid', 0).Get_Value;
FDescription := WmiObj.Qualifiers_.Item('Description', 0).Get_Value;

Si la description n'a pas été définie, on peut utiliser le nom de la classe comme nom de provider. Le nom de la classe peut être lu avec :

 
Sélectionnez

FClassName := WmiObj.Path_.Class_;

V.A.3. Enumérer la liste des classes d'événements

Dans WMI, les providers sont les classes qui dérivent de la classe EventTrace.

Les classes d'événements dérivent de la classe du provider auquel elles se rapportent.

Il suffit donc de recommencer récursivement le traitement d'énumération des providers en énumérant cette fois les classes qui dérivent de chaque provider.

Au passage, on en profitera pour lire les qualifiers Guid, Description, DisplayName et EventVersion.

V.A.4. Enumérer la liste des types d'événements

On recommence la même énumération une dernière fois pour obtenir les classes qui décrivent réellement la structure des événements.

Cette fois ci, ce sont les qualifiers EventType et EventTypeName qui nous intéresseront particulièrement.

Lorsqu'on lit leur valeur avec Get_Value, on peut obtenir soit une valeur seule, soit un tableau de valeurs. Dans ce cas, il faut utiliser les fonctions de manipulation des tableaux de variants de Delphi pour récupérer chaque valeur.

Lorsqu'on rencontre un événement donné dans la trace, si on veut décoder ses informations MOF on recherche la classe d'événement (deuxième niveau) avec le Guid et l'EventVersion de l'événement.

Ensuite, il faut rechercher parmi les classes dérivées celle qui possède le bon EventType.

Pour que cette recherche ne prenne pas trop de temps lorsqu'on traite une trace, la classe TWmiInfo construit un index à partir du Guid, de l'EventVersion et le l'EventType. Cet index permet de retrouver directement la classe à utiliser pour décoder l'événement.

V.A.5. Enumérer la liste des propriétés d'une classe

Une fois qu'on a trouvé la classe correspondant à l'événement, à sa version et son EventType, il suffit de rechercher les propriétés marquées avec [WmiDataId] et de les trier par ordre croissant des WmiDataId.

Ces dernières nous donnent la structure du champ MOFData de l'événement.

On fait l'énumération avec un code du genre :

 
Sélectionnez

Enum := WmiObj.Properties_._NewEnum as IEnumVARIANT;
while Enum.Next(1, TempObj, Fetch) = S_OK do
begin
  prop := IUnknown(TempObj) as ISWbemProperty;
  try
    FWmiDataId := prop.Qualifiers_.Item('WmiDataId', 0).Get_Value;
  except
    continue;
  end;

Pour chaque propriété les informations nécessaires pour décoder un événement sont :

  • Pratiquement tous les qualifiers. Ils décrivent en effet la façon dont la propriété doit être formatée.
  • Le type de donnée : prop.CIMType
  • Si la propriété est un tableau : prop.IsArray
  • Le nom de la propriété : prop.Name.

Maintenant, il ne restera plus qu'à prendre les propriétés dans l'ordre des WmiDataId pour interpréter le champ MofData octet par octet.

Il faut traiter chaque propriété en fonction de son type pour connaître la taille de chaque champ. Le code n'est pas très compliqué, mais il y a beaucoup de cas de figure.

La classe TMOFField dans uETWWmiInfo implémente le décodage d'une propriété d'un événement.

V.B. L'application client universel : ETWTraceViewer

Nous avons fait le tour de la plupart des fonctionnalités d'ETW. Il ne reste plus qu'à tout assembler dans une seule application : ETWTraceViewer.

Cette application est une version plus évoluée d'ETWSQLProfiler. Elle permet de créer tout type de trace, temps réel ou fichier et de choisir librement les providers.

Elle permet également d'ouvrir les fichiers etl générés avec perfmon (ou même avec une trace fichier ETWTraceViewer) et de l'afficher comme une trace temps réel.

Image non disponible

ETWTraceViewer est conçu pour traiter une fréquence élevée d'événements. C'est pourquoi les événements ne sont pas triés automatiquement dans la trace. Ils arrivent dans l'ordre où ETW les envoie.

Pour visualiser les événements dans l'ordre, il faut soit créer une trace fichier, soit trier explicitement la trace.

Le lancement de l'application est un petit peu long. C'est dû au fait que le schéma des événements est lu une fois pour toute au démarrage. Ca provoque un ralentissement au début, mais ça nous permet également ensuite de traiter les événements rapidement.

L'arrêt d'une trace peut être assez long et prendre plusieurs secondes. C'est le temps que met ETW pour détecter l'arrêt de la trace. Ce n'est qu'après ce laps de temps, que les fonctions ProcessTrace rendent la main.

VI. Aller encore plus loin, ne pas instrumenter son code

L'objectif premier de cet article était de créer un profiler SQL capable d'afficher les requêtes qui s'exécutent sur le SGBD, et ce quel que soit le SGBD utilisé. Pour cela, nous avons utilisé ETW pour générer et collecter des traces. Il suffit alors d'instrumenter les applications clientes pour qu'elles génèrent ces traces.

C'est le meilleur moyen pour obtenir une trace claire et compréhensible. Cependant il existe une autre alternative à l'instrumentation de l'application. Il s'agit d'exploiter les traces que Microsoft a déjà prévues dans ses API d'accès aux données.

Je ne pouvais pas conclure cet article sans en parler, même si nous verrons que dans la pratique le résultat est plutôt délicat à exploiter.

Les versions récentes des API d'accès aux données Microsoft sont toutes instrumentées et peuvent générer des traces dans ETW. Il s'agit de :

  • ADO.NET 2.0 (Les quatre providers SqlClient, OracleClient, OleDbClient, ODBCClient)
  • MDAC 2.8 SP2
  • SQL Server Native Client.
  • Microsoft SQL Server 2005 JDBC Driver
  • SQL Network Interface (SNI) layer.

VI.A. Activation des traces

Cette fonctionnalité n'est pas activée par défaut. Pour l'activer il faut créer une clé dans la base de registre :

 
Sélectionnez

HKEY_LOCAL_MACHINE\Software\Microsoft\BidInterface\Loader

Il faut définir une valeur de type chaîne (REG_SZ), de nom « :Path » (attention, il ne faut pas oublier les « : »). Dans la valeur, il faut indiquer la DLL AdoNetDiag.dll ou msdadiag.dll avec son chemin complet.

Normalement, la première se trouve dans le chemin d'installation de .Net Framework 2.0 (%SYSTEMROOT%\Microsoft.NET\Framework\v2.0.50727\ADONETDiag.dll) et la dernière se trouve dans system32.

VI.B. Test avec une requête simple

Pour la suite, nous allons utiliser AdoNetDiag.dll. Il faut commencer par installer le fichier adonetdiag.mof avec mofcomp. Ce dernier se trouve au même emplacement que la dll.

Dès lors, les providers doivent apparaître dans ETWTraceViewer.

Démarrons une trace temps réel et faisons un test d'exécution de la requête suivante avec ADO et dbGO :

 
Sélectionnez

Select top 1 * from sysobjects

On configure la chaîne de connexion ADO pour utiliser le provider « SQL Native client ».

Cette requête retourne la première ligne de la table système sysobjects d'une base SQL Server.

Elle génère une trace de 985 lignes ! Voici un exemple du résultat :

Image non disponible

La trace complète est trop longue pour figurer directement dans l'article. Aussi, je l'ai jointe aux codes sources. Il s'agit du fichier « Test Trace ADO.txt » dans le répertoire Traces.

La trace comprend 2 EventClass : SQLNCLI.1 et ADODB.1. Rien d'étonnant à cela, ADO n'est qu'une surcouche au dessus de OleDb. SQLNCLI.1 désigne le provider OleDb utilisé (SQL Native Client) tandis que ADODB.1 désigne la couche ADO.

Il n'y a que deux EventType : TextW et TextA. A chaque fois, l'événement généré n'est pratiquement constitué que d'une unique chaîne de caractères qui contient en réalité de nombreux champs.

Par exemple :

 
Sélectionnez

'enter_01 <ICommandText::SetCommandText|OLEDB|API> 19#{Command}, rguidDialect:
0012F414{REFGUID}, CommandText: "select top 1 * from sysobjects"'

Logiquement avec ETW on aurait pu avoir un EventClass « SetCommandText » avec un EventType à « enter » et deux champs rguidDialect et CommandText. Mais au lieu de ça, on a un seul type d'événement, juste une chaîne de caractères formatée.

Alors pourquoi une unique chaîne ? La réponse est simple : Cette instrumentation a été réalisée bien avant ETW. Je pense qu'elle date d'ODBC. La DLL ADONetDiag.dll est en réalité un pont qui détourne la trace normalement générée avec une autre technologie vers ETW.

L'exploitation d'une telle trace est donc particulièrement ardue. On ne peut pas s'en servir pour notre but premier qui était d'écrire un profiler SQL. Cependant elle peut être très utile pour diagnostiquer un problème de performances sur une requête en particulier, ou pour comprendre une erreur.

Elle permet également de comprendre ce qui se passe dans chaque couche lorsqu'on exécute une requête. Par exemple, la requête précédente a généré presque 1000 lignes. La durée totale du traitement a été de 56 ms.

Si on s'intéresse de près au déroulement, on voit tout d'abord qu'il y a eu un appel à :

 
Sélectionnez

ICommandText.SetCommandText('select top 1 * from sysobjects')
ICommandWithParameters.SetParameterInfo
ICommandPrepare.Prepare
ICommandWithParameters.GetParameterInfo
ICommandPrepare::Unprepare

Cette séquence ressemble fort à un Parameters.Refresh. Pourtant le code Delphi d'origine n'exécutait pas une requête paramétrée. Il s'agissait plutôt de :

 
Sélectionnez

adods.CommandText := eSQL.Lines.Text;
adods.Open;

Puis ADO a enchaîné avec :

 
Sélectionnez

ICommandProperties.GetProperties

Ce simple appel a engendré un accès au serveur et a durée 7ms.
On vient donc de passer 7ms, mais on n'a toujours pas demandé au serveur de l'exécuter. Même le prepare a été annulé avec Unprepare.

Après ça, on a l'exécution de la requête proprement dit :

 
Sélectionnez

ICommandText.SetCommandText('select top 1 * from sysobjects')
ICommand::Execute

Ce qui est particulièrement intéressant un peu plus loin c'est qu'on voit les accès réseaux :

 
Sélectionnez

BATCHCTX::SendPacket|TDS|IO
BATCHCTX::ReadPacket|TDS|IO

Cette séquence montre l'exécution réelle de la requête sur le SGBD. SendPacket correspond à l'envoi de la trame TDS au serveur. ReadPacket indique la lecture de la réponse du serveur. Entre les deux événements, il s'est écoulé 27,5ms.

Cela signifie que la requête s'exécute en réalité en 27,5ms. L'écart entre les 56ms et les 27,5ms est le temps qu'on perd dans ADO et OLEDB.

On peut se demander pourquoi ADO et OLEDB prennent autant de temps. On voit qu'on a déjà perdu 7ms à rafraichir les paramètres d'une requête alors qu'on savait très bien qu'elle n'était pas paramétrée !

Si on examine le reste de la trace, on pourra voir pourquoi on perd encore 21,5ms.

Après réception de la requête, on remarque les appels suivants :

 
Sélectionnez

IMultipleResults.GetResult
IColumnsInfo.GetColumnInfo
IRowsetInfo.GetProperties
25 appels à IAccessor.CreateAccessor

Cette séquence d'appels permet de lire la structure du recordset renvoyé par OLEDB. Elle dure 1ms.

Vient alors une série d'appels pour lire et convertir les données des lignes, qui dure 4ms.

Ce temps correspond au fetch des lignes. Ce qui est étonnant, c'est qu'on remarque plusieurs appels à GetNextRows, et à GetData. En effet, la requête ne retourne qu'une seule et unique ligne. Alors qu'il y a beaucoup plus d'appels à GetNextRows. De même, il y a de nombreux appels à GetData.

Cette trace semble montrer qu'ADO lit la même ligne plusieurs fois. Cette lecture s'effectue champ par champ. Ces lectures durent au total 4ms.

Mais ce qui est encore plus remarquable, c'est qu'une fois que la requête a été complètement exécutée et lue, que toutes les interfaces OLEDB ont été libérées, ADO passe encore 12ms à faire des ObtainIDw et RecycleIDw !

Cette trace d'exécution montre tout simplement qu'il ne faut pas négliger l'influence de l'API utilisée pour les accès aux données. Même si les temps d'exécution d'une requête peuvent être importants (ici 27,5ms) ces derniers peuvent encore être fortement amplifiés par un usage non optimal des API d'accès aux données.

ADO a été développé par-dessus OLEDB pour faciliter la vie du développeur en lui évitant de devoir gérer la complexité des interfaces OLEDB. Cependant on voit ici avec cette trace que cette simplification a un coût, et que contrairement à ce qu'on croit souvent, ce coût est loin d'être négligeable. Chaque fois qu'on empile une couche par-dessus une autre, on dégrade les performances. En générant ce type de trace dans l'application finale, on peut se rendre compte de l'ampleur de la catastrophe.

Ici, ADO divise par deux les performances d'OLEDB. A votre avis, que se passe-t-il lorsqu'on rajoute dbGO par-dessus ? Que se passe-t-il ensuite lorsqu'on rajoute un TClientDataSet avec un TDataSetProvider encore par-dessus ?

Remarque : on peut se poser les mêmes questions avec dbExpress ou avec n'importe quelle autre API.

VII. Références

VIII. Conclusion

Event Tracing for Windows est une API redoutablement efficace. Pourtant elle est totalement méconnue. Même Microsoft n'en faisait pas particulièrement la promotion avant Vista. Cela est sans doute dû à plusieurs raisons :

Tout d'abord, il s'agit à la base d'une API développée pour les drivers de périphériques. Pendant très longtemps, Microsoft n'en a parlé que dans le DDK. Très peu de gens regardent le DDK donc très peu de gens la connaissent.

Ensuite, ETW est une API bas niveau, qui touche à la programmation système. Elle nécessite de travailler directement au niveau des buffers, sur la représentation mémoire des données. De fait ça interdit son usage sur tous les langages un peu trop évolués : les langages de scripts et les langages interprétés en général.

On pourrait croire que Microsoft va abandonner ETW pour des API plus faciles à mettre en oeuvre. Mais en réalité, c'est tout le contraire. ETW a été fortement étendu pour Vista.

ETW a été intégré dans .NET Framework 3.5. Cependant cette intégration ne fonctionne que sous Vista.

De plus en plus d'applications Microsoft utilisent ETW. Sous Windows 2003, on commence à trouver des services Windows instrumentés avec ETW. Par exemple, avec IIS6 il est possible de suivre le traitement d'une requête http de sa réception sur le serveur, jusqu'à l'envoi de la réponse au client, en passant par les extensions ISAPI. Dernièrement je suis tombé sur un exemple dans la MSDN qui expliquait comment écrire un message dans les logs de SharePoint 2003. En regardant l'exemple, j'ai immédiatement reconnu l'écriture d'un événement ETW...

En fait, on dirait plutôt que Microsoft ne découvre que maintenant qu'ETW peut servir à autre chose qu'à déboguer des drivers.

Cet article nous à permis de découvrir ETW et de l'utiliser pour développer un profiler. Dans de prochains articles, nous l'utiliserons pour analyser et optimiser différentes applications.

IX. Remerciements

Je tiens à remercier l'équipe de la rédaction pour la mise au gabarit initiale de l'article.

Je remercie particulièrement Bruno Orsier pour sa relecture et conseils judicieux.