Exemple 15 : Mesure du temps DPC/ISR
Vous pouvez mesurer la quantité de temps qu’un pilote passe dans les appels de procédure différée (DPCs) et les routines de service d’interruption (ISRs) en traçant ces événements dans le noyau Windows. Ces informations vous aideront à minimiser le temps que le pilote passe à des IRQLs plus élevés, rendant le pilote et le système plus efficaces.
Microsoft recommande que les DPCs ne durent pas plus de 100 microsecondes et que les ISRs ne durent pas plus de 25 microsecondes. Pour les exigences les plus récentes, veuillez consulter la section Hardware Lab Kit.
La procédure décrite dans cette rubrique comprend les étapes suivantes :
Lancez le traçage du noyau des événements DPC/ISR.
Surveillez la session de traçage pour les événements perdus et, si nécessaire, augmentez la taille des tampons de traçage.
Exercez le pilote de test.
Arrêtez la session de traçage.
Utilisez Tracerpt pour générer un rapport qui résume l’activité DPC/ISR.
Analysez les rapports
Étape 1 : Démarrer une session de traçage.
La commande suivante démarre une session de traçage du journal du noyau NT :
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
La commande tracelog -start démarre la session de traçage. Étant donné que « NT Kernel Logger » est le nom de session par défaut, vous n’avez pas besoin de le spécifier, et vous ne pouvez pas utiliser le paramètre -guid pour spécifier un fichier fournisseur. La commande utilise le paramètre -f pour indiquer une session de journal et pour diriger les messages de traçage vers le fichier journal d’événements test01.etl.
La commande inclut le paramètre -dpcisr pour activer le traçage des DPCs, des ISRs, des commutations de contexte et du chargement d’images.
Lors du traçage des DPCs et des ISRs, ajoutez toujours le paramètre -UsePerfCounter à la commande. La résolution de l’horloge système est trop basse pour mesurer le temps passé dans ces activités. De plus, Tracerpt, l’outil qui formate les événements DPC/ISR, nécessite les valeurs de l’horloge du compteur de performance pour ses rapports. (Tracerpt est inclus dans Windows XP et les versions ultérieures de Windows).
Enfin, la commande utilise le paramètre -b pour augmenter la taille des tampons de traçage à 64 KB. Étant donné que le traçage DPC/ISR génère un volume élevé de messages de traçage à un rythme rapide, il est important d’augmenter la taille des tampons de traçage afin de ne pas perdre d’événements.
En réponse à cette commande, Tracelog démarre la session du journal du noyau NT et affiche ses propriétés.
Logger Started...
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000C18
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 5
Free Buffers: 4
Buffers Written: 14
Events Lost: 0
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test01.etl
Notez que les événements DPC, ISR et de commutation de contexte n’apparaissent pas dans le champ Enabled tracing de l’affichage. Parce que ces événements sont surveillés par l’instrumentation interne, ils n’apparaissent pas dans cette liste même lorsqu’ils sont activés. Cependant, les événements de chargement d’image, qui sont également activés par le paramètre -dpcisr, apparaissent.
Étape 2 : Vérifier les événements perdus.
Utilisez périodiquement une commande tracelog -q (query) pour vérifier les événements perdus. Si vous en trouvez, utilisez une commande tracelog -update pour ajouter plus de tampons à la session de traçage.
tracelog -q
La commande tracelog -q prend un nom de session, mais il n’est pas nécessaire d’en fournir un dans ce cas car « NT Kernel Logger » est le nom par défaut.
En réponse à cette commande, Tracelog affiche les propriétés de la session.
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000BC4
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 25
Free Buffers: 23
Buffers Written: 571
Events Lost: 544
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test.etl
Dans ce cas, 544 événements générés n’ont pas été sauvegardés dans un tampon. Pour éviter que cela ne se reproduise, utilisez une commande tracelog -update pour augmenter la taille de chaque tampon (-b) ou pour augmenter le nombre maximal de tampons (-max), par exemple :
tracelog -update -b 128 -max 40
Étape 3 : Exercez le pilote.
Utilisez vos routines de test pour faire exécuter ses fonctions au pilote. Envisagez d’exécuter deux tests, un pour les fonctions de base et un pour les fonctions plus avancées.
Étape 4 : Arrêter la session de traçage.
Utilisez la commande suivante pour arrêter la session de traçage :
tracelog -stop
Une commande tracelog -stop nécessite généralement un nom de session, mais comme « NT Kernel Logger » est le nom par défaut, le nom de session n’est pas requis.
Étape 5 : Créer un rapport DPC/ISR.
Pour résumer les messages DPC/ISR dans le journal de traçage des événements, utilisez la version de Tracerpt incluse dans Windows XP avec SP2 et les versions ultérieures de Windows.
La commande Tracerpt suivante formate les messages dans le fichier Test01.etl et crée un rapport au format texte de l’activité dans Windows XP avec SP2.
tracerpt test01.etl -report dpcisr.txt -df
Dans cette commande, le paramètre -report spécifie la méthode d’analyse et le nom du fichier de sortie. Le paramètre -df est requis pour formater correctement les messages uniquement dans Windows XP avec SP2.
Lors de la création de ce rapport dans Windows Server 2003 avec SP1 et les versions ultérieures de Windows, vous pouvez créer un rapport au format HTML en utilisant la commande suivante.
tracerpt test01.etl -report dpcisr.html -f HTML
Dans cette commande, le paramètre -report spécifie le nom du fichier de sortie et le paramètre -f spécifie le format du rapport.
Étape 6 : Analyser le rapport.
Le « Rapport de session de traçage des événements Windows » comprend les sections suivantes :
Statistiques d’image. Affiche des données sur les processus en cours d’exécution sur l’ordinateur pendant le traçage.
Totaux de disque. Affiche des données sur les E/S de disque pour chaque processus en cours d’exécution pendant le traçage.
Utilisation du processeur DPC pour l’ensemble du traçage : Affiche le pourcentage de temps processeur passé à exécuter des routines DPC pour chaque pilote.
Répartition de tous les temps d’exécution DPC pour l’ensemble du traçage. Un tableau des plages de temps en unités de microsecondes. Le tableau affiche le pourcentage de routines DPC qui tombent dans chaque plage de temps.
Répartition des temps d’exécution des routines DPC de DriverName ( DPCRoutineAddress ) pour l’ensemble du traçage. Un tableau des plages de temps en unités de microsecondes. Le tableau affiche le pourcentage d’instances de cette routine DPC qui tombent dans chaque plage de temps. Une section comme celle-ci apparaît pour chaque routine DPC dans le traçage.
Utilisation du processeur ISR pour l’ensemble du traçage. Affiche le pourcentage de temps processeur passé à exécuter des routines de service d’interruption pour chaque pilote dans le traçage.
Répartition de tous les temps d’exécution ISR pour l’ensemble du traçage. Un tableau des plages de temps en unités de microsecondes. Le tableau affiche le pourcentage de routines ISR qui tombent dans chaque plage de temps.
Répartition des temps d’exécution des routines ISR de DriverName ( ISRAddress ) pour l’ensemble du traçage. Un tableau des plages de temps en unités de microsecondes. Le tableau affiche le pourcentage d’instances de l’ISR qui tombent dans chaque plage de temps. Une section comme celle-ci apparaît pour chaque ISR dans le traçage.
Répartition de l’utilisation du processeur DPC et ISR pour des fenêtres de temps de deux microsecondes TracingPeriodInMs. Affiche l’utilisation combinée du processeur par les DPCs et les ISRs pendant le traçage.
Répartition des latences ISR de DriverName ( ISRAddress ) à DPC de DriverName ( DPCRoutineAddress ) pour l’ensemble du traçage. Affiche la répartition des intervalles de retard entre la fin d’un ISR et le début du DPC associé.
L’extrait suivant d’un rapport d’exemple montre la répartition des temps d’exécution DPC pour Ipsec.sys. En général, les routines DPC durant plus de 100 microsecondes sont découragées. Le rapport montre que plus de la moitié des routines DPC pour ce pilote dépassent le seuil.
+------------------------------------------------------------------------------+
| Distribution of ipsec.sys (F7AA7449) DPC execution times for the whole trace |
+------------------------------------------------------------------------------+
| Lower Bound Upper Bound Count Percent |
+------------------------------------------------------------------------------+
| 0 1 0 0.00% |
| 1 2 0 0.00% |
| 2 3 8 42.11% |
| 3 4 1 5.26% |
| 4 5 0 0.00% |
| 5 10 0 0.00% |
| 10 25 0 0.00% |
| 25 50 0 0.00% |
| 50 100 0 0.00% |
| 100 250 10 52.63% |
+------------------------------------------------------------------------------+
| 19 100.00% |
+------------------------------------------------------------------------------+