合同会社小村ソフト
日本語 English 한국어 繁體中文 العربية
相談する
メニュー

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

· · PerfView, dotnet-trace, ETW, パフォーマンス調査, .NET, CSharp, 不具合調査, Windows開発, 技術相談

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

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

1. まず結論

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

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

症状 最初に使う道具 見るもの
CPUが高いまま張り付く dotnet-trace collect / PerfViewのCPU Stacks exclusiveの大きい関数
CPUは低いのに処理が遅い・固まる PerfView(ThreadTime収集) どのスレッドが何を待ってブロックしたか
遅いが、まずは傾向だけ知りたい dotnet-counters CPU使用率、GC頻度、ThreadPoolキューの詰まり
GCが多すぎる疑い dotnet-counters → dotnet-trace(GCイベント) GC回数・停止時間、割り当ての多い場所
特定の業務処理のどこが遅いか知りたい EventSourceの独自イベント+上記 独自イベント間の経過時間とその区間のスタック

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

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

  • ETW(Event Tracing for Windows): OS全体を貫くトレース基盤。カーネルからアプリまで同じ時間軸で記録できる反面、セッションの開始・停止に管理者権限が必要で、Windows専用です。3
  • EventPipe: .NETランタイムに組み込まれたトレース機構。管理者権限が不要で全OSで同じように動く代わりに、見えるのはマネージドコードとランタイムの範囲に限られ、カーネルイベントやネイティブスタックは取れません。2
  dotnet-trace(EventPipe) PerfView(ETW)
管理者権限 不要(同一ユーザーのプロセスに対して) 必要
対象 指定した.NETプロセス1つ マシン全体(全プロセス+カーネル)
ネイティブスタック 取れない 取れる
ブロック時間(コンテキストスイッチ) 取れない ThreadTime収集で取れる
対応OS Windows / Linux / macOS Windowsのみ

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

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

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

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ベースの収集ツールです。5 インストールと基本の収集は次のとおりです。

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 の組み合わせが既定です。5 用途に応じて --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形式に変換してブラウザーで見ます。5

dotnet-trace convert trace.nettrace --format Speedscope

speedscope形式は speedscope.app で開ける軽量なフレームグラフ表示で、「どの関数の配下で時間を使ったか」を直感的に眺めるのに向いています。関数名まで特定した精査はPerfViewのスタックビューアーのほうが強力なので、次章に進みます。

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

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

5.1 収集する

GUIの「Collect > Collect」でダイアログを開き、Start Collection → 対象の操作を再現 → Stop Collection が基本の流れです。コマンドラインなら次の形になります(ETWセッションを開始するため、管理者として実行します3)。

PerfView collect /nogui /acceptEULA /maxCollectSec:30

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

5.2 CPU Stacksを読む

収集結果(.etl.zip)を開き、「CPU Stacks」で対象プロセスを選ぶと、スタックビューアーが開きます。最初に見るのは By Name タブの2つの列です。

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

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

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

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

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

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

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

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イベントが効いてきます。

  • アプリ側で 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業務アプリの性能問題の調査と、計測しやすくするための計装・設計の相談を扱っています。再現手順とトレースファイルがあれば、そこからの解析のみのご依頼も可能です。

関連記事

関連する相談領域

参考リンク

  1. GitHub, PerfView User’s Guide. 既定収集がプロセッサごとに1ミリ秒間隔のCPUサンプル(コールスタック付き)であること、判断には1,000〜5,000サンプル程度が望ましいこと、ThreadTimeオプションでコンテキストスイッチを収集しブロック時間まで分析できることについて(PerfView本体のHelpからも参照可能)。 ↩ ↩2 ↩3 ↩4 ↩5

  2. Microsoft Learn, EventPipe Overview. EventPipeが管理者権限のような高権限コンポーネントに依存せずに.NETアプリをトレースするための仕組みであること、対象がマネージドコードとランタイムに限られ、カーネルイベントやネイティブスタックは取得できないことについて。 ↩ ↩2

  3. Microsoft Learn, Collect and View EventSource Traces. ETWのトレース収集には常に管理者権限が必要であること、PerfViewやVisual Studioが.nettraceファイルを開けることについて。 ↩ ↩2 ↩3 ↩4

  4. Microsoft Learn, dotnet-counters diagnostic tool. System.Runtimeカウンターによる実行中プロセスのCPU・GC・ThreadPool等のメトリクス監視について。 ↩

  5. Microsoft Learn, dotnet-trace diagnostic tool. collectコマンドの使い方、既定で有効になるプロファイル(dotnet-common / dotnet-sampled-thread-time)とcpu-samplingプロファイルの廃止、gc-verbose / gc-collectなどのプロファイル、Speedscope / Chromium形式への変換について。 ↩ ↩2 ↩3

  6. GitHub, microsoft/perfview. PerfViewがCPU・メモリ関連の性能問題を調査するための無償の性能分析ツールであり、リリースページから実行ファイルを直接入手できることについて。 ↩

  7. GitHub, microsoft/perfview Issue #598. PerfViewメンテナーによる、既定収集時のオーバーヘッドがおおむね3%程度であるという説明、および/CpuSampleMSecでサンプリング間隔を調整して負荷を下げられることについて。 ↩

関連する記事

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

関連トピック

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

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

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

よくある質問

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

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

お問い合わせ
ブログ一覧に戻る