演習 3 - クリティカルパスと待機の分析について理解する

[アーティクル]
06/20/2023

シナリオとアクティビティが予期せず遅延する場合があります。たとえば、Microsoft Edge 内でタブを開くとき、予想以上に時間がかかる場合があります。

アクティビティとは、ある開始イベントからある終了イベントまで、順次または並行して行われる一連の操作と定義されます。トレース内の開始イベントと終了イベントのペアは、アクティビティと見なすことができます。この一連の操作で最も長いパスをクリティカルパスと呼びます。クリティカルパス上のいずれかの操作の期間を短縮することで、アクティビティ全体の期間を直接短縮できます。

アクティビティを完了したプロセスとスレッドを特定し、アクティビティが完了した時間から遡って作業を行うことをお勧めします。まず、アクティビティを完了したスレッドを分析して、そのスレッドがその時間のほとんどをどの状態 (実行中、準備完了、または待機中) で過ごしたかを確認します。

実行中の時間が極めて長い場合は、直接の CPU 使用率がクリティカルパスの期間に影響を与えていることを示します。 準備完了状態で時間を費やしている場合は、他のスレッドがクリティカルパス上のスレッドの実行を妨げることで、クリティカルパスの期間に影響を与えていることを示します。 待機中で費やした時間は、I/O、タイマーなど、クリティカルパス上の他のスレッドやプロセスを現在のスレッドが待機していたことを示します。

現在のスレッドの準備をする各スレッドは、おそらくクリティカルパスの別のリンクであり、クリティカルパスの期間の詳細が明らかになるまで分析の対象となる可能性があります。

必要なすべての情報が、WPA の CPU Usage (Precise) (CPU 使用率 (厳密)) グラフ/テーブルに記録されます。ディスパッチャーによってログに記録される CPU 使用率イベントは、コンテキストスイッチに関連付けられています。このテーブルは、切り替わった後のスレッドである NewThread に焦点を合わせ、各行がコンテキストスイッチを表しています。データは、以下のイベントシーケンスについて収集されます。

データ収集ワークフローを示す図。

NewThread が、ブロッキング関数の呼び出しのため、別のスレッドに切り替わります。
NewThread が、準備スレッドによって実行準備完了状態になります。
NewThread に切り替わり、それによって古いスレッドはオフになります。
NewThread が再び別のスレッドに切り替わります。

以下に、CPU Usage (Precise) (CPU 使用率 (厳密)) テーブルの興味深い列を示します。

列	詳細
% CPU Usage	切り替えられた後の新しいスレッドの CPU 使用率。この値は、現在表示されている期間の総 CPU 時間に対する割合で表されます。
Count	行で表されるコンテキストスイッチの数。これは、個々の行に対して常に 1 です。
CPU Usage (ms)	コンテキストの切り替え後の新しいスレッドの CPU 使用率。
NewProcess	新しいスレッドのプロセス。
NewThreadId	新しいスレッドのスレッド ID。
NewThreadStack	新しいスレッドに切り替わったときのスレッドのスタック。通常、スレッドをブロックしたもの、またはスレッドが待機していたものを示します。
Ready(s)	スレッドが準備完了のキューで費やした時間 (プリエンプションまたは CPU の枯渇が原因)。
ReadyingThreadId	準備スレッドのスレッド ID。
ReadyingProcess	準備スレッドを所有するプロセス。
ReadyThreadStack	準備スレッドのスタック。
ReadyTime (s)	新しいスレッドの準備ができたときの時間。
SwitchInTime(s)	新しいスレッドに切り替わったときの時間。
Waits (s)	スレッドが論理リソースまたは物理リソースで待機した時間。 ReadyingThreadId によって NewThreadId が通知されたときに待機は終了します。

手順 1: UI 遅延の問題のため、トレースをキャプチャして開く

