PerfViewとdotnet-traceで「遅い」を特定する ── .NETパフォーマンス調査の実務入門

前回の「Windowsイベントログ・ETW入門」では、ETWが何であるかと、EventSource で独自イベントを定義するところまでを扱い、PerfViewでの解析は「範囲外」としました。この記事はその続きです。業務アプリが「遅い」「CPUが張り付く」「たまに固まる」ときに、PerfViewとdotnet-traceで原因の関数まで特定する手順を扱います。

なお、この記事はCPU・応答時間の調査が主題です。メモリが増え続ける問題の切り分けは「.NETでGC待ちとメモリリークを見分ける」、クラッシュしてしまう問題は「WinDbg + SOSでクラッシュダンプを読む」で扱っています。

1. まず結論

• 「遅い」には2種類あります。CPUを使い切って遅い(CPU bound)か、CPUは暇なのに待たされて遅い(ブロック)かです。 前者はCPUサンプリング、後者はThreadTime(コンテキストスイッチ)の収集が必要で、既定のCPU収集だけ見ても後者の原因は写りません。¹
• 迷ったら dotnet-trace から始めます。 EventPipeベースのクロスプラットフォームツールで、対象プロセスを起動したのと同じユーザーであれば管理者権限なしで収集できます。² 収集した .nettrace はPerfViewやVisual Studioで開けます。³
• PerfViewが必要になるのは、マシン全体・ネイティブ・ブロック時間まで見たいときです。 ETWベースなので、カーネルイベントやネイティブコードのスタックも扱えます。その代わり、ETWセッションの開始には管理者権限が必要です。³
• CPUサンプリングは既定で1ミリ秒ごと(プロセッサごと)です。 1サンプル=約1msのCPU時間として読み、目安として1,000サンプル以上(できれば5,000程度)集まってから判断します。サンプル数が少ないうちの上位関数は偶然の可能性があります。¹
• 数字の解釈は inclusive(自分+呼び出し先) と exclusive(自分自身) の区別がすべての起点です。 exclusiveが大きい関数が「実際にCPUを使っている場所」、inclusiveが大きい関数は「その配下のどこかが重い場所」です。
• 測る前に、何が「遅い」のかを1つの操作に固定します。 「全体的に重い」のまま収集しても読めません。「この帳票の出力に40秒かかる」のように操作と時間を固定してから収集します。改善前後の比較計測の考え方は「Windowsでプログラムのバージョン別速度を正しく比較する方法」も参考になります。

症状からの入り口を判断表にまとめます。

この記事の知識マップ

業務アプリの「遅い」はCPUを使い切っているCPU boundな遅さと、CPUは暇なのに待たされているブロックによる遅さに分かれ、前者はCPUサンプリング、後者はコンテキストスイッチを記録するThreadTime収集でなければ原因が見えない。管理者権限が不要でクロスプラットフォームなdotnet-trace(EventPipe)がまず試す対象で、マシン全体・ネイティブコード・ブロック時間まで見たい場合はETWベースのPerfViewが必要になる。収集した.nettraceファイルはPerfView・Visual Studio・speedscopeで開け、PerfViewのスタックビューアーはexclusive(自分自身)とinclusive(自分+呼び出し先)の区別を起点に読む。EventSourceで業務処理の区間を独自イベントとして計装しておくと、遅かった1回だけに絞り込んだ分析ができる。

