@btime alters subsequent @time result

General Usage Performance
1

I’m trying to benchmark a struct implementation, where I encounter this. Minimal example:

using BenchmarkTools

struct S
end
(s::S)() = 1

let
    s = S()
    # @btime $s()
    @time s()
end

From which I get output 0.000000 seconds. No surprise here since the function should not have any allocations. But things change if I add @btime before @time like so:

let
    s = S()
    @btime $s()
    @time s()
end

From which I get output

  1.266 ns (0 allocations: 0 bytes)
  0.000006 seconds (8 allocations: 384 bytes)

So @time depends on previous seemingly unrelated calls.

I tried @allocated and it correctly prints out 0:

let
    s = S()
    @btime $s()
    println(@allocated s())
end

Does this mean there is a bug in @time? Did I use it wrong? Should I stop trusting it for tracking allocations? Thanks!

2

versioninfo():

julia> versioninfo()
Julia Version 1.10.2
Commit bd47eca2c8a (2024-03-01 10:14 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 12 × Intel(R) Core(TM) i7-6850K CPU @ 3.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-15.0.7 (ORCJIT, broadwell)
Threads: 1 default, 0 interactive, 1 GC (on 12 virtual cores)
3

I get the same behaviour on my system but it goes away if the code is in a function

using BenchmarkTools

struct S
end
(s::S)() = 1

function test(withbtime)
    s = S()
    withbtime && (@btime $s())
    @time s()
    return
end

test(true)
test(false)

I know that things behave slightly differently when run at global scope in the REPL so I suspect this is one of those interactions. The general advice is to always put your code in a function, especially when benchmarking and I guess this is one of the reasons why.

1 Like
4

According to the doc, let block is local scope as in a function.

5

I’m not sure where the funny business is coming from, but there’s definitely something funny here.

julia> begin
       @benchmark nothing
       @time 1
       @time 1
       @time 1
       end
  0.000004 seconds (8 allocations: 384 bytes)
  0.000001 seconds (7 allocations: 368 bytes)
  0.000004 seconds (8 allocations: 384 bytes)
1
2 Likes
6

Wow, thank you, this is a much better minimal example.

7

I think this is a bug, so I opened an issue on GitHub `@btime` alters subsequent `@time` result · Issue #53694 · JuliaLang/julia · GitHub
Maybe we can discuss over there. Thanks everyone!

1 Like