Le Tracing avec Event Tracing for Windows (ETW)
Date de publication : 08/04/2008 , Date de mise à jour : 09/05/2008
Par
Franck SORIANO (Pages perso)
Cet article présente comment utiliser ETW pour instrumenter une application.
Grâce à la collecte temps réel des traces, on peut réaliser facilement un profiler,
par exemple un clone de SQL profiler.
I. Introduction
I.A. Pré-requis
I-B. Télécharger les sources de l'article
I-C. Présentation d'ETW
Remarques
II. Construire les bases
II.A. Import du fichier EvnTrace.h
II.B. Le Provider
II.B.1. Enregistrement auprès d'ETW
II.B.2. TraceControlCallBack
II.B.3. Ecrire dans la trace
II.B.3.a. Structure d'un événement
II.B.3.b. Ecriture de l'événement
II.B.4. Provider générique
II.B.5. Provider SQL
II.B.6. Publication du schéma des événements
II.C. Le Contrôleur
II.C.1. Démarrer une trace
II.C.2. Arrêter une trace
II.C.3. Activer/Désactiver un Provider
II.C.4. Enumérer la liste des providers disponibles
II.D. Le Client
II.D.1. Ouvrir une trace existante
II.D.2. Traiter les événements
II.D.3. Fermer une trace
II.D.4. La méthode GetDateTime
III. Le Profiler SQL
III.A. Affichage des événements dans la grille
III.B. Comment instrumenter son code ?
III.C. Pour ADO (et dbGO)
III.D. Pour dbExpress
IV. Tests et Performances
IV.A. Tests avec les outils de Windows
IV.A.1. Test du provider : ETWTest
IV.A.1.a. ETWTest
IV.B. Evaluation des performances
IV.B.1. Test 1 : La référence
IV.B.2. Test 2 : Test avec Perfmon
IV.B.3. Test 3 : Test avec ETWSQLProfiler
IV.B.4. Test 4 : Risque de perte d'événements
IV.B.5. Test 5 : Dégradation des performances liée à la trace
IV.B.6. Conclusion
V. Pour aller plus loin, le client universel
V.A. Interrogation du schéma avec WMI
V.A.1. Se connecter à WMI
V.A.2. Enumérer la liste des Providers ETW
V.A.3. Enumérer la liste des classes d'événements
V.A.4. Enumérer la liste des types d'événements
V.A.5. Enumérer la liste des propriétés d'une classe
V.B. L'application client universel : ETWTraceViewer
VI. Aller encore plus loin, ne pas instrumenter son code
VI.A. Activation des traces
VI.B. Test avec une requête simple
VII. Références
VIII. Conclusion
IX. Remerciements
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 :
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
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 :
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 :
type
TGenericLogger = class(TObject)
private
FEventEnabled : boolean;
FEnableLevel : integer;
FEnableFlags : cardinal;
FTraceSession : TRACEHANDLE;
FRegistrationHandle : TRACEHANDLE;
FProviderGUID : TGUID;
FEventClass : TGUID;
FRegistrationEventClass : TRACE_GUID_REGISTRATION;
protected
function MessageEnabled(Level : byte) : boolean;
procedure EnableEvents(Header : pointer);
procedure DisableEvents(Header : pointer);
property TraceSession : TRACEHANDLE read FTraceSession;
property RegistrationHandle : TRACEHANDLE read FRegistrationHandle;
public
constructor Create(aProviderGUID : TGUID; aEventClass : TGUID);
destructor Destroy; override;
procedure Trace(msg : string); overload;
procedure Trace(EventType : integer; msg : string;
msgLevel : integer = TRACE_LEVEL_INFORMATION;
OperationTime : int64=0); overload;
procedure TraceBegin(EventType : integer; msg : string;
var currentTime : int64;
msgLevel : integer = TRACE_LEVEL_INFORMATION);
procedure TraceEnd(EventType : integer; msg : string; var currentTime : int64;
msgLevel : integer = TRACE_LEVEL_INFORMATION);
procedure TraceException(e : exception;
msgLevel : integer = TRACE_LEVEL_ERROR);
property ProviderGUID : TGUID read FPRoviderGUID;
property EventClass : TGUID read FEventClass;
property EventEnabled : boolean read FEventEnabled write FEventEnabled;
property EnableLevel : integer read FEnableLevel;
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 :
constructor TGenericLogger.Create(aProviderGUID: TGUID; aEventClass : TGUID);
begin
FProviderGUID := aProviderGUID;
FEventClass := aEventClass;
FRegistrationEventClass.Guid := @FEventClass;
FRegistrationEventClass.RegHandle := 0;
if RegisterTraceGuids(@TraceControlCallBack,
Self,
@FProviderGUID,
1,
@FRegistrationEventClass,
nil,
nil,
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
function TraceControlCallBack(RequestCode : WMIDPREQUESTCODE;
RequestContext : pointer;
BufferSize : cardinal;
Buffer : pointer) : cardinal; stdcall;
begin
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 :
type
TGenericEvent = packed record
Header : EVENT_TRACE_HEADER;
Data : array[0..1] of MOF_FIELD;
end;
|
II.B.3.b. Ecriture de l'événement
procedure TGenericLogger.Trace(EventType: integer; msg: string;
msgLevel: integer;
OperationTime: int64);
const EmptyStr : char = #0;
var Event : TGenericEvent;
EventSize : cardinal;
begin
if MessageEnabled(msgLevel)
then begin
EventSize := Sizeof(Event);
fillchar(Event, EventSize, 0);
Event.Header.Size := EventSize;
Event.Header.Flags := WNODE_FLAG_TRACED_GUID or WNODE_FLAG_USE_MOF_PTR;
Event.Header.Guid := FEventClass;
Event.Header.Version := 0;
Event.Header.Type_ := EventType;
Event.Header.Level := msgLevel;
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;
end
else begin
Event.Data[1].DataPtr := @EmptyStr;
Event.Data[1].Length := 1;
end;
TraceEvent(TraceSession, @Event);
end;
end;
|