次の方法で共有

.NET パフォーマンス

  • [アーティクル]

ETW を使用した .NET アプリケーションのパフォーマンス診断

Subramanian Ramaswamy

コード サンプルのダウンロード

マネージ アプリケーションを作成して、軽く実行してみたところ、動作が遅かったとします。このアプリケーションは機能的には問題ないのですが、パフォーマンスには大いに不満があります。パフォーマンスの問題を診断して解決したいのですが、アプリケーションは運用環境で実行されているため、プロファイラーをインストールすることも、アプリケーションを中断することもできません。また、CPU プロファイリングを行うために Visual Studio Profiler を購入するほど、アプリケーションが広範には使用されていません。

さいわい、このような問題には Event Tracing for Windows (ETW) を利用できます。ETW は強力なログ テクノロジで、Windows インフラストラクチャのさまざまなコンポーネントに組み込まれています。また、Microsoft .NET Framework 4 CLR では、ETW のおかけで、かつてないほど簡単にマネージ アプリケーションをプロファイリングできるようになっています。ETW では、システム全体からデータが収集され、すべてのリソース (CPU、ディスク、ネットワーク、メモリ) のプロファイリングが行われるため、全体像を把握するうえで非常に便利です。さらに、ETW エコシステムは、オーバーヘッドが低くなるようにチューニングできるため、運用環境の診断にも適しています。

今回の記事の目標は、ETW を使用してマネージ アプリケーションのプロファイリングを行うことがいかに有用であるかをお伝えすることです。ただし、ここですべてをご紹介するわけではなく、診断に利用できるいくつかの OS イベントと CLR ETW イベントについては割愛させていただきます。しかし、ETW エコシステムを使用して、マネージ アプリケーションのパフォーマンスと機能性がどのようにして劇的に向上するかについてご理解いただけるでしょう。読者がマネージ コードの ETW ベースの診断を始められるように、ここでは無償で提供されている ETW ツールの PerfMonitor (bcl.codeplex.com/releases/view/49601 からダウンロード) を使用した診断の例についてもご紹介します。

PerfMonitor

PerfMonitor を使用すると、すばやく簡単に ETW パフォーマンス データを収集して、有用なレポートを生成できます。PerfMonitor は、Visual Studio Profiler などの高度な分析ツールに代わるものではなく、アプリケーションのパフォーマンス上の特徴について概要を把握し、簡単な分析を実行できるようにします。

ETW の診断に使用できる XPerf という別のツールもあります。XPerf は Windows Performance Toolkit により無償で提供されています。ただし、XPerf は Windows のネイティブ コードのプロファイリングには威力を発揮しますが、マネージ コードのプロファイリング サポートは強くありません。一方、PerfMonitor では、ETW を使用したマネージ コードのプロファイリングのスコープも威力も引き出せます。PerfMonitor は、XPerf で実行できる詳細な分析はサポートしていませんが、.NET Framework ランタイム コードに関連付けられているシンボル情報を収集できるため、.NET Framework のパフォーマンスの調査にとても便利です。

PerfMonitor は完全に自己完結型のツールで、このツールさえあれば、マネージ アプリケーションのプロファイリングと診断を開始できます。その他の唯一の要件は、Windows Vista または Windows Server 2008 以上を実行していることです。PerfMonitor はコマンドライン ツールで、保存先のディレクトリから「PerfMonitor.exe usersGuide」と入力すると、概要が表示されます。たとえば運用サーバー上など、運用状態で診断するプログラムが客先にある場合、ファイルをそのコンピューターにコピーするだけで、いつでもプロファイルの収集を開始できます。収集したプロファイルは、必要に応じてオフラインで分析できます。

パフォーマンスの調査では、一般に、CPU、ディスク I/O、メモリ、スケーラビリティの 4 要素が検査されます。ほとんどの調査は、アプリケーションの起動と実行時間の両方に影響する CPU から始めます。ディスク I/O の検査は、起動時間がかかる場合の診断に最も有用です (ディスク I/O はコールド起動にかかる時間を決める主な要素です。これは、再起動後など、アプリケーションがメモリ内にない状態で起動する際にかかる時間です)。一方、過剰なメモリ使用 (リーク) は、アプリケーションの動作が時間の経過と共に遅くなる原因となり得ます。スケーラビリティは、プロセッサ数と比例してアプリケーションのスループットの向上を期待する場合に関係します。

