@benchmark takes extra long time

I have found that @benchmark takes an exceptionally long (additional) time to run when the computation it is timing is more than a second or so. Here is an example:

julia> using Combinatorics

function sum_subsets(A)
   return sum(sum(S) for S in powerset(A))
end

A = rand(Int64,24);

julia> @time B = @benchmark sum_subsets(A)
 20.740046 seconds (234.92 M allocations: 23.190 GiB, 19.22% gc time, 0.11% compilation time)
BenchmarkTools.Trial: 2 samples with 1 evaluation.
 Range (min … max):  2.885 s …   2.907 s  ┊ GC (min … max): 17.20% … 16.99%
 Time  (median):     2.896 s              ┊ GC (median):    17.09%
 Time  (mean ± σ):   2.896 s ± 15.491 ms  ┊ GC (mean ± σ):  17.09% ±  0.15%

So the function takes about 2.9 seconds and it ran it twice (which makes sense since the default time is 5 seconds). But it took 20.7 seconds to do that!

julia> A = rand(Int64,26);

julia> @time B = @benchmark sum_subsets(A)
 48.963094 seconds (536.91 M allocations: 55.002 GiB, 18.00% gc time, 0.05% compilation time)
BenchmarkTools.Trial: 1 sample with 1 evaluation.
 Single result which took 12.163 s (17.08% GC) to evaluate,
 with a memory estimate of 13.75 GiB, over 134217759 allocations.

So that took 48.9 seconds to time 12.2 seconds of computation. Any idea what is going on? Obviously, for longer computations just timing a single iteration is sufficient, but I sometimes do @benchmark in a loop as a vary the size of the input and this messes up the longer computations.

1 Like

I thought that that could be caused by the ammount of allocations, but no:

julia> f(x) = sum(val^13 for val in x)
f (generic function with 1 method)

julia> x = rand(10^8);

julia> @time f(x)
  7.841366 seconds (49.89 k allocations: 2.877 MiB, 0.27% compilation time)
7.143536252636694e6

julia> @time f(x)
  7.787694 seconds (1 allocation: 16 bytes)
7.143536252636694e6

julia> @time @benchmark f($x)
 32.097185 seconds (209.24 k allocations: 10.844 MiB, 2.35% gc time, 0.49% compilation time)
BenchmarkTools.Trial: 1 sample with 1 evaluation.
 Single result which took 7.813 s (0.00% GC) to evaluate,
 with a memory estimate of 0 bytes, over 0 allocations.


Yea it does seem like this is a widespread problem now…

julia> f(x) = sum(abs2,x)
f (generic function with 1 method)

julia> @time @btime f(y) setup=(y=rand(10^5)) evals=1
  7.900 μs (0 allocations: 0 bytes)
  2.978831 seconds (210.58 k allocations: 7.460 GiB, 21.10% gc time, 0.56% compilation time)
33334.99700818058

It takes 3 seconds to time something that takes 8 microseconds.