cprof - The Call Count Profiler

2 cprof - The Call Count Profiler

cprof is a profiling tool that can be used to get a picture of how often different functions in the system are called.

cprof uses breakpoints similar to local call trace, but containing counters, to collect profiling data. Therfore there is no need for special compilation of any module to be profiled.

cprof presents all profiled modules in decreasing total call count order, and for each module presents all profiled functions also in decreasing call count order. A call count limit can be specified to filter out all functions below the limit.

Profiling is done in the following steps:

cprof:start/0..3: Starts profiling with zeroed call counters for specified functions by setting call count breakpoints on them.
Mod:Fun(): Runs the code to be profiled.
cprof:pause/0..3: Pauses the call counters for specified functions. This minimises the impact of code running in the background or in the shell that disturbs the profiling. Call counters are automatically paused when they "hit the ceiling" of the host machine word size. For a 32 bit host the maximum counter value is 2147483647.
cprof:analyse/0..2: Collects call counters and computes the result.
cprof:restart/0..3: Restarts the call counters from zero for specified functions. Can be used to collect a new set of counters without having to stop and start call count profiling.
cprof:stop/0..3: Stops profiling by removing call count breakpoints from specified functions.

Functions can be specified as either all in the system, all in one module, all arities of one function, one function, or all functions in all modules not yet loaded. As for now, BIFs cannot be call count traced.

The analysis result can either be for all modules, or for one module. In either case a call count limit can be given to filter out the functions with a call count below the limit. The all modules analysis does not contain the module cprof itself, it can only be analysed by specifying it as a single module to analyse.

Call count tracing is very lightweight compared to other forms of tracing since no trace message has to be generated. Some measurements indicates performance degradations in the vicinity of 10 percent.

The following sections show some examples of profiling with cprof. See also cprof(3).

2.1 Example: Background work

From the Erlang shell:

1> cprof:start(), cprof:pause(). % Stop counters just after start
3476
2> cprof:analyse().
{30,
 [{erl_eval,11,
            [{{erl_eval,expr,3},3},
             {{erl_eval,'-merge_bindings/2-fun-0-',2},2},
             {{erl_eval,expand_module_name,2},1},
             {{erl_eval,merge_bindings,2},1},
             {{erl_eval,binding,2},1},
             {{erl_eval,expr_list,5},1},
             {{erl_eval,expr_list,3},1},
             {{erl_eval,exprs,4},1}]},
  {orddict,8,
           [{{orddict,find,2},6},
            {{orddict,dict_to_list,1},1},
            {{orddict,to_list,1},1}]},
  {packages,7,[{{packages,is_segmented_1,1},6},
               {{packages,is_segmented,1},1}]},
  {lists,4,[{{lists,foldl,3},3},{{lists,reverse,1},1}]}]}
3> cprof:analyse(cprof).             
{cprof,3,[{{cprof,tr,2},2},{{cprof,pause,0},1}]}
4> cprof:stop().
3476

The example showed the background work that the shell performs just to interpret the first command line. Most work is done by erl_eval and orddict.

What is captured in this example is the part of the work the shell does while interpreting the command line that occurs between the actual calls to cprof:start() and cprof:analyse().

2.2 Example: One module

From the Erlang shell:

1> cprof:start(),R=calendar:day_of_the_week(1896,4,27),cprof:pause(),R.
1
2> cprof:analyse(calendar).
{calendar,9,
          [{{calendar,df,2},1},
           {{calendar,dm,1},1},
           {{calendar,dy,1},1},
           {{calendar,last_day_of_the_month1,2},1},
           {{calendar,last_day_of_the_month,2},1},
           {{calendar,is_leap_year1,1},1},
           {{calendar,is_leap_year,1},1},
           {{calendar,day_of_the_week,3},1},
           {{calendar,date_to_gregorian_days,3},1}]}
3> cprof:stop().
3271

The example tells us that "Aktiebolaget LM Ericsson & Co" was registered on a Monday (since the return value of the first command is 1), and that the calendar module needed 9 function calls to calculate that.

Using cprof:analyse() in this example also shows approximately the same background work as in the first example.

2.3 Example: In the code

Write a module:

-module(sort).
      
-export([do/1]).
      
do(N) ->
    cprof:stop(),
    cprof:start(),
    do(N, []).
      
do(0, L) ->
    R = lists:sort(L),
    cprof:pause(),
    R;
do(N, L) ->
    do(N-1, [random:uniform(256)-1 | L]).

From the Erlang shell:

1> c(sort).
{ok,sort}
2> l(random).
3> sort:do(1000).
[0,0,1,1,1,1,1,1,2,2,2,3,3,3,3,3,4,4,4,5,5,5,5,6,6,6,6,6,6|...]
4> cprof:analyse().
{9050,
 [{lists_sort,6047,
              [{{lists_sort,merge3_2,6},923},
               {{lists_sort,merge3_1,6},879},
               {{lists_sort,split_2,5},661},
               {{lists_sort,rmerge3_1,6},580},
               {{lists_sort,rmerge3_2,6},543},
               {{lists_sort,merge3_12_3,6},531},
               {{lists_sort,merge3_21_3,6},383},
               {{lists_sort,split_2_1,6},338},
               {{lists_sort,rmerge3_21_3,6},299},
               {{lists_sort,rmerge3_12_3,6},205},
               {{lists_sort,rmerge2_2,4},180},
               {{lists_sort,rmerge2_1,4},171},
               {{lists_sort,merge2_1,4},127},
               {{lists_sort,merge2_2,4},121},
               {{lists_sort,mergel,2},79},
               {{lists_sort,rmergel,2},27}]},
  {random,2001,
          [{{random,uniform,1},1000},
           {{random,uniform,0},1000},
           {{random,seed0,0},1}]},
  {sort,1001,[{{sort,do,2},1001}]},
  {lists,1,[{{lists,sort,1},1}]}]}
5> cprof:stop().
5369

The example shows some details of how lists:sort/1 works. It used 6047 function calls in the module lists_sort to complete the work.

This time, since the shell was not involved, no other work was done in the system during the profiling. If you retry the same example with a freshly started Erlang emulator, but omit the command l(random), the analysis will show a lot more function calls done by code_server and others to automatically load the module random.