PerfMonitor を使用すると、スケーラビリティ以外のすべての要素についてスナップショットをすばやく記録できます。また、他の専用ツールを使用して、さらに細かい分析を実行できるだけの情報も得られます。たとえば、CLR .NET ガーベージ コレクション (GC) ヒープの問題を診断する場合は、CLRProfiler が適しています。ただし、PerfMonitor では、問題があるかどうかと、他のツールを使用してさらに詳しい調査が必要かどうかをすばやく調べることができます。場合によっては、PerfMonitor だけで、問題を特定し、パフォーマンス バグの対応に必要なすべての情報が得られることがあります (これについては、すぐに説明します)。CLR 徹底解剖コラムの「.NET アプリケーションのメモリ使用量の監査」(msdn.microsoft.com/magazine/dd882521) を参照してください。このコラムでは、プログラムのメモリ使用量を監査し、パフォーマンスの計画を立てることの重要性が述べられています。その考え方を推し進め、PerfMonitor ではメモリだけでなく、マネージ プログラムのさまざまなパフォーマンス関連の項目をすばやく監査できます。

調査例: CsvToXml

ETW を使用してこれから診断するサンプル プログラムは、CSV ファイルを XML ファイルに変換するプログラムです。ソース コードとソリューション パッケージ (およびサンプルの入力用 CSV ファイル data.csv) は、code.msdn.microsoft.com/mag201012ETW からダウンロードできます。このプログラムを実行するには、「CsvToXml.exe data.csv output.xml」というコマンドを実行します。

多くのプログラムと同様、CsvToXml は短時間で作成したもので、開発者はこのプログラムがサイズの大きな CSV ファイルに使用されるとは考えていませんでした。実際に使用し始めると、処理が非常に遅いことがわかりました。750 KB のファイルの処理に 15 秒以上もかかります。問題があるのはわかっていますが、プロファイリング ツールなしでは、処理が遅い原因について推測するしかありません (皆さんはソースを見ただけで原因を特定できるでしょうか)。さいわい、原因の解明に PerfMonitor を利用できます。

プログラム トレースの生成と表示

まず、管理者特権で開いたコマンド プロンプト ウィンドウで次のコマンドを実行して、アプリケーションを簡単に監査します (ETW では、コンピューター全体からデータが収集されるため、管理者特権が必要です)。

PerfMonitor runAnalyze CsvToXml.exe data.csv out.xml

このコマンドを実行すると、ETW によるログ記録が開始され、CsvToXml.exe が実行され、
CsvToXml の処理が完了するのを待って、ログ記録を終了し、最後に CsvToXml の分析結果を示す Web ページが表示されます。簡単な 1 作業だけで、CsvToXml のパフォーマンス ボトルネックの解明に役立つデータが豊富に得られます。

このコマンドの結果は図 1 のようになります。結果ページに表示されるデータには、プロセス ID、使用されたコマンド ライン、CPU の統計情報、GC の統計情報、ジャストインタイム (JIT) の統計情報などの高度なパフォーマンス データの詳細があります。PerfMonitor では、参考記事や他のツールへの役に立つリンクと併せて、診断を開始するポイントについての第一段階の分析結果も提示されます。

Figure 1 Performance Analysis for CsvToXml

図 1 CsvToXml のパフォーマンス分析

結果レポートによると、ファイル形式の変換に 14 秒近くかかっています。そのうち 13.6 秒が CPU の処理に使われ、平均して 99% の使用率を示しています。したがって、原因解明のシナリオは CPU に絞られます。

GC の合計時間と GC の一時停止時間の値は小さく、これらは問題ありません。ただし、最大 GC 割り当て率は105.1 MB/sec で、これは高すぎます。これについてはさらに調査を進めるに値します。

CPU 分析

CPU の詳細分析 (Detailed CPU Analysis) では、図 2 のように CPU 時間の内訳が示されます。CPU プロファイル データを確認する方法には次の 3 種類があります。1 つはボトムアップ形式のビューで、CPU の使用時間が最も長いメソッドがわかります。このビューを最初に診断してください。トップダウン形式のビューは、コードのアーキテクチャまたは構造を変更する必要があるかどうかを判断する場合に有効で、プログラムの全体的パフォーマンスを把握できます。呼び出し元と呼び出し先のビューでは、どのメソッドがどのメソッドを呼び出しているかなど、メソッド間の関係がわかります。

Figure 2 Bottom-Up Analysis of CsvToXml.exe

図 2 CsvToXml.exe のボトムアップ分析

