Elixir 1.1.1 has been recently released and the includes built in profiling support with mix profile.fprof. I decied to take this new command for a spin. I’ve used fprof before so I’ll desribe some of the differences about using the new mix version.
This will be a short post, but hopefully useful or interesting.
Results Format
I’m using my game of life implementation that I wrote about in the past. I had previously setup profiling options for this program, including support for fprof. There are some differences between the reporing when using fprof directly and with the new mix profile.fprof support. With mix, I’ve enabled all the options I used with fprof before, and here’s the output:
MIX_ENV=prod time mix profile.fprof --callers=true --sort=own --details -e "Profile.run_test"
CNT ACC (ms) OWN (ms)
Total 81526 1042.615 1031.268
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 38.851
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 38.333
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 37.715
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 37.498
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 36.128
Enum."-reduce/3-lists^foldl/2-0-"/3 1010 0.000 13.145
Enum.reduce/3 601 161.130 9.827
Enum.reduce/3 601 161.082 9.593
Enum.reduce/3 601 159.431 9.464
Enum.reduce/3 601 160.294 9.230
Enum.reduce/3 601 154.103 8.899
Enum.reduce/3 20 829.270 4.894
Enum."-reduce/3-lists^foldl/2-0-"/3 18535 1625.310 253.577 <--
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 38.851
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 38.333
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 37.715
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 37.498
Enum."-reduce/3-lists^foldl/2-0-"/3 2900 0.000 36.128
anonymous fn/3 in Enum.map/2 900 159.238 14.991
anonymous fn/3 in Enum.map/2 900 158.584 14.887
anonymous fn/3 in Enum.map/2 900 159.389 14.852
...This is nice and readable. The anonymous functions are still a little hard to fillow but that’s just a problem with functions not having names. The data is organized is nice columns and easy to follow.
To contrast, here’s the direct fprof output:
% MIX_ENV=prod mix run -e "Profile.fprof"
%% Analysis results:
{ anlysis_options,
[{callers, true},
{sort, own},
{totals, true},
{details, true}]}.
% CNT ACC OWN
[{ totals, 81530, 985.003, 977.102}]. %%%
{[{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 42.280},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 37.985},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 36.809},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 36.663},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 21.512},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},1010, 0.000, 12.211},
{ {'Elixir.Enum',reduce,3}, 601, 178.067, 9.724},
{ {'Elixir.Enum',reduce,3}, 601, 158.718, 9.110},
{ {'Elixir.Enum',reduce,3}, 601, 162.003, 9.077},
{ {'Elixir.Enum',reduce,3}, 601, 158.718, 9.006},
{ {'Elixir.Enum',reduce,3}, 601, 91.765, 5.222},
{ {'Elixir.Enum',reduce,3}, 20, 778.835, 3.958}],
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},18535, 1528.106, 233.557}, %
[{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 42.280},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 37.985},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 36.809},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 36.663},
{ {'Elixir.Enum','-reduce/3-lists^foldl/2-0-',3},2900, 0.000, 21.512},
{ {'Elixir.Enum','-map/2-fun-0-',3}, 900, 176.149, 16.459},
{ {'Elixir.Life','-list_of_neighbors/3-fun-0-',6}, 900, 59.302, 15.913},
{ {'Elixir.Enum','-map/2-fun-0-',3}, 900, 160.314, 14.960},
{ {'Elixir.Enum','-map/2-fun-0-',3}, 900, 157.062, 14.751},
{ {'Elixir.Enum','-map/2-fun-0-',3}, 900, 157.090, 14.670},
...This data is still organized in columns, kind of. The “{}” make things a little difficult to follow. It also has the “Elixir.” annotations because it’s in Erlang format.
Peronsally (i.e. as a person) I find the new mix form easier to read. But, if I were writing a program to process the output and transform it or analyze it then the standard fprof format would be preferable. Especially if was writing that program in Elixir or Erlang - the output from fprof is a set of Erlang terms. The results should be directly consumable by an Erlang or Elixir program.
In fact, I’m assuming that mix profile.fprof takes in this format and transforms it into the human readable format we see when the running the command.
If you want to setup standard fprof yourself see my older post Profiling Elixir. But if you just want human readable results the mix profile.fprof command will serve your well.
In might be interesting if a future version of mix profile.fprof had a variant that could return the raw analysis as an Elixir structure.
Next Week
That’s all for fprof for now.
Next week’s I’lldescribe some of the interesting talks I saw last week at Elixir Conf 2015.