How to measure performance in Julia
For that, we have a look at a simple vector summation function and include the simple @time
macro.
function my_sum(V)
s = zero(eltype(V))
for i in eachindex(V)
@inbounds s += V[i]
end
return s
end
V = rand(100_000)
@time my_sum(V)
@time my_sum(V)
0.007566 seconds (2.21 k allocations: 152.062 KiB, 98.51% compilation time)
0.000097 seconds (1 allocation: 16 bytes)
49923.9182677654
@inbounds
macro to eliminate inbound checks for the array access and thus improve performance. It is challenging and probably even not possible to prove the safety of methods using @inbounds
, so it is essential to consider the trade-off between performance gains and the potential for unnoticed errors. Rule of thumb: Do not use it, unless you really need this performance gain.The downside with the @time
macro is, that it really just measures the execution time of what is given to it. This means, if the function is not already compiled this might include compiling or if the CPU is busy with something else it is often not accurate.
Therefore, if we are serious about measuring performance we should stick to the BenchmarkTools
. It comes with a couple of macros that we should test out:
using BenchmarkTools
, as any other package. Benchmark our my_sum
function with the following macros:
@benchmark
@btime
Look at the detailed output of your benchmark with
dump(t)
, wheret
is the output result of a@benchmark
run and compare the output and results.Duplicate
my_sum()
, name itmy_sum_no_inbounds()
, remove the@inbounds
macro and compare the performance to that ofmy_sum()
.
using BenchmarkTools
@benchmark my_sum($V)
BenchmarkTools.Trial: 10000 samples with 1 evaluation.
Range (min … max): 92.542 μs … 131.215 μs ┊ GC (min … max): 0.00% … 0.00%
Time (median): 92.613 μs ┊ GC (median): 0.00%
Time (mean ± σ): 93.217 μs ± 2.190 μs ┊ GC (mean ± σ): 0.00% ± 0.00%
█ ▂▁ ▁
█▅▃▅██▃▅▄▂▄▅▇▆▅▅▅▄▅▄▅▅▄▄▄▅▄▅▅▄▅▅▅▇▆▆▆▆▇▇▆▆▆▅▅▅▅▄▄▅▄▇▇▇▆▅▅▅▅▅ █
92.5 μs Histogram: log(frequency) by time 103 μs <
Memory estimate: 0 bytes, allocs estimate: 0.
the full details with
t = @benchmark my_sum($V)
dump(t)
BenchmarkTools.Trial
params: BenchmarkTools.Parameters
seconds: Float64 5.0
samples: Int64 10000
evals: Int64 1
overhead: Float64 0.0
gctrial: Bool true
gcsample: Bool false
time_tolerance: Float64 0.05
memory_tolerance: Float64 0.01
times: Array{Float64}((10000,)) [94116.0, 93164.0, 92583.0, 92644.0, 92713.0, 92704.0, 92653.0, 92874.0, 92613.0, 110998.0 … 99376.0, 92613.0, 92634.0, 92633.0, 92673.0, 92644.0, 92613.0, 92664.0, 92653.0, 92643.0]
gctimes: Array{Float64}((10000,)) [0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0 … 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0]
memory: Int64 0
allocs: Int64 0
and the often used sanity check, that actually also shows you the output of your code.
@btime my_sum($V)
92.553 μs (0 allocations: 0 bytes)
49923.9182677654
Skipping the inbound
check only gives a minor improvement as you can see when you compare the results to the following version which performs the check:
function my_sum_no_inbounds(V)
s = zero(eltype(V))
for i in eachindex(V)
s += V[i]
end
return s
end
@benchmark my_sum_no_inbounds($V)
BenchmarkTools.Trial: 10000 samples with 1 evaluation.
Range (min … max): 92.543 μs … 115.947 μs ┊ GC (min … max): 0.00% … 0.00%
Time (median): 92.603 μs ┊ GC (median): 0.00%
Time (mean ± σ): 93.134 μs ± 2.011 μs ┊ GC (mean ± σ): 0.00% ± 0.00%
█ ▂▂ ▁
█▆▆▇██▆▆▄▄▄▆▇█▇▅▅▆▆▅▆▄▆▁▆▅▅▅▆▅▆▅▄▅▆▆▆▆▆▇▇▇▇▆▆▅▆▅▅▆▅▇██▆▅▅▄▄▅ █
92.5 μs Histogram: log(frequency) by time 102 μs <
Memory estimate: 0 bytes, allocs estimate: 0.
$
literal for variables to tell the Julia interpreter to use interpolation. This will make sure that the variable is not allocated inside the function and the measurement is more accurate, or more likely what we actually want to know.We can also use the Profiler
package to really dig into profiling the code but this is a bit too much of a deep dive for this class, it would look like this:
using Profile
Profile.clear()
@profile for _ in 1:100_000; my_sum(V); end
Profile.print(maxdepth=15)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
╎8281 @Base/client.jl:495; _start()
╎ 8281 @Base/client.jl:309; exec_options(opts::Base.JLOptions)
╎ 8281 @Base/client.jl:379; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
╎ 8281 @Base/essentials.jl:714; invokelatest
╎ 8281 @Base/essentials.jl:716; #invokelatest#2
╎ 8281 @Base/client.jl:394; (::Base.var"#936#938"{Bool, Bool, Bool})(REPL::Module)
╎ ╎ 8281 ...r/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:351; run_repl(repl::REPL.AbstractREPL, consumer::Any)
╎ ╎ 8281 ...r/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:364; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
╎ ╎ 8281 .../worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:231; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
╎ ╎ 8281 .../worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:246; repl_backend_loop(backend::REPL.REPLBackend)
╎ ╎ 8281 ...worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:150; eval_user_input(ast::Any, backend::REPL.REPLBackend)
╎ ╎ ╎ 8281 @Base/boot.jl:373; eval
╎ ╎ ╎ 8281 .../package_linux64/build/usr/share/julia/stdlib/v1.7/Profile/src/Profile.jl:28; top-level scope
1╎ ╎ ╎ 8281 REPL[18]:1; macro expansion
╎ ╎ ╎ 1 REPL[7]:3; my_sum(V::Vector{Float64})
╎ ╎ ╎ 1 @Base/abstractarray.jl:279; eachindex
╎ ╎ ╎ 8279 REPL[7]:4; my_sum(V::Vector{Float64})
╎ ╎ ╎ 8279 @Base/range.jl:837; iterate
Total snapshots: 16562