示例 15：测量 DPC/ISR 时间

项目
05/29/2024

通过跟踪 Windows 内核中的延迟过程调用 (DPC) 和中断服务例程 (ISR)，可以测量驱动程序在这些事件中花费的时间。这些信息将帮助您最大限度地减少驱动程序在较高 IRQL 上花费的时间，从而提高驱动程序和系统的效率。

Microsoft 建议，DPC 的运行时间不应超过 100 微秒，ISR 的运行时间不应超过 25 微秒。有关最新要求，请参阅硬件实验套件。

本节介绍的程序包括以下步骤：

启动 DPC/ISR 事件的内核跟踪。
监控跟踪会话中丢失的事件，必要时增加跟踪缓冲区的大小。
测试驱动程序。
停止跟踪会话。
使用 Tracerpt 生成报告，汇总 DPC/ISR 活动。
分析报告

步骤 1：开始跟踪会话。

以下命令将启动 NT 内核记录器跟踪会话：

tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64

该 tracelog -start 命令启动跟踪会话。由于“NT 内核记录器”是默认会话名称，因此无需指定，也不能使用 -guid 参数指定提供程序文件。该命令使用 -f 参数指示日志会话，并将跟踪信息导入 test01.etl 事件跟踪日志文件。

该命令包含 -dpcisr 参数，用于启用对 DPC、ISR、上下文切换和映像加载的跟踪。

跟踪 DPC 和 ISR 时，请务必在命令中添加 -UsePerfCounter 参数。系统计时器的分辨率太低，无法测量这些活动所花费的时间。此外，格式化 DPC/ISR 事件的工具 Tracerpt 也需要性能计数器时钟值来生成报告。 (Tracerpt 包含在 Windows XP 和更高版本的 Windows 中）。

最后，该命令使用 -b 参数将跟踪缓冲区的大小增至 64 KB。由于 DPC/ISR 跟踪会快速生成大量跟踪信息，因此必须增加跟踪缓冲区的大小，以免丢失事件。

作为对该命令的响应，Tracelog 会启动 NT 内核记录器会话并显示其属性。

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

请注意，DPC、ISR 和上下文切换事件不会出现在 Enabled tracing 显示字段中。由于这些事件由内部仪器监控，因此即使启用了这些事件，它们也不会出现在此列表中。不过，图像加载事件（也可通过 -dpcisr 参数启用）确实会出现。

步骤 2：检查丢失的事件。

定期使用 tracelog -q （查询）命令检查丢失的事件。如果发现它们，请使用 tracelog -update 命令向跟踪会话添加更多缓冲区。

tracelog -q

该 tracelog -q 命令需要会话名称，但在本例中无需提供，因为“NT 内核记录器”是默认名称。

作为对该命令的响应，Tracelog 会显示会话的属性。

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

在这种情况下，生成的 544 个事件没有保存在缓冲区中。要防止这种情况再次发生，可使用 tracelog -update 命令增加每个缓冲区的大小 (-b) 或增加缓冲区的最大数量 (-max) 等：

tracelog -update -b 128 -max 40

步骤 3：锻炼驾驶员。

使用测试例程使驱动程序执行其功能。考虑运行两个测试，一个测试基本功能，另一个测试更高级的功能。

步骤 4：停止跟踪会话。

使用以下命令停止跟踪会话：

tracelog -stop

该 tracelog -stop 命令通常需要会话名称，但由于“NT 内核记录器”是默认设置，因此不需要会话名称。

步骤 5：创建 DPC/ISR 报告。

要汇总事件跟踪日志中的 DPC/ISR 消息，请使用 Windows XP SP2 及更高版本 Windows 中包含的 Tracerpt 版本。

以下 Tracerpt 命令格式化了 Test01.etl 文件中的信息，并在装有 SP2 的 Windows XP 中创建了文本格式的活动报告。

tracerpt test01.etl -report dpcisr.txt -df

在该命令中， -report 参数指定了分析方法和输出文件的名称。只有在带 SP2 的 Windows XP 中，才需要使用 -df 参数来正确格式化报文。

在带 SP1 的 Windows Server 2003 和更高版本的 Windows 中创建此报告时，可使用以下命令创建 HTML 格式的报告。

tracerpt test01.etl -report dpcisr.html -f HTML

在该命令中， -report 参数指定输出文件的名称， -f 参数指定报告格式。

步骤 6：分析报告。

Windows 事件跟踪会话报告 "包含以下部分：

图像统计。 显示跟踪期间计算机上运行的进程数据。
磁盘总数。 显示跟踪期间运行的每个进程的磁盘 I/O 数据。
整个轨迹的 DPC 处理器利用率：显示每个驱动程序用于 DPC 例程的处理器时间百分比。
整个跟踪过程中所有 DPC 执行时间的分布。以微秒为单位的时间范围表。该表显示了每个时间范围内 DPC 例程的百分比。
整个跟踪中 DriverName ( DPCRoutineAddress ) DPC 执行时间的分布。 以微秒为单位的时间范围表。该表显示了该 DPC 例程在每个时间范围内的实例百分比。跟踪中的每个 DPC 例程都会出现类似这样的部分。
整个跟踪过程中 ISR 处理器的利用率。 显示跟踪中每个驱动程序用于中断服务例程的处理器时间百分比。
整个跟踪的所有 ISR 执行时间分布。 以微秒为单位的时间范围表。该表显示了每个时间范围内 ISR 例程的百分比。
整个跟踪过程中驱动程序名称 ( ISRAddress ) ISR 执行时间的分布。 以微秒为单位的时间范围表。该表显示 ISR 实例在每个时间范围内的百分比。跟踪中的每个 ISR 都会出现类似这样的部分。
TracingPeriodInMs 两个微秒时间窗口的 DPC 和 ISR 处理器利用率分布。 显示跟踪期间 DPC 和 ISR 的综合处理器利用率。
整个跟踪中从 DriverName ( ISRAddress ) ISR 到 DriverName ( DPCRoutineAddress ) DPC 延迟的分布。 显示 ISR 结束与相关 DPC 开始之间延迟时间间隔的分布。

下面的示例报告节选显示了 Ipsec.sys 的 DPC 执行时间分布。一般来说，不鼓励使用超过 100 微秒的 DPC 例程。报告显示，该驱动程序的半数以上 DPC 例程都超过了阈值。

+------------------------------------------------------------------------------+
| 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%        |
+------------------------------------------------------------------------------+

通过