他の CPU プロファイラーと同様、PerfMonitor の表示では、包括時間 (特定のメソッドで使用された時間で、メソッドの呼び出し先で使用された時間も含みます) と排他時間 (特定のメソッドで使用された時間で、呼び出し先の時間は含みません) が示されます。包括時間と排他時間が同じであれば、処理はその特定のメソッド内でのみ行われています。PerfMonitor では、特定のメソッドについて、CPU の使用率の詳細を経時的に示す CPU 使用率のグラフも得られます。レポート内の列見出しをマウスでポイントすると、その列についての詳しい説明が表示されます。

ほとんどのパフォーマンス調査では、排他時間順にメソッドを一覧表示するボトムアップ形式の表示が最初に示されます (図 2 参照)。ボトムアップ ビューを選択すると、mscorlib メソッドの System.IO.File.OpenText が、CPU をほとんど使用しているメソッドであることがわかります。そのリンクをクリックすると、OpenText メソッドの呼び出し元と呼び出し先のビューが表示されます。このビューによると、CsvToXml.CsvFile.get_ColumnNames メソッドが、プログラムから OpenText を呼び出しています。そして、get_ColumnNames は、ほぼ 10 秒 CPU 時間を使用しています (図 3 参照)。さらに、このメソッドは、ループ内で CsvToXml.CsvFile.XmlElementForRow から呼び出されています (XmlElementForRow 自体は Main メソッドから呼び出されています)。

Figure 3 Caller-Callee View for get_ColumnNames

図 3 get_ColumnNames の呼び出し元と呼び出し先のビュー

したがって、これらのメソッドに何か不具合があるようです。これらのメソッドのコードを確認すると、図 4 のような問題が見つかりました。ループ内でファイルを開いては解析するという作業が繰り返されているのです。

図 4 XmlElementForRow メソッドに呼び出される ColumnNames メソッド

public string[] ColumnNames
{
  get
  {
    using (var reader = File.OpenText(Filename))
      return Parse(reader.ReadLine());
  }
}

public string XmlElementForRow(string elementName, string[] row)
{
  string ret = "<" + elementName;
  for (int i = 0; i < row.Length; i++)
    ret += " " + ToValidXmlName(ColumnNames[i]) + "=\"" + EscapeXml(row[i]) + "\"";
  ret += "/>";
  return ret;
}

同様のシナリオは、皆さんが考えるよりも頻繁に起こっています。メソッドが最初に作成された時点では、(ColumnNames の場合と同様に) 開発者はそのメソッドはごくまれにしか呼び出されないと思っている可能性があります。そのために、メソッドのパフォーマンスにはあまり注意が払われていない可能性があります。しかし、後々ループ内でメソッドが呼び出されるような状況が発生すると、アプリケーションのパフォーマンスが影響を受けます。

CSV ファイルでは、すべての行が同じフォーマットであるため、この処理を毎回実行する意味はありません。ColumnNames の機能をコンストラクターに組み入れて (図 5 参照)、プロパティからキャッシュした列名を渡すようにします。これにより、確実にファイルが 1 回だけ読み取られるようになります。

図 5 列名をキャッシュしてパフォーマンスを改善

public CsvFile(string csvFileName)
{
  Filename = csvFileName;

    using (var reader = File.OpenText(Filename))
      ColumnNames = Parse(reader.ReadLine());
        
}

public string Filename { get; private set; }

public string[] ColumnNames { get; private set;}

リビルドして、前述のコマンドを再び実行すると、アプリケーションの動作はかなり早くなり、実行時間はわずか 2.5 秒になりました。

それでも、修正後のプログラムについてのデータを確認すると、CPU 時間の占める割合がまだ高いままです。再び CPU 時間の詳細を参照して、ボトムアップ分析を確認してみると、今度は Regex.Replace が最も CPU を使用しているメソッドであり、これは EscapeXml and ToValidXmlName から呼び出されていることがわかります。EscapeXml が CPU 使用率の高いメソッドであるため (排他時間が 330 ミリ秒)、そのソース コードを調べてみましょう。

private static string EscapeXml(string str)
{
  str = Regex.Replace(str, "\"", "&quote;");
  str = Regex.Replace(str, "<", "&lt;");
  str = Regex.Replace(str, ">", "&gt;");
  str = Regex.Replace(str, "&", "&amp;");
  return str;
}

EscapeXml はループ内で XmlElementForRow からも呼び出されているため、ボトルネックになる可能性があります。正規表現をこれらの代わりに使用するのはやや行き過ぎなので、文字列を処理する Replace メソッドの方が効率が良いでしょう。そこで EscapeXml を次のコードで置き換えます。

