示例 15：测量 DPC/ISR 时间

  • 项目

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

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

本节中所述的过程包括以下步骤：

  1. 启动 DPC/ISR 事件的内核跟踪。

  2. 监视跟踪会话中丢失的事件，并在必要时增加跟踪缓冲区的大小。

  3. 练习测试驱动程序。

  4. 停止跟踪会话。

  5. 使用 Tracerpt 生成汇总 DPC/ISR 活动的报告。

  6. 分析报表

步骤 1：启动跟踪会话。

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

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

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

命令包含 -dpcisr 参数，用于启用 DPC、ISR、上下文开关和图像加载的跟踪。

跟踪 DPC 和 ISR 时，始终将 -UsePerfCounter 参数添加到 命令。 系统计时器分辨率太低，无法测量这些活动所花费的时间。 此外，Tracerpt（格式化 DPC/ISR 事件的工具）需要其报表的性能计数器时钟值。 (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 和上下文切换事件不会显示在显示的 “已启用跟踪” 字段中。 由于这些事件由内部检测监视，因此即使启用这些事件，它们也不会出现在此列表中。 但是，也由 -dpcisr 参数启用的图像加载事件确实会出现。

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

定期使用 tracelog -q (query) 命令检查丢失事件。 如果找到它们，请使用 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 中包含的 Tracerpt 版本与 SP2 及更高版本的 Windows 配合使用。

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

tracerpt test01.etl -report dpcisr.txt -df

在此命令中， -report 参数指定分析方法和输出文件的名称。 需要 -df 参数才能仅在具有 SP2 的 Windows XP 中正确设置消息格式。

在 Windows Server 2003 SP1 及更高版本的 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 例程的百分比。

  • DriverName ( 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%        |
+------------------------------------------------------------------------------+