Either process identified (pid), or a registered process name.
tprof
Description
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]
okBy 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]
Data Types
trace_type() = call_count | call_time | call_memory
trace_map() = #{module() => [{Fun :: atom(), arity()}]}
Traced functions (with their arities) grouped by module name.
trace_pattern() = {module(), Fun :: atom(), arity() | '_'}
trace_options() = #{set_on_spawn => boolean()}
Options for enabling profiling of the selected processes, see enable_trace/2.
trace_info() =
{module(),
Fun :: atom(),
Arity :: integer() >= 0,
[{pid(),
Count :: integer() >= 1,
Measurement :: integer() >= 1}]}
{module(),
Fun :: atom(),
Arity :: integer() >= 0,
[{pid(),
Count :: integer() >= 1,
Measurement :: integer() >= 1}]}
Raw data extracted from tracing BIFs.
profile_options() =
#{type => trace_type(),
timeout => timeout(),
pattern => trace_pattern() | [trace_pattern()],
set_on_spawn => boolean(),
rootset => rootset(),
report =>
return | process | total |
{process, sort_by()} |
{total, sort_by()},
device => io:device(),
registered => false | {local, atom()}}
#{type => trace_type(),
timeout => timeout(),
pattern => trace_pattern() | [trace_pattern()],
set_on_spawn => boolean(),
rootset => rootset(),
report =>
return | process | total |
{process, sort_by()} |
{total, sort_by()},
device => io:device(),
registered => false | {local, atom()}}
Ad-hoc profiler options, see profile.
profile_line() =
{module(),
Function :: {atom(), arity()},
Count :: integer() >= 1,
Measurement :: integer() >= 1,
MeasurementPerCall :: integer() >= 0,
Percent :: float()}
{module(),
Function :: {atom(), arity()},
Count :: integer() >= 1,
Measurement :: integer() >= 1,
MeasurementPerCall :: integer() >= 0,
Percent :: float()}
Inspected data for a single function of the specified Module.
profile_result() =
{trace_type(),
TotalMeasurement :: integer() >= 0,
[profile_line()]}
{trace_type(),
TotalMeasurement :: integer() >= 0,
[profile_line()]}
Profile of a single process, or combined profile of multiple processes, sorted by a selected column.
column() =
module | function | calls | measurement |
measurement_per_call | percent
module | function | calls | measurement |
measurement_per_call | percent
Column to sort by inspect/3, or profile.
- module
- Module name.
- function
- Function name.
- calls
- Number of calls to the function.
- measurement
- Total measurement (call count, time, or heap allocation) throughout all calls to the function.
- measurement_per_call
- Measurement (call count, time, or heap allocation) on average per function call.
- percent
- Percentage of measurement to total amount during the entire profile collection.
start() -> {ok, Pid} | {error, Reason}OTP 27.0
Starts the server, not supervised. Profiling server stores current trace patterns and ensures a single instance of profiler is running.
start_link() -> {ok, Pid} | {error, Reason}OTP 27.0
Starts the server, supervised by the calling process.
stop() -> okOTP 27.0
Stops the tprof, disabling tracing that has been enabled.
set_pattern(Mod :: module(),
Fun :: atom(),
Arity :: arity() | '_') ->
ok | {error, {trace_pattern, trace_pattern()}}OTP 27.0
Turns tracing on for the supplied pattern. Requires running tprof. Patterns are additive, following the same rules as erlang:trace_pattern/3. Returns number of functions matching the supplied pattern.
1> tprof:set_pattern(lists, seq, '_').
2
2> tprof:set_pattern(lists, keyfind, 3).
1
3> tprof:get_trace_map().
#{lists => [{keyfind,3},{seq,2},{seq,3}]}If there are no functions matching the pattern, error is returned
> tprof:set_pattern(no_module, func, '_').
{error,{trace_pattern,no_module,func,'_'}}
clear_pattern(Mod :: module(),
Fun :: atom(),
Arity :: arity() | '_') ->
okOTP 27.0
Turns tracing off for the supplied pattern.
1> tprof:set_pattern(lists, seq, '_').
2
2> tprof:clear_pattern(lists, seq, 3).
1
3> tprof:get_trace_map().
#{lists => [{seq,2}]}
get_trace_map() -> trace_map()OTP 27.0
Returns a map of module names to functions with their arities.
enable_trace(Spec) -> integer() >= 0OTP 27.0
enable_trace(Rootset :: [process()]) ->
integer() >= 0 |
{integer() >= 0, [process()]}OTP 27.0
The same as enable_trace (Spec, #{set_on_spawn => true}).
enable_trace(Spec, Options :: trace_options()) ->
integer() >= 0OTP 27.0
enable_trace(Procs :: [process()], Options :: trace_options()) ->
integer() >= 0 |
{integer() >= 0, [process()]}OTP 27.0
Similar to erlang:trace/3, but supports a few more options for tracing convenience. Tracing per process is not supported by call_count profilers.
Spec is either a process identifier (pid) for a local process, one of the following atoms, or a list of local process identifiers or their registered names:
- processes
- All currently existing processes and all that will be created in the future.
- existing_processes
- All currently existing processes.
- new_processes
- All processes that will be created in the future.
- children
- All currently running processes that were directly spawned by the specified process. This mode is helpful for tracing workers of a single supervisor.
- all_children
- All currently running processes that were spawned by the specified process, or any recursive descendant of it. This mode is designed to facilitate tracing of supervision trees.
Note
The profiling server does not keep track of processes that were added to the tracing set. It is permitted to stop the profiling server (wiping out any accumulated data), restart the server, set entirely different tracing pattern keeping the list of traced processes for future use. Use disable_trace(processes) to clear the list of traced processes.
Specify Options to modify tracing behaviour:
- set_on_spawn
- Automatically start tracing for processes spawned by the traced process. On by default.
disable_trace(Spec) -> integer() >= 0OTP 27.0
disable_trace(Rootset :: [process()]) ->
integer() >= 0 |
{integer() >= 0, [process()]}OTP 27.0
The same as disable_trace (Spec, #{set_on_spawn => true}).
disable_trace(Spec, Options :: trace_options()) ->
integer() >= 0OTP 27.0
disable_trace(Procs :: [process()], Options :: trace_options()) ->
integer() >= 0 |
{integer() >= 0, [process()]}OTP 27.0
Stops accumulating traces for specified processes. See enable_trace/2 for options description.
Profile accumulated before process is removed from the traced list is retained. This allows to enable tracing for many or even all processes in the system, sleep for a short period of time, then disable tracing for all processes, avoiding system overload, but keeping profile data.
pause() -> ok | not_runningOTP 27.0
Pauses trace collection for all currently traced functions, keeping all traces intact. Use continue/0 to resume trace collection.
continue() -> ok | not_pausedOTP 27.0
Resumes previously paused profiling.
restart() -> okOTP 27.0
Clears accumulated profiles. If profiling was paused prior to calling restart, it gets continued.
profile(Fun :: fun(() -> term())) -> ok | {term(), [trace_info()]}OTP 27.0
profile(Fun :: fun(() -> term()), Options :: profile_options()) ->
ok | {term(), [trace_info()]}OTP 27.0
profile(Module :: module(), Fun :: atom(), Args :: [term()]) ->
ok | {term(), [trace_info()]}OTP 27.0
profile(Module :: module(),
Fun :: atom(),
Args :: [term()],
Options :: profile_options()) ->
ok | {term(), [trace_info()]}OTP 27.0
Produces ad-hoc profile for function Fun or Module:Function call. By default, result is formatted to the output device, use report option to change this behaviour.
Ad-hoc profiling starts a new instance of tprof server, runs the profiling routine, extracts results and shuts the server down. If tprof is already running (for server-aided profiling), default ad-hoc profiler options block this call to avoid mixing results from several independent instances. Use registered => false option to override this behaviour.
Ad-hoc profiler supports following Options:
- type
- The type of profiling to perform.
- device
- Specifies I/O devices to print the profile to. Useful to redirect text output to console or standard_error.
- pattern
- Specifies trace pattern, or a list of trace patterns to enable. By default, all functions ({'_', '_', '_'}) are traced.
- registered
- Specifies tprof registered process name. Use false to leave the process unregistered, or {local, myname} to register the process under a different name.
- report
- Controls output format. The default is process, printing per-process profiling data sorted by percentage of the total allocation. Specify report => return to suppress printing and get the raw data for further evaluation with inspect/3 and formatting with format/2.
- rootset
- Includes extra processes in the trace list. Useful for profiling allocations for gen_server, calls, or other allocations caused by inter-process communications. See example.
- set_on_spawn
- Automatically start tracing for processes spawned by the traced process. On by default.
- timeout
- Terminate profiling after the specified amount of time (milliseconds).
format(Inspected :: #{pid() | all => profile_result()}) -> okOTP 27.0
format(IoDevice :: io:device(),
Inspected :: #{pid() | all => profile_result()}) ->
okOTP 27.0
Formats profile transformed with inspect to a specified device.
inspect(Profile :: {trace_type(), [trace_info()]}) ->
#{pid() | all => profile_result()}OTP 27.0
The same as inspect (Profile, process, percent). Transforms raw profile into a map of process identifiers to a tuple containing total count of words allocated, and a list of all traced functions sorted in the ascending order by the allocation percentage.
inspect(X1 :: {trace_type(), [trace_info()]},
X2 :: process | total,
SortBy :: sort_by()) ->
#{pid() | all => profile_result()}OTP 27.0
Transforms raw data returned by tracing BIFs into a form convenient for subsequent analysis and formatting.
When process is given as second argument, it returns a map of process identifiers with corresponding profiling results sorted by the selected column. When the second argument is total or when profiling by call_count, the returned map has a single all key with profiling results from all processes.
Inspected profile can be leveraged to print profiling results.