Process Tracing Profiling Tool

tprof provides convenience helpers for Erlang process profiling. Underlying mechanism is the Erlang trace BIFs.

Warning

This module aims to replace eprof and cprof into a unified API for measuring call count, time, and allocation. It is experimental in Erlang/OTP 27.0.

It is possible to analyze the number of calls, the time spent by function, and heap allocations by function. Profiling can be done ad-hoc or run in a server-aided mode for deeper introspection of the code running in production.

Warning

Avoid hot code reload for modules that are participating in the tracing. Reloading a module turns tracing off, discarding accumulated statistics. tprof may not report correct amounts when code reload happened during profiling session.

The type option controls which type of profiling to perform. You can choose between call_count, call_time, and call_memory. The default is call_count, it has the smallest footprint on the system but it does not support per-process profiling. For this reason, all of the examples below use call_memory, which measures heap allocation, and provide a more complex feature set to demonstrate.

Heap allocations happen for all Erlang terms that do not fit a single machine word. For example, a function returning tuple of 2 elements needs to allocate this tuple on the process heap. Actual consumption is more than 2 machine words, because Erlang runtime needs to store tuple size and other internal information.

Note

When profiling is enabled, expect a slowdown in the program execution.

For profiling convenience, measurements are accumulated for functions that are not enabled in trace pattern. Consider this call stack example:

top_traced_function(...)
not_traced_function()
bottom_traced_function()

Allocations that happened within not_traced_function will be accounted into top_traced_function. However allocations happened within bottom_traced_function are not included in the top_traced_function. If you want to account only own allocations, you need to trace all functions.

Ad-hoc profiling

Basic profiling providing accumulated memory allocation data. You can choose to print per-process statistics, total statistics, or omit printing and extract machine-readable data that you can later sort/print:

1> tprof:profile(lists, seq, [1, 16], #{type => call_memory}).

****** Process <0.179.0>    -- 100.00 % of total allocations ***
FUNCTION          CALLS  WORDS  PER CALL  [     %]
lists:seq_loop/3      5     32         6  [100.00]
32            [ 100.0]
ok

By default tracing is enabled for all functions of all modules. When functions are created in the interactive shell, parts of shell code are also traced. It is however possible to limit the trace to specific functions or modules:

1> tprof:profile(fun() -> lists:seq(1, 16) end, #{type => call_memory}).

****** Process <0.224.0>    -- 100.00 % of total allocations ***
FUNCTION                   CALLS  WORDS  PER CALL  [    %]
erl_eval:match_list/6          1      3         3  [ 3.19]
erl_eval:do_apply/7            1      3         3  [ 3.19]
lists:reverse/1                1      4         4  [ 4.26]
erl_eval:add_bindings/2        1      5         5  [ 5.32]
erl_eval:expr_list/7           3      7         2  [ 7.45]
erl_eval:ret_expr/3            4     16         4  [17.02]
erl_eval:merge_bindings/4      3     24         8  [25.53]
lists:seq_loop/3               5     32         6  [34.04]

2> tprof:profile(fun() -> lists:seq(1, 16) end,
                 #{type => call_memory, pattern => [{lists, seq_loop, '_'}]}).
****** Process <0.247.0>    -- 100.00 % of total allocations ***
FUNCTION          CALLS  WORDS  PER CALL  [     %]
lists:seq_loop/3      5     32         6  [100.00]

Ad-hoc profiling results may be printed in a few different ways. Following examples are using test module defined like this:

-module(test).
-export([test_spawn/0]).
test_spawn() ->
    {Pid, MRef} = spawn_monitor(fun () -> lists:seq(1, 32) end),
    receive
        {'DOWN', MRef, process, Pid, normal} ->
            done
    end.

Default format prints per-process statistics.

2> tprof:profile(test, test_spawn, [], #{type => call_memory}).

****** Process <0.176.0>    -- 23.66 % of total allocations ***
FUNCTION                CALLS  WORDS  PER CALL  [    %]
erlang:spawn_monitor/1      1      2         2  [ 9.09]
erlang:spawn_opt/4          1      6         6  [27.27]
test:test_spawn/0           1     14        14  [63.64]
                                    22            [100.0]

****** Process <0.177.0>    -- 76.34 % of total allocations ***
FUNCTION           CALLS  WORDS  PER CALL  [    %]
erlang:apply/2         1      7         7  [ 9.86]
lists:seq_loop/3       9     64         7  [90.14]
                             71            [100.0]

This example prints the combined memory allocation of all processes, sorted by total allocated words in the descending order

5> tprof:profile(test, test_spawn, [],
                 #{type => call_memory, report => {total, {measurement, descending}}}).

FUNCTION                CALLS  WORDS  PER CALL  [    %]
lists:seq_loop/3            9     64         7  [68.82]
test:test_spawn/0           1     14        14  [15.05]
erlang:apply/2              1      7         7  [ 7.53]
erlang:spawn_opt/4          1      6         6  [ 6.45]
erlang:spawn_monitor/1      1      2         2  [ 2.15]
                                  93            [100.0]

You can also collect the profile for further inspection.

6> {done, ProfileData} = tprof:profile(fun test:test_spawn/0,
                                       #{type => call_memory, report => return}).
<...>
7> tprof:format(tprof:inspect(ProfileData, process, {percent, descending})).

****** Process <0.223.0>    -- 23.66 % of total allocations ***
FUNCTION                CALLS  WORDS  PER CALL  [    %]
test:test_spawn/0           1     14        14  [63.64]
erlang:spawn_opt/4          1      6         6  [27.27]
erlang:spawn_monitor/1      1      2         2  [ 9.09]
22            [100.0]

****** Process <0.224.0>    -- 76.34 % of total allocations ***
FUNCTION           CALLS  WORDS  PER CALL  [    %]
lists:seq_loop/3       9     64         7  [90.14]
erlang:apply/2         1      7         7  [ 9.86]
71            [100.0]

The processes which are profiled depends on the profiling type. call_count, the default, will count calls across all processes. The other types, call_time and call_memory, take into account all processes spawned from the user-provided function (using set_on_spawn argument for trace/3 BIF). You cannot restrict the profiled processes for call_count, but you can limit the trace to a single process for the other two:

2> tprof:profile(test, test_spawn, [],
                 #{type => call_memory, set_on_spawn => false}).

****** Process <0.183.0>    -- 100.00 % of total allocations ***
FUNCTION                CALLS  WORDS  PER CALL  [    %]
erlang:spawn_monitor/1      1      2         2  [ 9.09]
erlang:spawn_opt/4          1      6         6  [27.27]
test:test_spawn/0           1     14        14  [63.64]

Erlang programs may perform expensive operations in processes that are different from the original one. You can include multiple, new or even all processes in the trace when measuring time or memory:

7> pg:start_link().
{ok,<0.252.0>}
8> tprof:profile(fun() -> pg:join(group, self()) end,
                 #{type => call_memory, rootset => [pg]}).
****** Process <0.252.0>    -- 52.86 % of total allocations ***
FUNCTION                      CALLS  WORDS  PER CALL  [    %]
pg:leave_local_update_ets/5       1      2         2  [ 1.80]
gen:reply/2                       1      3         3  [ 2.70]
erlang:monitor/2                  1      3         3  [ 2.70]
gen_server:try_handle_call/4      1      3         3  [ 2.70]
gen_server:try_dispatch/4         1      3         3  [ 2.70]
maps:iterator/1                   2      4         2  [ 3.60]
maps:take/2                       1      6         6  [ 5.41]
pg:join_local_update_ets/5        1      8         8  [ 7.21]
pg:handle_info/2                  1      8         8  [ 7.21]
pg:handle_call/3                  1      9         9  [ 8.11]
gen_server:loop/7                 2      9         4  [ 8.11]
ets:lookup/2                      2     10         5  [ 9.01]
pg:join_local/3                   1     11        11  [ 9.91]
pg:notify_group/5                 2     16         8  [14.41]
erlang:setelement/3               2     16         8  [14.41]
111            [100.0]

****** Process <0.255.0>    -- 47.14 % of total allocations ***
FUNCTION                   CALLS  WORDS  PER CALL  [    %]
erl_eval:match_list/6          1      3         3  [ 3.03]
erlang:monitor/2               1      3         3  [ 3.03]
lists:reverse/1                2      4         2  [ 4.04]
pg:join/3                      1      4         4  [ 4.04]
erl_eval:add_bindings/2        1      5         5  [ 5.05]
erl_eval:do_apply/7            2      6         3  [ 6.06]
gen:call/4                     1      8         8  [ 8.08]
erl_eval:expr_list/7           4     10         2  [10.10]
gen:do_call/4                  1     16        16  [16.16]
erl_eval:ret_expr/3            4     16         4  [16.16]
erl_eval:merge_bindings/4      3     24         8  [24.24]
99            [100.0]

There is no default limit on the profiling time. It is possible to define such limit for ad-hoc profile. If function being profiled does not return in a specified amount of time, process is terminated with kill reason. Any unlinked children started by the user-supplied function are kept, it is developer's responsibility to ensure cleanup.

9> tprof:profile(timer, sleep, [100000], #{timeout => 1000}).

By default, only one ad-hoc or server-aided profiling session is allowed at any point in time. It is possible to force multiple ad-hoc sessions concurrently, but it is developer responsibility to ensure non-overlapping trace patterns.

1> tprof:profile(fun() -> lists:seq(1, 32) end,
    #{registered => false, pattern => [{lists, '_', '_'}]}).

Server-aided profiling

Memory profiling can be done when your system is up and running. You can start the tprof server, add trace patterns and processes to trace while your system handles actual traffic. You can extract the data any time, inspect, and print. The example below traces activity of all processes supervised by kernel:

1> tprof:start(#{type => call_memory}).
{ok,<0.200.0>}
2> tprof:enable_trace({all_children, kernel_sup}).
34
3> tprof:set_pattern('_', '_' , '_').
16728
4> Sample = tprof:collect().
[{gen_server,try_dispatch,4,[{<0.154.0>,2,6}]},
{erlang,iolist_to_iovec,1,[{<0.161.0>,1,8}]},
<...>
5 > tprof:format(tprof:inspect(Sample)).

****** Process <0.154.0>    -- 14.21 % of total allocations ***
FUNCTION                   CALLS  WORDS  PER CALL  [    %]
maps:iterator/1                2      4         2  [15.38]
gen_server:try_dispatch/4      2      6         3  [23.08]
net_kernel:handle_info/2       2     16         8  [61.54]
                                     26            [100.0]

****** Process <0.161.0>    -- 85.79 % of total allocations ***
FUNCTION                        CALLS  WORDS  PER CALL  [    %]
disk_log:handle/2                   2      2         1  [ 1.27]
disk_log_1:maybe_start_timer/1      1      3         3  [ 1.91]
disk_log_1:mf_write_cache/1         1      3         3  [ 1.91]
<...>

It is possible to profile the entire running system, and then examine individual processes:

1> tprof:start(#{type => call_memory}).
2> tprof:enable_trace(processes), tprof:set_pattern('_', '_' , '_').
9041
3> timer:sleep(10000), tprof:disable_trace(processes), Sample = tprof:collect().
[{user_drv,server,3,[{<0.64.0>,12,136}]},
{user_drv,contains_ctrl_g_or_ctrl_c,1,[{<0.64.0>,80,10}]},
<...>
4> Inspected = tprof:inspect(Sample, process, words), Shell = maps:get(self(), Inspected).
{2743,
[{shell,{enc,0},1,2,2,0.07291286912139992},
<...>
5> tprof:format(Shell).

FUNCTION                           CALLS  WORDS  PER CALL  [    %]
<...>
erl_lint:start/2                       2    300       150  [10.94]
shell:used_records/1                 114    342         3  [12.47]