private static string EscapeXml(string str)
{
  str = str.Replace("\"", "&quote;");
  str = str.Replace("<", "&lt;");
  str = str.Replace(">", "&gt;");
  str = str.Replace("&", "&amp;");
  return str;
}

この変更によって、CPU 時間は他よりも高いままですが、全体の時間は約 2 秒に短縮されました。これは許容できるパフォーマンスです。実行時間が約 1/7 に改善されました。

読者の演習用に、サンプル プログラムには、ETW イベントを使用して特定できるパフォーマンスのバグをさらにいくつか残してあります。

GC の統計情報を調査する

PerfMonitor による GC 統計情報からは、メモリ プロファイルの概要をすばやく把握できます。ご記憶にあるかと思いますが、メモリ使用率の監査を行うことを強くお勧めします。GC ETW イベントによって得られる情報からは、.NET GC ヒープの問題をすばやく確認できます。この GC 統計の概要ビューからは、GC ヒープの総サイズ、割り当て率、および GC 一時停止時間がわかります。[PerfMonitor results] (PerfMonitor の結果) タブの [GC Time Analysis] (GC 時間の分析) リンクを選択すると、GC が行われている場合は、GC での使用時間など、GC の詳細が表示されます。

この情報から、CLRProfiler や他のメモリ プロファイラーを使用して、メモリの問題をさらに調査する必要があるかどうかを判断できます。「.NET ガベージ コレクション ヒープをプロファイリングする」(msdn.microsoft.com/magazine/ee309515) では、CLRProfiler を使用した .NET GC ヒープのデバッグについて詳しく説明されています。

このサンプル プログラムについては、気になる GC 統計情報はないように見えます。割り当て率は高く、割り当て率は 10 MB/秒より低くなることが目安です。ただし、一時停止時間は非常に短くなっています。割り当て率が高いのは CPU 時間であり、これは基本的に CPU 処理が高くなっていることを示します (実際、これについては先ほど確認しました)。ただし、修正後でも、割り当て率は高いままです。これは、割り当てが多数発生していることを意味します (皆さんはこれを修正できますか)。GC の一時停止時間は数ミリ秒で、.NET Framework ランタイムによる自己調整と効率のよい GC が機能している証拠です。つまり、.NET Framework GC によって、自動的にメモリ管理が処理されています。

JIT 統計情報を調査する

起動時間を改善するために、最初に確認すべき項目の 1 つは、メソッドの JIT コンパイルに必要な時間です。かなりの時間がかかっている場合 (たとえば、アプリケーションの起動にかかった時間のほとんどが JIT コンパイルによるものである場合)、アプリケーションのパフォーマンスは、ネイティブ イメージの生成 (NGen) によって改善される可能性があります。NGen を利用すると、アセンブリが事前にコンパイルされてディスクに保存されるため、JIT コンパイル時間を省略できます。つまり、アセンブリは、JIT コンパイルされてからディスクに保存されるため、それ以降の実行では JIT コンパイルが不要です。ただし、NGen を採用する前に、JIT コンパイルされるいくつかのメソッドをプログラムの後半に移動して、JIT コンパイル時間が起動時間に影響しないようにすることを検討してください。詳細については、「NGen によるパフォーマンス上の利点」(msdn.microsoft.com/magazine/cc163610、英語) を参照してください。

CsvToXml.exe サンプル アプリケーションでは、起動時の大きなコストにならないため、毎回すべてのメソッドを JIT コンパイルしても問題ありません。JIT コンパイルについての統計情報からは、JIT コンパイルされたメソッドが 17 あること (呼び出されたすべてのメソッドが JIT コンパイルされていることを示しています)、 および JIT コンパイルの合計時間が 23 ミリ秒であることもわかります。どちらの値も、このアプリケーションのパフォーマンスの問題にはなりませんが、規模の大きいアプリケーションでは、JIT コンパイル時間も影響要因となるため、NGen を使用することで、問題を取り除くことができます。通常、JIT コンパイル時間は、アプリケーションが数百または数千のメソッドの JIT コンパイルを開始するときに、影響要因になります。このような場合は、NGen が JIT コンパイルによるコストを排除するソリューションになります。

起動時間の改善についてその他のアドバイスが、他の MSDN マガジンの記事で紹介されています。ETW イベントは、ボトルネックの特定と修正に役立てることができます。また、メソッドがインライン展開されていない理由を探ることができる JIT インライン イベントなど、JIT イベントも他にいくつかあります。