flowchart LR
    accTitle: PerfViewとdotnet-traceによる.NET性能調査の知識マップ
    accDescr: CPU boundな遅さとブロックによる遅さを見分ける入り口として、dotnet-trace(EventPipe)とPerfView(ETW)の役割分担、CPUサンプリングとThreadTime収集の使い分け、inclusive/exclusiveの読み方、EventSourceの独自イベントによる区間の絞り込みを示す図
    perfview["PerfView"]
    dotnet_trace["dotnet-trace"]
    etw["ETW(Event Tracing for Windows)"]
    eventpipe["EventPipe"]
    blocking_slowness["ブロックによる遅さ"]
    cpu_bound_slowness["CPU boundな遅さ"]
    perfview_stack_viewer["PerfViewのスタックビューアー"]
    inclusive_exclusive_time["inclusive/exclusive(Inc/Exc)"]
    cpu_sampling["CPUサンプリング"]
    thread_time_collection["ThreadTime収集"]
    dotnet_counters["dotnet-counters"]
    eventsource_instrumentation["EventSourceによる独自イベント計装"]
    nettrace_file[".nettraceファイル"]
    speedscope["speedscope"]
    pdb["PDB(プログラムデータベース)"]
    wpr_wpa["WPR/WPA(Windows Performance Recorder/Analyzer)"]
    perfview -->|"利用する"| etw
    dotnet_trace -->|"利用する"| eventpipe
    dotnet_trace -->|"用いるのは非推奨"| blocking_slowness
    perfview -->|"推奨される対応"| blocking_slowness
    dotnet_trace -->|"推奨される対応"| cpu_bound_slowness
    perfview -->|"実装を担う"| perfview_stack_viewer
    perfview_stack_viewer -->|"利用する"| inclusive_exclusive_time
    cpu_bound_slowness -->|"で確認できる"| cpu_sampling
    blocking_slowness -->|"で確認できる"| thread_time_collection
    thread_time_collection -->|"前提とする"| etw
    dotnet_counters -->|"より先に行うべき"| dotnet_trace
    eventsource_instrumentation -->|"利用する"| etw
    eventsource_instrumentation -->|"利用する"| eventpipe
    perfview -->|"利用する"| nettrace_file
    speedscope -->|"利用する"| nettrace_file
    perfview_stack_viewer -.->|"前提とする"| pdb
    wpr_wpa -->|"利用する"| etw
    dotnet_trace -->|"利用する"| cpu_sampling
    perfview -->|"利用する"| cpu_sampling
    perfview -.->|"利用する"| thread_time_collection

図の実線は常に成り立つ関係、破線は条件付きの関係です(成立条件は詳細ページの各関係の説明に記載)。関係すべての一覧(全20件、根拠・確度つき)と主要概念の定義は知識マップ詳細ページにまとめています。データ: JSON-LD / Turtle

2. 道具の関係を整理する ── ETWとEventPipe

登場するツールは多く見えますが、土台は2つしかありません。

• ETW(Event Tracing for Windows): OS全体を貫くトレース基盤。カーネルからアプリまで同じ時間軸で記録できる反面、セッションの開始・停止に管理者権限が必要で、Windows専用です。³
• EventPipe: .NETランタイムに組み込まれたトレース機構。管理者権限が不要で全OSで同じように動く代わりに、見えるのはマネージドコードとランタイムの範囲に限られ、カーネルイベントやネイティブスタックは取れません。²

この対応関係が頭に入っていると、「まずdotnet-traceで軽く取る。足りなければPerfViewでETWごと取る」という使い分けが自然に決まります。

3. 収集の前に ── dotnet-countersで傾向を10分見る

いきなりトレースを取るより、まず dotnet-counters でランタイムの主要メトリクスを眺めるほうが早いことが多いです。⁴

dotnet tool install --global dotnet-counters
dotnet-counters ps
dotnet-counters monitor --process-id <PID> --counters System.Runtime

ここで見るのは、CPU使用率、GCヒープサイズとGC回数、ThreadPoolのキュー長・スレッド数、例外数です。この時点で「GCが毎秒何度も走っている」「ThreadPoolのキューが伸び続けている」といった傾向が見えれば、次に取るべきトレースの種類(割り当てなのか、ブロックなのか)を絞れます。

とはいえ、初めて計測する人にとっては「その数字が異常なのか」が分かりません。最も確実な基準は、正常時の自分のアプリで同じコマンドを流して取った値です。それを持たない段階での当たり付けとして、実務で使っている見方をまとめます。⁵

閾値そのものより、「時間とともにどう動くか」を見るのが要点です。負荷に応じて増減し頭打ちになる値は健全で、負荷を止めても戻らない値が調査対象になります。メモリ系の傾向の読み方は GC待ちとメモリリークの見分け方の記事 で詳しく書いています。

4. dotnet-traceでトレースを取る

dotnet-trace はEventPipeベースの収集ツールです。⁶ インストールと基本の収集は次のとおりです。

dotnet tool install --global dotnet-trace
dotnet-trace ps
dotnet-trace collect --process-id <PID> --duration 00:00:00:30

オプションを何も指定しない場合、ランタイムの主要イベントとスレッドのサンプリングを含む既定のプロファイル構成で収集されます。かつて存在した cpu-sampling という名前のプロファイルは廃止され、現在は dotnet-common と dotnet-sampled-thread-time の組み合わせが既定です。⁶ 用途に応じて --profile gc-verbose(GCとオブジェクト割り当てのサンプリング)や --profile gc-collect(GCの発生のみを低負荷で記録)も選べます。

前回の記事で作った EventSource の独自プロバイダーを一緒に収集するには、--providers を追加します。

