範例 15：測量 DPC/ISR 時間

  • 發行項

您可以藉由追蹤 Windows 核心中的這些事件，測量驅動程式花費在延後過程調用 （DPC） 和中斷服務例程的時間量。 這項資訊可協助您將驅動程序花費在較高 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 Kernel Logger」 是預設工作階段名稱，所以您不需要指定它，而且您無法使用 -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 和內容切換事件不會出現在 顯示器的 [已啟用追蹤 ] 字段中。 由於這些事件是由內部檢測監視，因此即使啟用這些事件，也不會出現在此清單中。 不過，也會由 -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） 或增加緩衝區數目上限，例如：

tracelog -update -b 128 -max 40

步驟 3：練習驅動程式。

使用測試例程讓驅動程式執行其函式。 請考慮執行兩個測試，一個用於基本函式，另一個用於更進階的函式。

步驟 4：停止追蹤會話。

使用下列命令來停止追蹤工作階段：

tracelog -stop

tracelog -stop 命令通常需要會話名稱，但因為 “NT Kernel Logger” 是預設值，因此不需要會話名稱。

步驟 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 參數，才能在 Windows XP 中使用 SP2 正確格式化訊息。

使用 SP1 和更新版本的 Windows 在 Windows Server 2003 中建立此報表時，您可以使用下列命令建立 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都會顯示類似此區段的區段。

  • 追蹤追蹤PeriodInMs的 DPC 和 ISR 處理器使用率分佈兩個微秒時間範圍。 在追蹤期間顯示 DPC 和 ISR 的合併處理器使用率。

  • 將 DriverName （ISRAddress） ISR 散發至 DriverName （DPCRoutineAddress） DPC 延遲，以取得整個追蹤。 顯示ISR結尾與相關聯 DPC 開頭之間的延遲間隔分佈。

下列範例報表摘錄顯示Ipsec.sys的 DPC 運行時間分佈。 一般而言，DPC 例程持續超過 100 微秒，不建議使用。 報告顯示，此驅動程式的 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%        |
+------------------------------------------------------------------------------+