Beispiel 15: Messen der DPC/ISR-Zeit
Sie können die Zeit messen, die ein Treiber in Deferred Procedure Calls (DPCs) und Interrupt Service Routines (ISRs) verbringt, indem Sie diese Ereignisse im Windows-Kernel nachverfolgen. Diese Informationen helfen Ihnen, die Zeit, die der Treiber bei höheren IRQLs verbringt, zu minimieren, wodurch der Treiber und das System effizienter werden.
Microsoft empfiehlt, dass DPCs nicht länger als 100 Mikrosekunden und ISRs nicht länger als 25 Mikrosekunden laufen sollten. Die aktuellsten Anforderungen finden Sie im Hardware Lab Kit.
Das in diesem Abschnitt beschriebene Verfahren umfasst die folgenden Schritte:
Start der Kernel-Verfolgung von DPC/ISR-Ereignissen.
Überwachen Sie die Trace-Sitzung auf verlorene Ereignisse und erhöhen Sie gegebenenfalls die Größe der Trace-Puffer.
Üben Sie den Testfahrer.
Beenden Sie die Trace-Sitzung.
Verwenden Sie Tracerpt, um einen Bericht zu erstellen, der die DPC/ISR-Aktivität zusammenfasst.
Analysieren Sie die Berichte
Schritt 1: Starten Sie eine Trace-Sitzung.
Der folgende Befehl startet eine NT-Kernel-Logger-Trace-Sitzung:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
Der Befehl tracelog -start startet die Trace-Sitzung. Da "NT Kernel Logger" der Standard-Sitzungsname ist, müssen Sie ihn nicht angeben, und Sie können den Parameter -guid nicht zur Angabe einer Anbieterdatei verwenden. Der Befehl verwendet den Parameter -f, um eine Protokollsitzung anzugeben und die Ablaufverfolgungsmeldungen in die Protokolldatei test01.etl Event Trace zu leiten.
Der Befehl enthält den Parameter -dpcisr zur Aktivierung der Verfolgung von DPCs, ISRs, Kontextwechseln und dem Laden von Bildern.
Wenn Sie DPCs und ISRs verfolgen, fügen Sie dem Befehl immer den Parameter -UsePerfCounter hinzu. Die Auflösung des Systemtimers ist zu gering, um die für diese Tätigkeiten aufgewendete Zeit zu messen. Auch Tracerpt, das Tool zur Formatierung von DPC/ISR-Ereignissen, benötigt die Performance-Counter-Taktwerte für seine Berichte. (Tracerpt ist in Windows XP und späteren Versionen von Windows enthalten)
Schließlich verwendet der Befehl den Parameter -b, um die Größe der Trace-Puffer auf 64 KB zu erhöhen. Da das DPC/ISR-Tracing eine große Menge an Trace-Meldungen in kurzer Zeit erzeugt, ist es wichtig, die Größe der Trace-Puffer zu erhöhen, damit keine Ereignisse verloren gehen.
Als Antwort auf diesen Befehl startet Tracelog die NT-Kernel-Logger-Sitzung und zeigt deren Eigenschaften an.
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
Beachten Sie, dass DPC-, ISR- und Kontextwechselereignisse nicht im Feld Enabled tracing der Anzeige erscheinen. Da diese Ereignisse von internen Instrumenten überwacht werden, erscheinen sie nicht in dieser Liste, selbst wenn sie aktiviert sind. Es werden jedoch Bildladeereignisse angezeigt, die auch durch den Parameter -dpcisr aktiviert werden.
Schritt 2: Suchen Sie nach verlorenen Ereignissen.
Verwenden Sie den Befehl tracelog -q (query), um regelmäßig nach verlorenen Ereignissen zu suchen. Wenn Sie diese finden, verwenden Sie den Befehl tracelog -update, um der Trace-Sitzung weitere Puffer hinzuzufügen.
tracelog -q
Der Befehl tracelog -q benötigt einen Sitzungsnamen, der in diesem Fall jedoch nicht angegeben werden muss, da "NT Kernel Logger" der Standard ist.
Als Antwort auf diesen Befehl zeigt Tracelog die Eigenschaften der Sitzung an.
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
In diesem Fall wurden 544 Ereignisse, die erzeugt wurden, nicht in einem Puffer gespeichert. Um dies zu verhindern, verwenden Sie z. B. den Befehl tracelog -update, um die Größe der einzelnen Puffer zu erhöhen (-b) oder die maximale Anzahl der Puffer zu erhöhen (-max):
tracelog -update -b 128 -max 40
Schritt 3: Üben Sie den Fahrer.
Verwenden Sie Ihre Testroutinen, damit der Treiber seine Funktionen ausführt. Erwägen Sie, zwei Tests durchzuführen, einen für die Grundfunktionen und einen für die fortgeschrittenen Funktionen.
Schritt 4: Beenden Sie die Trace-Sitzung.
Verwenden Sie den folgenden Befehl, um die Trace-Sitzung zu beenden:
tracelog -stop
Der Befehl tracelog -stop erfordert normalerweise einen Sitzungsnamen, aber da "NT Kernel Logger" die Standardeinstellung ist, ist der Sitzungsname nicht erforderlich.
Schritt 5: Erstellen Sie einen DPC/ISR-Bericht.
Um die DPC/ISR-Meldungen im Ereignisprotokoll zusammenzufassen, verwenden Sie die in Windows XP mit SP2 und späteren Versionen von Windows enthaltene Version von Tracerpt.
Der folgende Tracerpt-Befehl formatiert die Meldungen in der Datei Test01.etl und erstellt einen textformatierten Bericht über die Aktivitäten in Windows XP mit SP2.
tracerpt test01.etl -report dpcisr.txt -df
In diesem Befehl gibt der Parameter -report die Methode der Analyse und den Namen der Ausgabedatei an. Der Parameter -df ist nur unter Windows XP mit SP2 erforderlich, um die Nachrichten korrekt zu formatieren.
Wenn Sie diesen Bericht in Windows Server 2003 mit SP1 und späteren Versionen von Windows erstellen, können Sie einen HTML-formatierten Bericht mit dem folgenden Befehl erstellen.
tracerpt test01.etl -report dpcisr.html -f HTML
In diesem Befehl gibt der Parameter -report den Namen der Ausgabedatei an, und der Parameter -f gibt das Berichtsformat an.
Schritt 6: Analysieren Sie den Bericht.
Der "Windows Event Trace Session Report" besteht aus folgenden Abschnitten:
Image-Statistics. Zeigt Daten über die Prozesse an, die während der Aufzeichnung auf dem Computer laufen.
Gesamtzahl der Scheiben. Zeigt Daten über Festplatten-E/A für jeden Prozess an, der während des Traces läuft.
DPC-Prozessorauslastung für den gesamten Trace: Zeigt den prozentualen Anteil der Prozessorzeit an, der für die Bedienung der DPC-Routinen für jeden Treiber aufgewendet wird.
Verteilung aller DPC-Ausführungszeiten für die gesamte Spur. Eine Tabelle mit Zeitbereichen in Mikrosekundeneinheiten. Die Tabelle zeigt den Prozentsatz der DPC-Routinen, die in jeden Zeitbereich fallen.
Verteilung der DriverName ( DPCRoutineAddress ) DPC-Ausführungszeiten für den gesamten Trace. Eine Tabelle mit Zeitbereichen in Mikrosekundeneinheiten. Die Tabelle zeigt den Prozentsatz der Instanzen dieser DPC-Routine, die in jeden Zeitbereich fallen. Ein Abschnitt wie dieser erscheint für jede DPC-Routine im Trace.
ISR-Prozessorauslastung für den gesamten Trace. Zeigt den prozentualen Anteil der Prozessorzeit an, der für die Bedienung von Interrupt-Service-Routinen für jeden Treiber im Trace verwendet wird.
Verteilung aller ISR-Ausführungszeiten für den gesamten Trace. Eine Tabelle mit Zeitbereichen in Mikrosekundeneinheiten. Die Tabelle zeigt den prozentualen Anteil der ISR-Routinen, die in jeden Zeitbereich fallen.
Verteilung der DriverName ( ISRAddress ) ISR-Ausführungszeiten für den gesamten Trace. Eine Tabelle mit Zeitbereichen in Mikrosekundeneinheiten. Die Tabelle zeigt den Prozentsatz der Instanzen des ISR, die in jeden Zeitbereich fallen. Ein Abschnitt wie dieser erscheint für jede ISR im Trace.
Verteilung der DPC- und ISR-Prozessorauslastung für TracingPeriodInMs zwei Mikrosekunden-Zeitfenster. Zeigt die kombinierte Prozessorauslastung durch DPCs und ISRs während des Traces an.
Verteilung der Latenzen zwischen DriverName ( ISRAddress ) ISR und DriverName ( DPCRoutineAddress ) DPC für den gesamten Trace. Zeigt die Verteilung der Verzögerungsintervalle zwischen dem Ende eines ISR und dem Beginn des zugehörigen DPC an.
Der folgende Auszug aus einem Beispielbericht zeigt die Verteilung der DPC-Ausführungszeiten für Ipsec.sys. Im Allgemeinen wird von DPC-Routinen, die länger als 100 Mikrosekunden dauern, abgeraten. Der Bericht zeigt, dass mehr als die Hälfte der DPC-Routinen für diesen Treiber den Schwellenwert überschreiten.
+------------------------------------------------------------------------------+
| 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% |
+------------------------------------------------------------------------------+