dotnet-trace collect --process-id <PID> --providers KomuraSoft-OrderService

収集結果は .nettrace ファイルになります。開き方は3通りあり、Visual StudioかPerfViewで開くか、speedscope形式に変換してブラウザーで見ます。⁶

dotnet-trace convert trace.nettrace --format Speedscope

speedscope形式は speedscope.app で開ける軽量なフレームグラフ表示で、「どの関数の配下で時間を使ったか」を直感的に眺めるのに向いています。

どちらで開くかは、その結果を誰に見せるかで決めると迷いません。

つまりPerfViewは調査用、speedscopeは共有用、という住み分けです。関数名まで特定する精査はPerfViewのスタックビューアーのほうが強力なので、次章に進みます。

5. PerfViewでCPUを調べる ── スタックビューアーの読み方

PerfViewはMicrosoftが無償公開している性能調査ツールで、GitHubのリリースページから PerfView.exe 1つをダウンロードするだけで動きます(インストール不要)。⁷

5.1 収集する

GUIで収集する場合の流れを、画面のどこを触るかまで書き下すと次のとおりです。

1. PerfView.exe を管理者として実行する(ETWセッションの開始に管理者権限が必要です³)
2. メニューの Collect > Collect(ショートカットは Alt+C)を選ぶ。収集用のダイアログが開き、作成するデータファイル名の入力を求められます¹
3. ダイアログのチェックボックス群で収集内容を決める。既定のままでCPUサンプルとCLRの主要イベントが収集されます。待ち時間まで調べたい場合は、ここで Thread Time チェックボックスをオンにします(6章)¹
4. Start Collection ボタンを押す
5. 調べたい操作を再現する(ここが計測対象になるので、余計な操作は挟まない)
6. Stop Collection ボタンを押す。収集停止後にデータのマージとシンボル解決が走り、2で指定した名前の .etl.zip が作られます

同じことをコマンドラインで行うなら次の形になります(こちらも管理者として実行します³)。

PerfView collect /nogui /acceptEULA /maxCollectSec:30

既定の収集は、全プロセッサで1ミリ秒ごとのCPUサンプル(コールスタック付き)と、CLRの主要イベントを含みます。¹ 収集中のオーバーヘッドは既定構成でおおむね数%程度とされています。⁸

5.2 CPU Stacksを読む

収集結果(.etl.zip)を開き、「CPU Stacks」で対象プロセスを選ぶと、スタックビューアーが開きます。

初見だと画面の要素が多いので、どこに何があるかを先に対応付けておきます。スタックビューアーは大きく「上部のフィルター入力欄」と「下部のタブ切り替えのグリッド」に分かれています。

最初に見るのは ByName タブの2つの列です。

• Exc(exclusive): その関数自身が実行中だったサンプル数。実際にCPUを消費している場所です。
• Inc(inclusive): その関数と、そこから呼ばれた先すべてのサンプル数の合計。その配下のどこかが重いことを示します。

読み方の型は、Excの上位から見て「自分のコードか、ランタイム・ライブラリか」を仕分けることです。自分のコードがExc上位に出ていれば、その関数のアルゴリズムやループが直接の対象です。System.String 系や JSON シリアライザーがExc上位なら、CallersタブでそれをIncで辿って、自分のコードのどこから大量に呼んでいるかを突き止めます。

もう1つ重要なのがサンプル数そのものの確認です。CPUサンプルは1ms間隔の統計なので、サンプル数が少ないと偶然に左右されます。目安として合計1,000サンプル以上、できれば5,000程度を集めてから判断し、足りなければ対象の操作を繰り返し実行して収集時間を延ばします。¹

なお、自社モジュールの関数名がアドレス表示になってしまう場合は、シンボル(PDB)が解決できていません。ビルド成果物のPDBを手元に揃えておくことが、そのまま調査可能性になります。この話は「PDB（プログラムデータベース）とは何か」で詳しく書いています。

6. 「CPUは暇なのに遅い」 ── ThreadTimeでブロック時間を見る

実務の「遅い」の半分以上は、CPUではなく待ちです。ロック待ち、DB・HTTP応答待ち、ファイルI/O、Task.Result によるデッドロック気味の待ち合わせ。この種の問題は、CPUサンプルには「そもそもCPUを使っていない時間」として写らないため、既定収集では原因が見えません。

PerfViewでは、収集時に Thread Time オプションを有効にすると、コンテキストスイッチのイベントが追加で記録され、各スレッドが「CPUを使っていた時間」と「ブロックしていた時間」を合わせて追えるようになります。¹

