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;
|
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 :
const
DefaultLogger : TGUID = '{708A0B60-6786-460B-96A1-2C569C7B0B4C}';
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;
|
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 :
const
SQLLoggerGUID : TGUID = '{E356181E-4059-4BBA-BA4A-87280762A798}';
SQLEventClass : TGUID = '{815AA09D-DBC9-45FE-982E-0243FDF363ED}';
const
EVENT_SQL_INFO = 0;
EVENT_SQL_START = 1;
EVENT_SQL_END = 2;
EVENT_SQL_ERROR = 3;
EVENT_BEGINTRAN = 4;
EVENT_ROLLBACKTRAN = 5;
EVENT_COMMITTRAN = 6;
EVENT_SQL_FORMAT_START = 7;
EVENT_SQL_FORMAT_END = 8;
EVENT_SQL_CONNECT = 9;
EVENT_SQL_DISCONNECT = 10;
type
TSQLLogger = class(TGenericLogger)
private
function ParamStr(Param : TParam) : string;
procedure FormatParams(SQL : string; params : TParams);
public
procedure TraceSQLBegin(SQL : string; var Time : int64; Params : TParams=nil;
msgLevel : byte = TRACE_LEVEL_INFORMATION);
procedure TraceSQLEnd(SQL : string; var Time : int64; Params : TParams=nil;
msgLevel : byte = TRACE_LEVEL_INFORMATION);
procedure TraceStartTransaction(var Time : int64;
msgLevel : byte = TRACE_LEVEL_INFORMATION);
procedure TraceCommitTransaction(Time : int64;
msgLevel : byte = TRACE_LEVEL_INFORMATION);
procedure TraceRollbackTransaction(Time : int64;
msgLevel : byte = TRACE_LEVEL_INFORMATION);
procedure TraceConnect(msgLevel : byte = TRACE_LEVEL_INFORMATION);
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 :
| 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 :
#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 :
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;
};
|
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 :
TETWTraceControler = class(TObject)
private
FRunningSession : TRACEHANDLE;
FName : string;
FFileName : string;
FControlGuid : TGUID;
FTrcProps : TTraceProperties;
FEnabledProviders : TStrings;
public
constructor Create(aName : string; aFileName : string);
destructor Destroy; override;
procedure DisableProvider(Guid : TGUID);
procedure EnableProvider(Guid : TGUID; EnableLevel : byte;
EnableFlags : cardinal);
procedure Flush;
class procedure DecodeProviderInfo(provider : string;
var providerGUID : string;
var Enabled : boolean);
class procedure EnumerateRegisteredProviders(aList : TStrings);
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 :
constructor TETWTraceControler.Create(aName: string; aFileName : string);
begin
FName := aName;
FFileName := aFileName;
FControlGuid := ETWTraceControlerGuid;
fillchar(FTrcProps, sizeof(FTrcProps), 0);
FTrcProps.Props.Wnode.BufferSize := sizeof(FTrcProps);
FTrcProps.Props.Wnode.Flags := WNODE_FLAG_TRACED_GUID;
FTrcProps.Props.Wnode.ClientContext := 1;
FTrcProps.Props.Wnode.Guid := FControlGuid;
FTrcProps.Props.BufferSize := 64;
FTrcProps.Props.MinimumBuffers := 8;
FTrcProps.Props.MaximumBuffers := 16;
FTrcProps.Props.LoggerNameOffset := sizeof(FTrcProps.Props) +
sizeof(FTrcProps.filler);
FTrcProps.Props.LogFileNameOffset := FTrcProps.Props.LoggerNameOffset +
sizeof(FTrcProps.SessionName);
strcopy(@FTrcProps.FileName[0], PChar(FFileName));
if aFileName = ''
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;
end
else begin
FTrcProps.Props.LogFileMode := EVENT_TRACE_FILE_MODE_CIRCULAR or
EVENT_TRACE_USE_PAGED_MEMORY;
FTrcProps.Props.MaximumFileSize := 100;
end;
StopTrace(0, PChar(FName), @FTrcProps);
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 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 :
destructor TETWTraceControler.Destroy;
var i : integer;
begin
if Assigned(FEnabledProviders)
then begin
for i := FEnabledProviders.Count -1 downto 0 do
begin
DisableProvider(StringToGuid(FEnabledProviders[i]));
end;
FEnabledProviders.Free;
end;
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 :
procedure TETWTraceControler.DisableProvider(Guid: TGUID);
var idx : integer;
begin
if EnableTrace(TRACE_OFF, 0, 0, @GUID, FRunningSession)<>ERROR_SUCCESS
then RaiseLastOSError;
idx := FEnabledProviders.IndexOf(GuidToString(Guid));
if idx<>-1
then FEnabledProviders.Delete(idx);
end;
procedure TETWTraceControler.EnableProvider(Guid : TGUID; EnableLevel : byte;
EnableFlags : cardinal);
begin
if FEnabledProviders.IndexOf(GuidToString(Guid)) = -1
then begin
if EnableTrace(TRACE_ON, EnableFlags, EnableLevel,
@GUID, FRunningSession)<>ERROR_SUCCESS
then RaiseLastOSError;
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 :
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;
procedure InitTabs(nbProv : integer);
var i : integer;
begin
SetLength(Properties, nbProv);
SetLength(PropertiesPtr, nbProv);
fillchar(Properties[0], sizeof(TRACE_GUID_PROPERTIES) * nbProv, 0);
for i := 0 to nbProv -1 do
begin
PropertiesPtr[i] := @Properties[i];
end;
end;
begin
Assert(Assigned(aList));
aList.Clear;
MaxProv := 50;
nbProviders := MaxProv;
InitTabs(MaxProv);
result := EnumerateTraceGuids(PropertiesPtr, MaxProv, nbProviders);
case result of
ERROR_SUCCESS:;
ERROR_MORE_DATA:
begin
MaxProv := nbProviders;
InitTabs(MaxProv);
if EnumerateTraceGuids(PropertiesPtr, MaxProv, nbProviders)<>ERROR_SUCCESS
then raiseLastOSError;
end;
else RaiseLastOSError;
end;
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 :
type
TETWClient = class(TObject)
private
FWorkerThread : TThread;
FTrace : EVENT_TRACE_LOGFILE;
FList : TList;
FSession : TRACEHANDLE;
FTraceMutex : Cardinal;
protected
procedure ProcessEvent(pEvent : PEVENT_TRACE); virtual;
public
constructor Create(Name : string; IsRealTime : boolean);
destructor Destroy; override;
function GetDateTime(ClockTime : int64) : TDateTime;
procedure ClearTrace;
procedure AddEvent(Event : TEventTrace);
procedure Lock;
procedure UnLock;
procedure SortTrace;
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 :
constructor TETWClient.Create(Name: string; IsRealTime: boolean);
var result : cardinal;
begin
if Assigned(ActiveClient)
then raise Exception.Create('Il y a déjà une trace en cours de traitement.');
fillchar(FTrace, sizeof(FTrace), 0);
if isRealTime
then begin
FTrace.LoggerName := PChar(Name);
FTrace.LogFileMode := EVENT_TRACE_REAL_TIME_MODE;
end
else begin
FTrace.LogFileName := PChar(Name);
end;
FTrace.EventCallback := EventCallback;
FSession := OpenTrace(@FTrace);
if FSession = INVALID_HANDLE_VALUE
then raiseLastOSError;
if IsRealTime
then GetTimeZoneInformation(FTrace.LogfileHeader.TimeZone);
FList := TList.Create;
if IsRealTime
then FWorkerThread := TWorkerThread.create(self)
else begin
ActiveClient := self;
try
result := ProcessTrace(@FSession,
1,
nil,
nil);
if (result<>ERROR_SUCCESS) and (result<>ERROR_CANCELLED)
then raiseLastOSError;
finally
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 :
procedure EventCallBack(pEvent : PEVENT_TRACE); stdcall;
begin
if Assigned(ActiveClient)
then ActiveClient.ProcessEvent(pEvent);
end;
|
Puis la méthode ProcessEvent :
procedure TETWClient.ProcessEvent(pEvent: PEVENT_TRACE);
var
Data : TEventTrace;
begin
Data := nil;
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 :
destructor TETWClient.Destroy;
var i : integer;
begin
if ActiveClient = self
then ActiveClient := nil;
if FSession<>0
then CloseTrace(FSession);
if Assigned(FWorkerThread)
then begin
FWorkerThread.Free;
FWorkerThread := nil;
end;
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 :
function TETWClient.GetDateTime(ClockTime: int64): TDateTime;
var bias : int64;
begin
bias := FTrace.LogfileHeader.TimeZone.Bias;
bias := bias * 60*1000*10000;
result := (ClockTime-bias-t0) / TimeDay;
end;
|
Avec :
const TimeDay = 864000000000;
T0 = 109205 * TimeDay;
|
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 :
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 :
FTraceControler := TETWTraceControler.Create(TraceSessionName, '');
FTraceControler.EnableProvider(DefaultLogger, TRACE_LEVEL_VERBOSE, 0);
FTraceControler.EnableProvider(SQLLoggerGUID, TRACE_LEVEL_VERBOSE, 0);
try
FTrace := TETWClient.Create(TraceSessionName, true);
TmRefresh.Enabled := true;
except
Application.HandleException(self);
FTraceControler.Free;
FTraceControler := nil;
end;
|
Pour arrêter la trace :
FTraceControler.Free;
FTraceControler := nil;
TmRefresh.Enabled := false;
|
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 :
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 :
SQLLogger.TraceSQLBegin(SQL, time);
try
try
adods.Active := false;
adods.CommandText := SQL;
adods.Active := true;
except
on e:exception do
begin
SQLLogger.TraceException(e);
raise;
end;
end;
finally
SQLLogger.TraceSQLEnd(SQL, time);
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 :
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 :
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 :
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 :
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.
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 :
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 :
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 :
objList := Service.SubclassesOf('EventTrace',
wbemQueryFlagShallow,
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_;
|
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 :
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.
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 :
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 :
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 :
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 :
'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 à :
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 :
adods.CommandText := eSQL.Lines.Text;
adods.Open;
|
Puis ADO a enchaîné avec :
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 :
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 :
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 :
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.


Les sources présentées sur cette page sont libres de droits,
et vous pouvez les utiliser à votre convenance. Par contre, la page de présentation
constitue une oeuvre intellectuelle protégée par les droits d'auteurs. Copyright ©
2008 Franck SORIANO. Aucune reproduction,
même partielle, ne peut être faite de ce site et de l'ensemble de son contenu :
textes, documents, images, etc sans l'autorisation expresse de l'auteur.
Sinon vous encourez selon la loi jusqu'à 3 ans de prison et jusqu'à 300 000 E
de dommages et intérêts.
Cette page est déposée à la
SACD.