例15: DPC/ISR時間の測定
ドライバーが遅延プロシージャ呼び出し (DPC) と割り込みサービス ルーチン (ISR) に費やす時間を測定するには、Windows カーネルでこれらのイベントをトレースします。 この情報は、ドライバーがより高い 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 イベント トレース ログ ファイルに転送します。
このコマンドには、DPC、 ISR、コンテキスト スイッチ、およびイメージの読み込みのトレースを有効にする -dpcisr パラメーターが含まれています。
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) バッファーの最大数 (-max) を増やします。次に例を示します。
tracelog -update -b 128 -max 40
手順 3: ドライバーを実行します。
テスト ルーチンを使用して、ドライバーが機能を実行するようにします。 基本関数用と高度な関数用の 2 つのテストを実行することを検討してください。
手順4: トレース セッションを停止します。
次のコマンドを使用してトレース セッションを停止します。
tracelog -stop
tracelog -stop コマンドには通常、セッション名が必要ですが、"NT カーネル ロガー" が既定であるため、セッション名は必要ありません。
手順 5: DPC/ISR レポートを作成する。
イベント トレース ログの DPC/ISR メッセージを要約するには、Sp2 以降のバージョンの Windows で Windows XP に含まれる Tracerpt のバージョンを使用します。
次の 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 プロセッサ使用率の 2 マイクロ秒の時間枠の分布。 トレース中の 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% |
+------------------------------------------------------------------------------+