プロファイリングと監視、パフォーマンス最適化

この記事は英語の原文を日本語に翻訳したものです。原文: https://blog.stenmans.org/theBeamBook/#CH-Profiling

翻訳元: happi/theBeamBook 7998e22e78417dbe20e5136b9aee862a1ecaa404（コミット 7998e22）

“Make it work, then make it beautiful, then if you really, really have to, make it fast. 90% of the time, if you make it beautiful, it will already be fast.”
（まず動くようにし、次に美しくする。それでもどうしても必要なときにかぎり速くすればいい。たいていの場合、美しくした時点で90%はすでに十分速くなっている。）
― Joe Armstrong

パフォーマンス最適化は、堅牢でスケーラブルなシステムを構築するうえで欠かせない要素です。背後にある実行モデルとメモリ管理の戦略を理解することは、ボトルネックを特定しシステムのパフォーマンスを改善するために必須です。本章では、高性能なErlang・Elixirアプリケーションを構築するためのプロファイリングツール、監視の手法、最適化戦略を取り上げます。

BEAMパフォーマンスの基礎

ここまで本書で扱ってきた主要な概念を、手短におさらいします。

BEAMのパフォーマンスは、高い並行性と耐障害性を持つシステム向けに設計された実行モデルと本質的に結びついています。 BEAM仮想マシンは、各Erlangプロセスが自身の独立したヒープを持ち、それぞれ独立に動作するプロセス指向のモデルで動作します。この設計はプロセス間の競合を最小化しますが、特にメモリ使用量とメッセージパッシングの面で一定のパフォーマンス上のトレードオフを生みます。

BEAMにおける実行は、プロセスが行う作業の単位を表すリダクションを軸に構成されています。各プロセスには一定数のリダクションが割り当てられ、それを使い切ると別のプロセスに実行権を譲るようプリエンプトされ、実行中のすべてのエンティティに公平なスケジューリングが保たれます。スケジューラ自体はマルチコアでの効率を考慮して設計されており、通常はCPUコアごとに1つのスケジューラが動作します。スケジューラ間の負荷分散は動的に処理され、ワークスティーリング戦略が稼働率の均等化を助けます。タイミングホイールがスケジュールされた操作を管理し、過剰なCPUオーバーヘッドをかけずにタイムアウトや遅延メッセージを効率よく処理します。

BEAMにおけるプロセス間通信は、非同期のメッセージパッシングモデルに従います。プロセスはメモリを共有しないため、共有バイナリのような特定の最適化が適用されない限り、メッセージは送信元プロセスのヒープから受信先プロセスのヒープへとコピーされます。これは、高頻度のメッセージングが発生する場面では非効率につながることがあります。外部システムへのインターフェースとして機能するポートは、スケジューラをブロックしないよう非同期の通信機構に依存しています。これは、BEAMランタイムの外にあるI/Oバウンドな処理や計算負荷の高い処理と連携する際に、特に重要になります。

BEAMのメモリ管理は、プロセスごとのプライベートヒープを中心に構築されています。このアプローチはロックを最小限に抑えますが、その分ガベージコレクションの戦略には注意が必要です。プロセスごとに世代別ガベージコレクタが動作し、短命なデータを効率よく回収する一方で、長命なデータは保持し続けます。大きなバイナリは不要な重複を避けるため共有ヒープで別途管理されますが、扱いを誤るとメモリの断片化を招きます。 ETS（Erlang Term Storage）テーブルはデータを共有するための代替手段ですが、ETSに対する操作はタームのコピーを伴うため、高スループットなアプリケーションではオーバーヘッドの原因になり得ます。

BEAMのデータ構造はイミュータブルな設計に従っており、タプルやマップの更新はインプレースの変更ではなくコピーという形で行われます。このコピーオンアップデートの振る舞いは安全性を保証しますが、大きな構造体を頻繁に変更する場合はコストがかさみます。 BEAMのパフォーマンスを最適化するには、不要なコピーを最小限に抑えるようデータを構造化し、アクセスパターンに応じた適切な格納方式を活用することが求められます。

プロファイリングツール

BEAMには、時間、ひいてはパフォーマンス上の問題がどこに潜んでいるかを調べるための、組み込みのプロファイラが一式揃っています。プロファイリングにはredbugやreconのような外部ツールも使えます。それぞれのツールには固有の強みとトレードオフがあります。

`fprof`

fprofは、コードを計装してタイミング情報付きの詳細なコールグラフを取得する、トレースベースのプロファイラです。すべての関数呼び出しを収集し、別途行う後処理のステップで、その巨大なトレースを人間が読める形式のレポートへと変換します。どの関数が遅いかだけでなく、それらがどのようにネストしているかまで理解したいなら、fprofが全容を教えてくれます。欠点はオーバーヘッドが大きいことです。本番システムよりも、隔離されたテスト環境で使うのに向いています。