この演習では、UI が応答しないダミープロセスに重点的に取り組みます。このプロセスは、ボタンとテキストボックスを含むシンプルな Windows フォームアプリケーションです。ボタンをクリックすると、テキストボックスが更新されるまで 20 秒間 UI が応答しなくなります。この操作のクリティカルパスを分析します。

UIDelage サンプルダイアログのスクリーンショット。

こちらから UIDelay.exe をダウンロードします。
UIDelay.exe を起動します。
[スタート] メニューから WPR を開きます。
トレース構成を変更します。
1. [First Level Triage] (第 1 レベルのトリアージ) と [CPU 使用率] を選択します。
2. パフォーマンスシナリオとして [全般] を選択します。
3. 詳細レベルとして [詳細] を選択します。
[開始] をクリックします。
UIDelay.exe で [Click] (クリック) ボタンをクリックします。
- テキストボックスに "Done!" と表示されるまで待ちます。
WPR でトレースを保存し、WPA で開きます。
[トレース] メニューを開き、[Configure symbols path (シンボルパスの構成)] を選択します。
- シンボルキャッシュのパスを指定します。シンボルの詳細については、MSDN のシンボルサポートに関するページを参照してください。
[トレース] メニューを開き、[シンボルの読み込み] を選択します。

手順 2: 遅延している UI スレッドを特定する

クリティカルパスの分析を実行する前に、まずアクティビティの開始イベントと停止イベントを特定する必要があります。

Graph エクスプローラーの System Activity ノードにある UI Delays グラフを探します。
UI Delays グラフを [分析] タブにドラッグアンドドロップします。
UIDelay.exe プロセスを探します。
1. その期間は約 20 秒のはずです。これは、UIDelay.exe の UI スレッドで 20 秒の遅延があったことを示しています。
2. UI スレッド識別子が "スレッド ID" 列に表示されます。この例では 24174 です。この値は、ご使用のコンピューターでキャプチャしたトレースでは異なります。必ずスレッド ID をメモしてください。
UIDelay.exe の時間間隔全体を選択し、右クリックして拡大します。

分析しようとしている領域を常に拡大する必要があります。これによって、関連のないアクティビティによって発生するノイズの量が低減します。

手順 3: UI 遅延のクリティカルパスを分析する

以上でスレッド ID とタイムスタンプを含む分析の開始点を入手したので、UI スレッドで 20 秒の遅延を招く一連のイベントを理解するため、アクティビティのクリティカルパスの調査を開始することができます。

この手順の NewThreadId は、手順 2 で特定したスレッド (UIDelay.exe プロセスのスレッド 24174) です。

CPU Usage (Precise) グラフを [分析] タブに追加し、Utilization by Process, Thread (プロセス、スレッド別の使用率) プリセットを適用します。
列ヘッダーを右クリックし、NewThreadStack 列、ReadyThreadStack 列、CPU Usage (ms) 列を表示します。
Ready (us) [Max] 列と Waits (us) [Max] 列を削除します。これでビューポートは次のようになります。
NewProcess 列で UIDelay.exe プロセスを検索して展開し、列ヘッダーをクリックして Waits (us) [Sum] で並べ替えます。
UIDelay.exe プロセスで NewThreadId を検索し、実行中、準備完了、または待機中の状態で費やされた時間を分析します。
- 次の例では、以下のことを確認できます。
  - スレッドが消費している CPU 時間は 10.025 秒
  - スレッドが待機している時間は 5.159 秒
  - スレッドが準備完了状態にあるのは、ごくわずかな時間 (10 ミリ秒)
注演習 2、手順 4 で説明したのと同じ方法を使用して、CPU Usage (sampled) グラフを使用し、UIDelay.exe プロセスを確認することで、10 秒の CPU アクティビティを分析できます。
NewThreadId が何を待機していたかを調べるには、NewThreadId グループを展開して NewThreadStack を表示します。
[Root] を展開し、待機となる関数呼び出しを特定します。