Le Tracing avec Event Tracing for Windows (ETW)

• 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étail 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 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.

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 :

// 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.

// Cette fonction est appelée automatiquement par ETW pour contrôler 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.

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▲

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▲

// 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éfinie 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 champ 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éfini, on définit les informations à écrire dans la
    // trace.
    // On veut écrire un enregistrement composé des champs <OperationTime,
    // msg> Pour cela, 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;

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 :

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 :

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 :

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

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 toute 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 sortis, 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 :

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 :

select * from MaTable where Id = ?

Ou encore :

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 :

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é.

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 peut 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 :

#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 public 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 :

Mofcomp Logger.mof

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

#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;
};

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 :

// 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 buffers à 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 dû ê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 où 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 :

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 15 ms à 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 : À 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).

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 :

// 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;

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 :

// 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;

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 fourni à 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 :

// 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 maximale du tableau.
  // En retour <nbProviders> contiendra le nombre total de provider déclarés dans
  // ETW.
  // Si le tableau Properties est trop petit (il y a plus 50 providers déclarés)
  // 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 providers 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;

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 :

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 sortie 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é.

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 :

// 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 :

// 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ée 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.

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 :

// 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;

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 1^er janvier 1601.

Les dates Delphi correspondent au nombre de jours écoulés depuis le 1^er 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 fourni dans l'en-tête de la trace. Il suffit de lire LogfileHeader.TimeZone.Bias. Il est exprimé en minutes.

Finalement la conversion devient :

// 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 :

// 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.

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 :

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 :

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 ».

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

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.

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 :

Validons avec le bouton « OK ».

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

Maintenant fermons perfmon et retournons sur ETWTest.

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.

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 :

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 traduites sous forme d'une liste de valeurs. On retrouve les deux 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.

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 :

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 :

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.

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 :

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.

Finalement, 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.

Pour mieux nous 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 !

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.

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 42 ms (4,2.10^-2s). Donc chaque appel à la méthode Trace a engendré un ralentissement de 4,2.10^-2/10⁶=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.

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.

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 :

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

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 :

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

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

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 :

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 :

FClassName := WmiObj.Path_.Class_;

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.

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.

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 :

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.