How much time is your driver spending in its DPCs and ISRs?
Updated: August 13, 2005
For good system performance, a Windows kernel-mode driver should minimize the time it spends in its deferred procedure calls (DPCs) and interrupt service routines (ISRs). DPCs and ISRs run at an elevated interrupt request level, or IRQL (DISPATCH_LEVEL and device IRQL, respectively). A driver that spends too much time in its DPCs and ISRs prevents the system from servicing threads, which degrades overall system performance. A driver should spend no more than 25 microseconds in an ISR and no more than 100 microseconds in a DPC.
You can measure the time that Windows kernel-mode drivers spend in DPCs and ISRs by using a new feature of Tracelog, a command-line tool provided with the Windows Driver Kit (WDK) that manages software tracing sessions. The DPC/ISR feature of Tracelog captures the activity of all drivers running in the kernel during the trace, even drivers that are not instrumented for tracing.
Windows XP SP2 and later versions of Windows are instrumented for DPC/ISR tracing. To actually trace DPC/ISR activity, however, you need the version of Tracelog provided in the WDK for Windows Vista and later versions of the WDK. This tool is installed in the %winddk%\tools\tracing folder.
Starting a DPC/ISR trace session
The following Tracelog command starts a DPC/ISR trace session and saves the output in the dpcisr.etl event trace log file:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
In this command line:
| • | The tracelog -start command starts the trace session. "NT Kernel Logger" is the default trace provider so it is not necessary to specify it in the command, but you cannot use the -guid parameter to specify a provider. |
| • | The -f parameter creates a log session and directs the trace messages to the test01.etl event trace log file. |
| • | The -dpcisr parameter enables tracing of DPCs, ISRs, context switches, and image loading. |
| • | The -UsePerfCounter parameter records the value of the high-resolution performance counter clock, rather than the lower-resolution system time, with each trace message. This is necessary because the system timer resolution is too low to measure the time spent in DPCs and ISRs and because Tracerpt, the tool that formats DPC/ISR events, requires the performance counter clock values for its reports. (Tracerpt is included in Windows XP and later versions of Windows.) |
| • | The -b parameter increases the size of the trace buffers to 64 KB. DPC/ISR tracing generates a high volume of trace messages at a rapid rate, so it is possible to "lose" events if trace buffers are too small. It might also be necessary to increase the number of buffers by using the -max parameter. (The default number of buffers depends on the number of processors, the amount of physical memory, and the operating system in use.) |
Allow the trace to run for a few minutes, and exercise your driver while the trace is running. The statistics in the report are averages for the duration of the trace session, so if you want to simulate more than one test condition, run the tests during separate trace sessions. To see if events are being lost, periodically issue a tracelog -q command and, if necessary, use tracelog -update to increase buffer size or add more buffers for the trace session (for example, tracelog -update -b 128 -max 40.)
When you finish exercising your driver, use the following command to stop the trace session:
tracelog -stop
Creating the DPC/ISR trace report
To summarize the DPC/ISR messages in the event trace log, use the version of Tracerpt included in Windows XP SP2 and later versions of Windows.
The following Tracerpt command formats the messages in the test01.etl file and creates a text-formatted report of the activity in Windows XP SP2.
tracerpt test01.etl -report dpcisr.txt -df
In this command:
| • | The -report parameter specifies the method of analysis and the name of the output file, dpcisr.txt. |
| • | The -df parameter is required only for Windows XP SP2 to format the messages correctly. In Windows Server 2003 SP1 and later versions of Windows, you can create an HTML-formatted report by using -f HTML. |
In addition to image statistics and data about disk I/O for each process running during the trace, the DPC/ISR event trace session report contains information related to DPC and ISR execution, such as the following:
| • | DPC and ISR processor utilization as a percentage of processor time spent servicing DPC and ISR routines for each driver in the trace. |
| • | Distribution of DPC and ISR execution times that fall into different time ranges, for all DPC and ISR routines in the trace and for instances of individual routines. |
| • | Distribution of individual ISR to DPC latencies for the whole trace, showing delay intervals between the end of an ISR and the beginning of the associated DPC. |
For example, the following excerpt from a sample report shows the distribution of DPC execution times for ipsec.sys. The Lower Bound and Upper Bound columns show the time ranges in microseconds. This report shows that more than half of the DPC routines for this driver run between 100 and 250 microseconds, exceeding the recommended threshold.
+------------------------------------------------------------------------------+
| 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% |
+------------------------------------------------------------------------------+
For more information about Tracelog and the -dpcisr parameter, see "Tracelog" in the Windows Driver Kit documentation. The Tracelog documentation includes an extended example, "Example 15: Measuring DPC/ISR Time," that shows the details of the DPC/ISR tracing procedure and explains the report that Tracerpt generates.
For information about how a processor's IRQL affects the operation of kernel-mode drivers, see "Scheduling, Thread Context, and IRQL" at the end of this tip.
What should you do?
| • | Use Tracelog with the -dpcisr parameter to find out how much time your driver is spending in its DPC and ISR routines. |
| • | Optimize your driver's DPC and ISR routines to run as quickly as possible. |
For more information:
Windows Driver Kit (WDK)
Release versions of the WDK are available on WHDC or through MSDN Subscription.
Example 15: Measuring DPC/ISR Time
Event Tracing
Scheduling, Thread Context, and IRQL
Device-Driver Performance Considerations for Multimedia Platforms