有効化の方法はGUIとコマンドラインの2通りで、どちらでも結果は同じです。

• GUIの場合: 5.1の手順2で Collect > Collect(Alt+C)のダイアログを開いたら、Thread Time チェックボックスをオンにしてから Start Collection を押します。公式ガイドも「壁時計時間の調査をしたいなら、収集ダイアログの Thread Time チェックボックスを設定する必要がある」と明記しています。¹ ここを見落として既定のまま収集し、「ブロック時間が出てこない」と悩むのが最初の関門です。
• コマンドラインの場合: /threadTime スイッチを付けます。

PerfView collect /nogui /acceptEULA /threadTime /maxCollectSec:30

解析では「Thread Time Stacks」ビューを開きます。CPU Stacksと同じスタックビューアーですが、サンプルがCPU時間だけでなくBLOCKED_TIME(ブロックしていた時間)も含む点が違います。遅い操作の時間範囲に絞り込んだうえで、処理を担っていたスレッドのBLOCKED_TIMEがどのスタック(どの待ち)に積まれているかを見ると、「合計40秒のうち35秒はこのHTTP呼び出し待ちだった」という形で内訳が出ます。

UIが固まる系の症状(操作すると数秒応答なしになる)も、正体はUIスレッドのブロックであることがほとんどです。ThreadTimeでUIスレッドのブロック先を特定したうえで、恒久対策としては同期待ちを非同期化する設計に持ち込みます。この設計側の整理は「WPF/WinFormsのasyncとUIスレッドを一枚で整理」を参照してください。

注意点として、ThreadTime収集はコンテキストスイッチごとにイベントを記録するため、既定収集よりデータ量が明確に増えます。収集時間は短く区切り、本番での長時間収集は避けてください。

7. EventSourceと組み合わせる ── 「どの区間が遅いか」を業務の言葉で切る

CPU StacksもThread Timeも、プロセス全体の集計です。「注文処理1件の中のどこが遅いか」のように業務処理の単位で切りたい場合は、前回の記事で扱った EventSource のStart/Stopイベントが効いてきます。

前回の記事を読んでいなくてもこの章だけで試せるように、追跡対象のプロバイダーを自分で作る最小コードを置いておきます。4章の --providers KomuraSoft-OrderService は、この Name を指しています。

using System.Diagnostics.Tracing;

// [EventSource(Name = ...)] がETW/EventPipeから見えるプロバイダー名になる
[EventSource(Name = "KomuraSoft-OrderService")]
public sealed class OrderServiceEventSource : EventSource
{
    public static readonly OrderServiceEventSource Log = new OrderServiceEventSource();

    [Event(1, Level = EventLevel.Informational)]
    public void OrderProcessingStart(string orderId) => WriteEvent(1, orderId);

    [Event(2, Level = EventLevel.Informational)]
    public void OrderProcessingStop(string orderId) => WriteEvent(2, orderId);
}

呼び出し側は、計測したい区間を挟むだけです。

OrderServiceEventSource.Log.OrderProcessingStart(orderId);
try
{
    ProcessOrder(orderId); // 計測したい業務処理
}
finally
{
    OrderServiceEventSource.Log.OrderProcessingStop(orderId);
}

メソッド名を 〜Start / 〜Stop で揃え、イベントIDを連番にしておくと、PerfViewのEventsビューで対の区間として読みやすくなります。finally で必ずStopを出すのは、例外で抜けた回が「終わらない区間」として残らないようにするためです。イベント定義の詳しい書き方(引数の型の制約、EventLevel と Keywords の使い分け)は 前回の記事 を参照してください。

この計装があるという前提で、調査は次の順に進みます。

• アプリ側で OrderProcessingStart / OrderProcessingStop のようなイベントを計装しておく(上のコード)
• PerfViewの「Events」ビューでそのイベントの時刻を確認し、スタックビューアーの時間範囲(Start/Endフィルター)をその区間に絞る
• 絞った範囲でCPU/ブロック時間の内訳を読む

こうすると「遅かったその1回」だけを対象に分析でき、平常時のノイズに埋もれません。独自イベントはdotnet-traceでも同じように収集できるため、計装を一度入れておけば、開発機でも本番でも同じ調べ方が通用します。パフォーマンス調査は、ツールの腕前より「アプリ側に観測点があるか」で難易度が決まる、というのが実務での実感です。

まとめ