.NET Framework 4 の CLR ETW イベント

CLR チームは、DLL の読み込み状態を突き止め、特定の DLL を起動時に読み込む必要があるかどうかを判断する方法についてのブログ記事を投稿しています。起動時に特定の DLL の読み込みが必要かどうかを決定する作業は、ETW イベントを使用することで容易になります。.NET Framework 4 が提供する ETW モジュール読み込みイベントを使用することで、どのモジュールがなぜ読み込まれるかを知ることができます。また、これらは、モジュールのアンロードなどについてのイベントでもあります。

.NET Framework 4 には、マネージ アプリケーションの診断をこれまでにないほど容易にするイベントが他にもいくつかあります。図 6 にこのようなイベントの概要を示します。実行中にトリガーされたイベントはすべて、PerfMonitor runPrint コマンドを使用してダンプできます。また、CLR チームでは、ETW プロファイルのアタッチとデタッチを可能にするイベントについても簡単に説明しています。CLR チームでは、将来のリリースで、マネージ アプリケーションのデバッグをさらに簡単に実行できるように、今後も ETW イベントの拡充を続けていく予定です。

図 6 .NET Framework 4 の ETW イベント

イベント カテゴリ名 説明
ランタイム情報 ETW イベント SKU、バージョン番号、アクティブ化の方法、起動時に使用されたコマンド ライン パラメーター、GUID (該当する場合) などのランタイムに関する情報をキャプチャします。
例外スロー ETW イベント スローされた例外に関する情報をキャプチャします。
競合 ETW イベント ランタイムが使用するモニター ロックまたはネイティブ ロックの競合に関する情報をキャプチャします。
スレッド プール ETW イベント ワーカー スレッド プールと I/O スレッド プールに関する情報をキャプチャします。
ローダー ETW イベント アプリケーション ドメイン、アセンブリ、およびモジュールのロードとアンロードに関する情報をキャプチャします。
メソッド ETW イベント シンボルを解決するための CLR メソッドに関する情報をキャプチャします。
GC ETW イベント ガベージ コレクション (GC) に関する情報をキャプチャします。
JIT トレース ETW イベント JIT のインライン展開と tail 呼び出しに関する情報をキャプチャします。
相互運用 ETW イベント MSIL (Microsoft Intermediate Language) のスタブの生成とキャッシュに関する情報をキャプチャします。
アプリケーション ドメインのリソース監視 (ARM) ETW イベント アプリケーション ドメインの状態に関する詳細な診断情報をキャプチャします。
セキュリティ ETW イベント 厳密名と Authenticode 検証に関する情報をキャプチャします。
スタック ETW イベント イベントの発生後にスタック トレースを生成するために他のイベントと共に使用される情報をキャプチャします。

実行ディレクトリに、PerfMonitorOutput というサフィックスが付いた 2 つのファイルがあります。これらが、ETW ログ ファイルです。また、kernel というサフィックスが付いたファイルもあり、これらには OS イベントが含まれることがわかります。PerfMonitor が収集するデータは、XPerf が使用するデータと同じであるため、PerfMonitor を使用してデータ収集と単純なレポート作成を簡単に実行でき、一方、同じデータのより詳細な分析には XPerf を使用できます。PerfMonitor のマージ コマンドを使用すると、ETW ファイルを XPerf で読み取れる形式に変換できます。

まとめ

ETW を使用したパフォーマンス調査は、シンプルでありながら、強力です。マネージ コードを効率よくデバッグできる、オーバーヘッドが小さい ETW ベースのさまざまな無料ツールが提供されています。ここでは、.NET Framework ランタイムが提供する ETW イベントをごく簡単に紹介しました。今回の記事の目的は、ETW イベントと ETW ツールを使用して、読者の皆さんがマネージ アプリケーションのデバッグにとりかかれるようにすることでした。PerfMonitor をダウンロードし、CLR の ETW イベントについての MSDN ドキュメントと、前述の CLR Perf についてのブログを参考にすれば、マネージ アプリケーションのパフォーマンス調査をすぐに開始できます。

このコラムの執筆をガイドし、協力してくれた CLR Performanceパフォーマンスのパートナー アーキテクトの Vance Morrison 氏に感謝します。

Subramanian Ramaswamy は、マイクロソフトで CLR パフォーマンスのプログラム マネージャーを務めています。彼は、ジョージア工科大学で電気およびコンピューター エンジニアリングの博士号を取得しています。