View Source mix profile.tprof (Mix v1.17.3)
Profiles the given file or expression using Erlang's tprof
tool.
Requires Erlang/OTP27 or above.
:tprof
is an experimental module introduced in Erlang/OTP 27 which
provides a unified API for measuring call count, time, and allocation, and aims to
replace :eprof
and :cprof
.
It can be useful when you want to discover the bottlenecks related to any of these
measurements.
Before running the code, it invokes the app.start
task which compiles
and loads your project. After that, the target expression is profiled together
with all matching function calls using the Erlang trace BIFs. The tracing of
the function calls for that is enabled when the profiling is begun, and
disabled when profiling is stopped.
To profile the code, you can use syntax similar to the mix run
task:
$ mix profile.tprof -e Hello.world
$ mix profile.tprof -e "[1, 2, 3] |> Enum.reverse |> Enum.map(&Integer.to_string/1)"
$ mix profile.tprof my_script.exs arg1 arg2 arg3
By default, tprof uses the time
type, but you can profile memory too:
$ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type memory
Call count is present with both type time
and memory
, but if you only need
the call count information, you can use the type calls
which has the lowest footprint:
$ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type calls
This task is automatically re-enabled, so you can profile multiple times in the same Mix invocation.
Command line options
--matching
- only profile calls matching the givenModule.function/arity
pattern--type
- the type of profiling,calls
,time
ormemory
(default:time
)--calls
- filters out any results with a call count lower than this--time
- filters out any results that took lower than specified (in µs), thetype
needs to betime
--memory
- filters out any results that used less memory than specified (in words), thetype
needs to bememory
--sort
- sorts the results bycalls
,per_call
or by the value oftype
(default: the value oftype
)--report
- returns the per-process breakdown whenprocess
, or the total for all processes whentotal
(default:process
). Alwaystotal
whentype
iscalls
.--eval
,-e
- evaluates the given code--require
,-r
- requires pattern before running the command--parallel
,-p
- makes all requires parallel--no-warmup
- skips the warmup step before profiling--no-compile
- does not compile even if files require compilation--no-deps-check
- does not check dependencies--no-archives-check
- does not check archives--no-halt
- does not halt the system after running the command--no-start
- does not start applications after compilation--no-elixir-version-check
- does not check the Elixir version from mix.exs
Profile output
Example output (time
type):
Profile results of #PID<0.107.0>
# CALLS % TIME µS/CALL
Total 20 100.00 2 0.10
String.Chars.Integer.to_string/1 5 0.00 0 0.00
anonymous fn/0 in :elixir_compiler_1.__FILE__/1 1 0.00 0 0.00
Enum.each/2 1 0.00 0 0.00
Enum.reduce_range/5 3 0.00 0 0.00
:erlang.integer_to_binary/1 5 50.00 1 0.20
anonymous fn/3 in Enum.each/2 5 50.00 1 0.20
Profile done over 6 matching functions
Example output (memory
type):
Profile results of #PID<0.107.0>
# CALLS % WORDS PER CALL
Total 6 100.00 19 3.17
Enum.each/2 1 21.05 4 4.00
:erlang.integer_to_binary/1 5 78.95 15 3.00
Profile done over 2 matching functions
Example output (calls
type)
Profile results over all processes
# CALLS %
Total 20 100.00
anonymous fn/0 in :elixir_compiler_1.__FILE__/1 1 5.00
Enum.each/2 1 5.00
Enum.reduce_range/5 3 15.00
:erlang.integer_to_binary/1 5 25.00
String.Chars.Integer.to_string/1 5 25.00
anonymous fn/3 in Enum.each/2 5 25.00
Profile done over 6 matching functions
The default output contains data gathered from all matching functions. The first row after the header contains the sums of the partial results and the average time or memory usage for all the function calls listed. The following rows contain the function call, followed by the number of times that the function was called, then by the percentage of time/memory that the call uses, then the total time/memory for that function in microseconds/words, and, finally, the average time/memory per call in microseconds/words.
When --matching
option is specified, call count tracing will be started only for
the functions matching the given pattern:
Profile results of #PID<0.106.0>
# CALLS % TIME µS/CALL
Total 5 100.00 1 0.20
String.Chars.Integer.to_string/1 5 100.00 1 0.20
Profile done over 1 matching functions
The pattern can be a module name, such as String
to count all calls to that module,
a call without arity, such as String.split
, to count all calls to that function
regardless of arity, or a call with arity, such as String.split/3
, to count all
calls to that exact module, function and arity.
Caveats
You should be aware that the code being profiled is running in an anonymous
function which is invoked by :tprof
module.
Thus, you'll see some additional entries in your profile output. It is also
important to note that the profiler is stopped as soon as the code has finished running,
and this may need special attention, when: running asynchronous code as function calls which were
called before the profiler stopped will not be counted; running synchronous code as long
running computations and a profiler without a proper MFA trace pattern or filter may
lead to a result set which is difficult to comprehend.
You should expect a slowdown in your code execution using this tool since :tprof
has
some performance impact on the execution, but the impact is considerably lower than
Mix.Tasks.Profile.Fprof
. If you have a large system try to profile a limited
scenario or focus on the main modules or processes. The calls
type can also be used,
which is more limited but has a lower footprint.
Summary
Functions
Allows to programmatically run the tprof
profiler on expression in fun
.
Functions
Allows to programmatically run the tprof
profiler on expression in fun
.
Returns the return value of fun
.
Options
:matching
- only profile calls matching the given pattern in form of{module, function, arity}
, where each element may be replaced by:_
to allow any value:type
- the type of profiling, possible values are:time
,:memory
or:calls
, (default::time
), see moduledoc for more information:calls
- filters out any results with a call count lower than this:time
- filters out any results that took lower than specified (in µs),type
needs to be:time
:memory
- filters out any results that used less memory than specified (in words),type
needs to be:memory
:sort
- sort the results by:calls
,:per_call
or by the value oftype
(default: the value oftype
):report
- returns the per-process breakdown when:process
, or the total for all processes when:total
(default::process
). Always:total
whentype
is:calls
.:warmup
- if the code should be warmed up before profiling (default:true
):set_on_spawn
- if newly spawned processes should be measured (default:true
)