`eprof`

eprofは、すべての呼び出しを収集するのではなく、実行時間の計測に重点を置きます。稼働中のシステムをサンプリングすることで、各関数の実行にどれだけ時間がかかっているかを集計した形で把握できます。 eprofは詳細さとオーバーヘッドのバランスが良く、fprofのような大量のデータに埋もれることなく、コード中のホットスポットをレポートに浮かび上がらせます。これにより、手早くパフォーマンスの傾向を掴みたい場合に適しています。

`cprof`

cprofは、時間の経過に伴う関数呼び出しをサンプリングする統計的なアプローチを取ります。完全なコールグラフを生成する代わりに、cprofはデータを集計してアプリケーション内の「ホットスポット」を特定します。実行経路の一つひとつを教えてくれるわけではありませんが、処理時間の大半がどこで消費されているかを俯瞰するには優れています。

`tprof`

tprof（トレースプロファイラと見なされることが多い）は、Erlang組み込みのトレース機能を活用します。トレースフラグを設定することで、完全な計装よりも侵襲性の低い形でパフォーマンスデータを収集します。得られたレポートは後処理によって、タイミングと呼び出し関係の両方を明らかにできます。このツールは、長時間稼働するプロセスや稼働中のプロセスをプロファイリングする必要がある場合に特に有用ですが、セットアップはやや高度です。

ReconとRedbug

ReconとRedbugは、実行時の診断において強力なコミュニティ主導のライブラリです。どちらも実運用での利用を想定して設計されており、オンデマンドのトラブルシューティングのために本番システムに組み込めるほど軽量です。

Observer

Observerは、Erlang/OTPに同梱されているグラフィカルユーザーインターフェースで、システム全体をリアルタイムに俯瞰できます。プロセスの階層やメッセージキュー、パフォーマンスメトリクスを直感的な形で可視化します。 Observerについては、「プロセスの調査にObserverを使う」で簡単に紹介しました。

多少のオーバーヘッドが伴うため継続的な本番プロファイリングには通常使われませんが、Observerは対話的なデバッグや、アプリケーションの全体的なアーキテクチャを把握するうえで非常に役立ちます。個々のプロセスまで掘り下げられる点は、各プロファイラが提供するより粒度の細かい知見を補完します。

プロファイリングのシナリオ

Erlangアプリケーションが目に見えて遅くなっている場面を想像してみます。どこかのモジュールが原因だと疑っているとします。この例では、リストを処理する関数が再帰関数を呼び出すモジュールを用意し、どこに時間が費やされているかを突き止めます。単純な再帰の階乗関数だけを使うごく簡単なシナリオですが、各プロファイラをパフォーマンス問題の診断にどう使えるかを理解する助けになります。

-module(perf_example).
-export([compute/1, eprof/0, tprof_example/1]).

compute([]) ->
    ok;
compute([H|T]) ->
    _F = factorial(H),
    compute(T).

factorial(0) -> 1;
factorial(N) when N > 0 ->
    N * factorial(N - 1).


eprof() ->
    Compute = fun() -> perf_example:compute([10,15,20,25,30]) end,
    eprof:profile(Compute),
    eprof:analyze().