• 「遅い」をCPU boundとブロックに切り分けるのが出発点です。前者はCPUサンプリング(1サンプル≒1ms)、後者はThreadTime収集でなければ写りません。
• まずは管理者権限なしで使えるdotnet-trace、マシン全体・ネイティブ・ブロック時間が必要ならPerfView、という使い分けが基本です。収集した.nettraceをPerfViewで読む併用も定番です。
• スタックビューアーはexclusiveとinclusiveの区別が読み方の核で、サンプル数が十分あるかを常に確認します。
• EventSourceの独自イベントで業務処理の区間を切れるようにしておくと、調査の精度が一段上がります。

合同会社小村ソフトでは、「遅い」「固まる」「CPUが張り付く」といったWindows業務アプリの性能問題の調査と、計測しやすくするための計装・設計の相談を扱っています。再現手順とトレースファイルがあれば、そこからの解析のみのご依頼も可能です。

関連記事

• Windowsイベントログ・ETW入門 ── 業務アプリのログをOS標準の仕組みに乗せる
• .NETでGC待ちとメモリリークを見分ける ── 増えるメモリを観測・比較・証明する実務手順
• WinDbg + SOSでクラッシュダンプを読む ── 収集した後の実務解析入門
• Windowsクラッシュダンプ収集入門 - WER/ProcDump/WinDbg
• PDB（プログラムデータベース）とは何か ── デバッグ情報・シンボル・Source Linkを理解する
• Windowsでプログラムのバージョン別速度を正しく比較する方法
• WPF/WinFormsのasyncとUIスレッドを一枚で整理

関連する相談領域

• 不具合調査・原因解析
• Windowsアプリ開発
• 技術相談・設計レビュー
• お問い合わせ

参考リンク

関連する記事

同じタグを共有する最新の記事です。さらに近い話題で知識を深められます。

関連トピック

このテーマと近いトピックページです。記事を起点に、関連するサービスや他の記事へ進めます。

このテーマがつながるサービス

この記事は次のサービスページにつながります。近い入口からご覧ください。

よくある質問

この記事のテーマについて、相談時によくある質問をまとめています。

PerfViewとdotnet-trace、どちらを使うべきですか？

まずdotnet-traceから試すのがおすすめです。管理者権限なしで使え、対象プロセスだけを狙って収集でき、操作もコマンド1行で済みます。一方、ネイティブコードのスタックまで見たい場合、マシン全体の状況(他プロセスやカーネルの影響)まで見たい場合、ブロック時間をコンテキストスイッチ単位で追いたい場合は、ETWベースのPerfViewが必要です。収集した.nettraceファイルをPerfViewで開いて分析する、という併用も日常的に行います。

Visual Studioのプロファイラーとの関係はどうなりますか？

開発機で再現できる問題なら、Visual StudioのCPU使用率ツールやメモリツールのほうが手軽で、まずそちらで十分です。PerfViewやdotnet-traceが効くのは、Visual Studioを入れられない検証機・本番機で収集する場面、収集と分析を別マシンで分けたい場面、ETWのイベント(独自EventSourceやカーネルイベント)まで含めて見たい場面です。なお、Visual Studioはdotnet-traceが出力する.nettraceファイルを開くこともできます。

本番サーバーで実行しても大丈夫ですか？

どちらのツールも本番での短時間収集を想定して作られていますが、無条件ではありません。収集時間を数十秒〜数分に区切る、まず検証環境で同じコマンドを試してオーバーヘッドとファイルサイズを確認する、ディスク空き容量を確認する、という手順を踏んでください。特にThreadTime(コンテキストスイッチ)収集や割り当てトレースはイベント量が多く、ファイルが急速に大きくなります。また、トレースにはコマンドライン引数などの情報が含まれるため、取得ファイルの扱いにも注意が必要です。

WPR/WPAとはどう使い分けますか？

WPR(Windows Performance Recorder)とWPA(Windows Performance Analyzer)は、同じETWを土台にした、よりOS寄りの調査ツールです。ディスクI/O・電源・起動時間などOS全体の詳細分析ではWPR/WPAが強く、.NETアプリのCPU・GC・ブロック時間の調査ではマネージドコードの表示に最適化されたPerfViewのほうが読みやすいです。業務アプリの調査が目的なら、PerfViewとdotnet-traceで大半は足ります。

著者プロフィール

記事の著者プロフィールページです。

小村 豪

合同会社小村ソフト 代表

Windows ソフト開発、技術相談、不具合調査を中心に、既存資産が残る案件や原因が見えにくい障害調査に強みがあります。