Erlang Fprof Output Confusing? Try KCachegrind.

Your Erlang code is perfect, but to find out why other peoples code runs dog slow you probably profile the code with fprof like this:

1 2 3 (node@host)1> fprof:apply(module, function, [arguments]). (node@host)1> fprof:profile(). (node@host)1> fprof:analyse({dest, "outfile.fprof"}).

The printout of fprof analyse is a text dump of the result, which can grow over 1000 lines and contains a lot of noise which makes it hard to locate the bottlenecks. Below a truncated sample of an actual fprof trace.

%% Analysis results: { analysis_options, [{callers, true}, {sort, acc}, {totals, false}, {details, true}]}. % CNT ACC OWN [{ totals, 275978, 888.505, 872.193}]. %%% % CNT ACC OWN [{ "<7082.15229.0>", 275978,undefined, 872.193}]. %% {[{{qlc,eval,2}, 0, 843.539, 0.148}, {{mnesia_tm,execute_transaction,5}, 48, 14.085, 0.128}], { {mnesia_tm,apply_fun,3}, 48, 857.624, 0.276}, % [{{mnesia_tm,execute_transaction,5}, 0, 837.267, 0.479}, {{search_index,'-get_document_field_value/1-fun-13-',1}, 46, 689.082, 0.259}, {{mnesia_tm,t_commit,1}, 48, 6.327, 0.361}, {{search_index,'-get_field_facet_document/2-fun-1-',1}, 1, 1.397, 0.002}, {{search_index,'-get_term_document_field_frequencies/1-fun-0-',1}, 1, 0.114, 0.002}]}. {[{{qlc,post_funs,1}, 46, 844.225, 0.083}, {{qlc,eval,1}, 46, 12.254, 0.963}], { {qlc,eval,2}, 92, 856.479, 1.046}, % [{{mnesia_tm,apply_fun,3}, 0, 843.539, 0.148}, {{qlc,collect,1}, 46, 630.839, 0.176}, {{qlc,prepare_qlc,7}, 46, 33.384, 0.399}, {{qlc,setup_qlc,2}, 46, 5.028, 0.086}, {{qlc,options,2}, 46, 4.862, 0.093}, {{qlc,local_post,1}, 46, 0.603, 0.086}, {{qlc,get_handle,1}, 46, 0.087, 0.087}, {{qlc,post_funs,1}, 46, 0.022, 0.075}]}. {[{{mnesia_tm,apply_fun,3}, 0, 837.267, 0.479}, {{mnesia_tm,execute_outer,6}, 48, 14.139, 0.140}], { {mnesia_tm,execute_transaction,5}, 48, 851.406, 0.619}, % [{{search_index,get_document_field_value,1}, 0, 835.968, 0.077}, {{mnesia_tm,apply_fun,3}, 48, 14.085, 0.128}, {{mnesia_lib,incr_counter,1}, 48, 0.333, 0.156}, {{erlang,unlink,1}, 48, 0.281, 0.281}, {{mnesia_tm,flush_downs,0}, 48, 0.086, 0.086}, {{erlang,whereis,1}, 48, 0.073, 0.073}, {{erlang,erase,1}, 48, 0.004, 0.078}]}. %% 1714 lines truncated

KCachegrind

KCachegrind to the rescue! With this tool you can visually inspect the fprof analyse result with sorting, a fancy call graph view, callee map and more.

As KCachegrind can’t read fprof analysis output directly, you need to convert it first to the callgrind format with the Erlgrind script by Isac Sacchi e Souza.

1 $ ./erlgrind outfile.fprof callgrind.001

KCachegrind & Erlgrind Installation

For installation of KCachegrind on my Mac I use Homebrew, a package manager for OSX. Notice that you install qcachegrind, the QT version of KCachegrind.

1 2 3 $ brew install qcachegrind $ brew instal graphviz $ sudo ln -s /usr/local/bin/dot /usr/bin/dot

Installing the Erlgrind (Github) script:

1 2 3 $ curl -O "https://raw.github.com/isacssouza/erlgrind/master/src/erlgrind" $ chmod +x erlgrind $ mv erlgrind /usr/local/bin/

And open qcachegrind:

1 $ open ~/Applications/qcachegrind.app

Enjoy!