tprof_example(Type) ->
    Compute = fun() -> perf_example:compute([10,15,20,25,30]) end,
    tprof:profile(Compute, #{type => Type}).

本番環境で、中程度の長さのリストを処理するとシステムが遅延することに気づいたとします。 factorial/1への繰り返しの再帰呼び出しが、リダクションを消費しすぎてCPU競合を引き起こしているのではないかと疑っています。

以下に、それぞれのツールがどのように役立つか、使用例と結果の見本とともに示します。

`fprof`の例

fprofを使えば、すべての関数呼び出しをトレースし、タイミングの詳細を含む完全なコールグラフを構築できます。これにより呼び出しのネストと実行時間の全体像がわかりますが、その分オーバーヘッドは大きくなります。

Erlangシェルで次を実行します。

1> fprof:apply(fun perf_example:compute/1, [[10, 15, 20, 25, 30]]).
ok
2> fprof:profile().
Reading trace data...

End of trace!
ok
3> fprof:analyse().
Processing data...
Creating output...
%% Analysis results:
{  analysis_options,
 [{callers, true},
  {sort, acc},
  {totals, false},
  {details, true}]}.

%                                               CNT       ACC       OWN
[{ totals,                                      113,    0.259,    0.259}].  %%%


%                                               CNT       ACC       OWN
[{ "<0.105.0>",                                 113,undefined,    0.259}].   %%

{[{undefined,                                     0,    0.259,    0.017}],
 { {fprof,apply_start_stop,4},                    0,    0.259,    0.017},     %
 [{{perf_example,compute,1},                      1,    0.242,    0.005},
  {suspend,                                       1,    0.000,    0.000}]}.

{[{{fprof,apply_start_stop,4},                    1,    0.242,    0.005},
  {{perf_example,compute,1},                      5,    0.000,    0.009}],
 { {perf_example,compute,1},                      6,    0.242,    0.014},     %
 [{{perf_example,factorial,1},                    5,    0.228,    0.057},
  {{perf_example,compute,1},                      5,    0.000,    0.009}]}.

{[{{perf_example,compute,1},                      5,    0.228,    0.057},
  {{perf_example,factorial,1},                  100,    0.000,    0.163}],
 { {perf_example,factorial,1},                  105,    0.228,    0.220},     %
 [{garbage_collect,                               1,    0.008,    0.008},
  {{perf_example,factorial,1},                  100,    0.000,    0.163}]}.

{[{{perf_example,factorial,1},                    1,    0.008,    0.008}],
 { garbage_collect,                               1,    0.008,    0.008},     %
 [ ]}.

{[ ],
 { undefined,                                     0,    0.000,    0.000},     %
 [{{fprof,apply_start_stop,4},                    0,    0.259,    0.017}]}.

{[{{fprof,apply_start_stop,4},                    1,    0.000,    0.000}],
 { suspend,                                       1,    0.000,    0.000},     %
 [ ]}.


Done!
ok

この分析結果からは、今回のプロファイリングシナリオで実行時間がどこに費やされているかを詳しく読み取れます。ここからわかることは次のとおりです。

トータルの行から、113回の関数呼び出しにわたって約0.259秒の実時間が費やされたことがわかります。この時間には、各関数自体の「own」時間と、そこからネストして呼び出された関数すべての累積時間の両方が含まれます。

レポートの重要な部分は、再帰関数の呼び出しをグループ化して示しています。分析結果は、呼び出し階層を表すグループにデータを分割していることに注目してください。例えば、あるグループでは、perf_example:compute/1関数がperf_example:factorial/1を繰り返し呼び出している様子がわかります。具体的には、factorial/1が105回呼び出され、累積時間は約0.228秒、そのうち関数自体の「own」時間は0.220秒だったとレポートは示しています。

このことから、処理時間の大部分はfactorial/1に費やされており、その繰り返しの再帰呼び出しがパフォーマンスのボトルネックであるという予想が裏付けられます。ガベージコレクションに費やされた時間はわずか(約0.008秒)であり、重い計算がメモリ管理ではなく再帰呼び出しの側にあることを裏付けています。

最後に、fprof:apply_start_stop/4のような関数やsuspend呼び出しへの言及からは、プロファイラがコードの実行をどのようにラップしていたかがわかります。これらの詳細を総合すると、明確なコールグラフが見えてきます。 compute/1で費やされた時間の大部分はfactorial/1への呼び出しによって消費されており、そしてそのfactorial/1こそが総処理時間の大半を占めているということです。

`eprof`の例

再び、再帰関数、つまり素朴な階乗計算がCPU時間の大半を消費していると疑われる、あの遅いアプリケーションを考えます。 eprofを使えば、Erlangのトレース用BIFを利用して、各関数の実行にかかった時間を集計した形で把握できます。 eprofはfprofのような完全なコールグラフは提供しませんが、関数ごとの所要時間を簡潔にまとめて示してくれます。

以下は、再帰呼び出しをプロファイリングするためにeprofを使うモジュールの例です。

2> perf_example:eprof().

****** Process <0.108.0>    -- 100.00 % of profiled time ***
FUNCTION                          CALLS        %  TIME  [uS / CALLS]
--------                          -----  -------  ----  [----------]
perf_example:compute/1                6     0.00     0  [      0.00]
perf_example:'-eprof/0-fun-0-'/0      1     0.00     0  [      0.00]
erlang:apply/2                        1    11.76     2  [      2.00]
perf_example:factorial/1            105    88.24    15  [      0.14]
--------------------------------  -----  -------  ----  [----------]
Total:                              113  100.00%    17  [      0.15]
ok
3>

このレポートは、合計113回の関数呼び出しで17マイクロ秒、1回あたり平均約0.15マイクロ秒が消費されたことを示しています。

perf_example:compute/1は6回呼び出され、所要時間は実質0マイクロ秒でした。再帰処理のコストと比べれば無視できる水準です。
eprof/0が生成する無名関数は1回実行され、目立ったコストはありませんでした。
erlang:apply/2は1回登場し、合計時間の約11.76%（およそ2マイクロ秒）を占めています。これは、プロファイリングの仕組みの中で関数呼び出しを適用すること自体のオーバーヘッドを反映しています。
作業の大半はperf_example:factorial/1が担っており、105回呼び出されています。合計時間の88.24%、およそ15マイクロ秒、1回あたり約0.14マイクロ秒を消費しています。

ここからの教訓は次のとおりです。 factorial/1への各呼び出し自体は極めて高速ですが、呼び出し回数の多さがあいまって、全体の実行時間に対する最大の寄与要因になっています。これは、factorial/1内の再帰処理が今回のプロファイリングシナリオを支配する要因であるという予想を裏付けています。

`cprof`の例

cprofはブレークポイントを使って呼び出し回数を数える、軽量なアプローチを取ります。再コンパイルもトレースメッセージも必要ありません。その代わり、完全なコールグラフは得られず、タイミング情報も得られません。

2> f(), cprof:start(perf_example), Result = perf_example:compute([10,15,20,25,70]), PauseCount = cprof:pause().
14269
3> Analysis = cprof:analyse().
{151,
 [{perf_example,151,
                [{{perf_example,factorial,1},145},
                 {{perf_example,compute,1},6}]}]}

この分析結果は、perf_exampleモジュールで合計151回の呼び出しがあったことを示しており、そのうち2つの関数が記録されています。

perf_example:compute/1は6回呼び出されました。
perf_example:factorial/1は145回呼び出されました。

リストを処理するcompute/1関数が6回呼び出されているのは、5要素のリストを処理する場合と一致します（各再帰ステップで1回ずつ、それに基底ケースを加えた6回)。一方、重い処理を担っているのは145回呼び出されたfactorial/1です。これは、作業の大半がfactorial/1の再帰呼び出しで発生していることを裏付けています。

