Erlang 付属プロファイラ fprof の出力結果の見方
手短なコツ
プロファイラ結果を上から見ていき、ACC が大きいものをたどっていく。
% がついたマーク付きの関数に注目して、calling, called 関数の ACC を見比べていき、時間を消費している関数を特定する。
Emacs なら M-C s で 関数名.*% あたりで追っていくと良い。
詳細
マニュアルの超訳（ねつ造、改悪、省略）。
以下のコードのプロファイリングを見ている場合。
-module(foo). -export([create_file_slow/2]). create_file_slow(Name, N) when integer(N), N >= 0 -> {ok, FD} = file:open(Name, [raw, write, delayed_write, binary]), if N > 256 -> ok = file:write(FD, lists:map(fun (X) -> <<X:32/unsigned>> end, lists:seq(0, 255))), ok = create_file_slow(FD, 256, N); true -> ok = create_file_slow(FD, 0, N) end, ok = file:close(FD). create_file_slow(FD, M, M) -> ok; create_file_slow(FD, M, N) -> ok = file:write(FD, <<M:32/unsigned>>), create_file_slow(FD, M+1, N).
1> fprof:apply(foo, create_file_slow, [junk, 1024]). 2> fprof:profile(). 3> fprof:analyse().
% CNT ACC OWN [{ totals, 9627, 1691.119, 1659.074}]. %%%
- CNT カラムは trace 中に関数が呼ばれた回数。
- ACC カラムは trace していた時間。
- 数値の単位は msec 。
- OWN カラムは trace 中に実行された、その関数の実行時間の和。
% CNT ACC OWN [{ "<0.28.0>", 9627,undefined, 1659.074}]. %%
プロセスのヘッダ。ACC カラムが undefined なのは、そのプロセスでの関数実行の総和を出す事に意味がないから。
{[{undefined, 0, 1691.076, 0.030}], { {fprof,apply_start_stop,4}, 0, 1691.076, 0.030}, % [{{foo,create_file_slow,2}, 1, 1691.046, 0.103}, {suspend, 1, 0.000, 0.000}]}. {[{{fprof,apply_start_stop,4}, 1, 1691.046, 0.103}], { {foo,create_file_slow,2}, 1, 1691.046, 0.103}, % [{{file,close,1}, 1, 1398.873, 0.019}, {{foo,create_file_slow,3}, 1, 249.678, 0.029}, {{file,open,2}, 1, 20.778, 0.055}, {{lists,map,2}, 1, 16.590, 0.043}, {{lists,seq,2}, 1, 4.708, 0.017}, {{file,write,2}, 1, 0.316, 0.021}]}.
プロセスヘッダ以降。呼ばれた関数毎に 1 パラグラフ出力される。上の例だと 2 パラグラフ。
% がついている行がプロファイラがターゲットの関数で、それより上がターゲット関数の呼ぶ側(calling)、下が呼ばれる側(called)。
パラグラフはデフォルトでは、ACC の大きい順にソートされている。1 パラグラフ中の caller/callee も同様に ACC が大きい順。
- CNT ： 該当関数が呼ばれた回数
- ACC ： 該当関数内で消費された時間。その関数が呼び出した関数の時間も含む。
- OWN ： 該当関数内で消費された時間。その関数が呼び出した関数の時間も含まない。
calling, called の関数の行は、ともにターゲットの関数が関わる場合のみの統計情報である。
よって上の例では、foo:create_file_slow/2 は自分自身の実行自体は短い事が分かる（自分自身の実行時間 = 1691.046 - (1398+249+ ...)）。
ほとんどの時間を file:close/1 で消費している。
同様に、foo:create_file_slow/3 も消費時間が長い。
fprof:apply_start_stop/4 を読んだ 'undefined' function は trace を始める前の関数なので情報がない。
{[{{foo,create_file_slow,2}, 1, 249.678, 0.029}, {{foo,create_file_slow,3}, 768, 0.000, 23.294}], { {foo,create_file_slow,3}, 769, 249.678, 23.323}, % [{{file,write,2}, 768, 220.314, 14.539}, {suspend, 57, 6.041, 0.000}, {{foo,create_file_slow,3}, 768, 0.000, 23.294}]}.
コードとの比較から foo:create_file_slow/3 は
- foo:create_file_slow/3 と foo:create_file_slow/2 によってのみ呼ばれる
- file:write/2 のみを呼ぶ
事が分かる。
supend が何回か呼ばれている事に注目してみる。これは psedo 関数で、create_file_slow/3 の間にプロセスが suspend した事を意味する。
Erlang のスケジューリングによる suspension や、trace file driver のせいだろう。
suspend エントリーを見てみよう。
{[{{file,write,2}, 53, 6.281, 0.000}, {{foo,create_file_slow,3}, 57, 6.041, 0.000}, {{prim_file,drv_command,4}, 50, 4.582, 0.000}, {{prim_file,drv_get_response,1}, 34, 2.986, 0.000}, {{lists,map,2}, 10, 2.104, 0.000}, {{prim_file,write,2}, 17, 1.852, 0.000}, {{erlang,port_command,2}, 15, 1.713, 0.000}, {{prim_file,drv_command,2}, 22, 1.482, 0.000}, {{prim_file,translate_response,2}, 11, 1.441, 0.000}, {{prim_file,'-drv_command/2-fun-0-',1}, 15, 1.340, 0.000}, {{lists,seq,4}, 3, 0.880, 0.000}, {{foo,'-create_file_slow/2-fun-0-',1}, 5, 0.523, 0.000}, {{erlang,bump_reductions,1}, 4, 0.503, 0.000}, {{prim_file,open_int_setopts,3}, 1, 0.165, 0.000}, {{prim_file,i32,4}, 1, 0.109, 0.000}, {{fprof,apply_start_stop,4}, 1, 0.000, 0.000}], { suspend, 299, 32.002, 0.000}, % [ ]}.
suspend を呼び出している側の ACC を見るととても短いので、receive などで suspend している関数はない事が分かる。
suspend 時間は短い。
garbage_collect も大体同じ。
{[{{prim_file,drv_command,4}, 25, 0.873, 0.873}, {{prim_file,write,2}, 16, 0.692, 0.692}, {{lists,map,2}, 2, 0.195, 0.195}], { garbage_collect, 43, 1.760, 1.760}, % [ ]}.