このデータは、再帰的な階乗計算関数がホットスポットであることをはっきりと示しています。 factorial/1への個々の呼び出しは極めて高速ですが、その呼び出し頻度の高さ(145回)から、より大きなワークロードでボトルネックになった場合には、この関数の最適化がパフォーマンス向上につながる可能性があります。

`tprof`の例

tprofは、OTP 27で導入された実験的な統合プロセスプロファイリングツールです。呼び出し回数、実行時間、ヒープ割り当て(call_memory)の計測に対応しています。このシナリオでは、tprofをアドホックモードでそれぞれの種類で使い、実行中に各関数が何回呼び出され、どれだけの時間がかかり、どれだけのメモリ(ワード単位)が割り当てられたかを見ていきます。

3> perf_example:tprof_example(call_count).
FUNCTION                                  CALLS  [    %]
perf_example:'-tprof_example/1-fun-0-'/0      1  [ 0.89]
perf_example:compute/1                        6  [ 5.36]
perf_example:factorial/1                    105  [93.75]
                                                 [100.0]
ok
4> perf_example:tprof_example(call_time).

****** Process <0.129.0>  --  100.00% of total ***
FUNCTION                                  CALLS  TIME (us)  PER CALL  [    %]
perf_example:compute/1                        6          1      0.17  [ 5.00]
perf_example:'-tprof_example/1-fun-0-'/0      1          2      2.00  [10.00]
perf_example:factorial/1                    105         17      0.16  [85.00]
                                                        20            [100.0]
ok
5> perf_example:tprof_example(call_memory).

****** Process <0.132.0>  --  100.00% of total ***
FUNCTION                  CALLS  WORDS  PER CALL  [     %]
perf_example:factorial/1    105     51      0.49  [100.00]
                                    51            [ 100.0]
ok

call_countのプロファイルからは、無名のラッパー関数が1回(0.89%)、compute/1が6回(5.36%)呼び出され、重い作業は105回(93.75%)呼び出されたfactorial/1が担っていることがわかります。これは、呼び出しの(したがって作業量の)大半が再帰的なfactorial/1で発生しているという予想を裏付けています。

call_timeの出力からは、compute/1が6回の呼び出しで合計1マイクロ秒(1回あたり約0.17µs)、無名関数が2µs、factorial/1が105回の呼び出しで17µs(1回あたり約0.16µs)を要したことがわかります。 1回あたりの時間は非常に小さいものの、累積時間で見るとfactorial/1が実行時間の大半(85%)を占めており、この関数が計算の主な担い手であることが改めて裏付けられます。

call_memoryのプロファイルは、計測されたヒープ割り当て(合計51ワード)のすべてが、105回呼び出されたfactorial/1で発生していることを示しています。 1回あたりに換算すると、約0.49ワードが割り当てられている計算になります。 compute/1や無名のラッパー関数にはメモリ割り当てが一切帰属していないため、このワークロードにおけるメモリのオーバーヘッドはすべて再帰関数によるものだと確認できます。

プロファイリングと監視、パフォーマンス最適化

BEAMパフォーマンスの基礎

プロファイリングツール

fprof

eprof

cprof

tprof