@time is off by at least 10x

New to Julia
1

f1 calls f2 and f3. (this trivial logic will help with parallelization later)

f2 and f3 both mutate struct1 and struct2.

function f1!(int1,int2,struct1,struct2)
 println("\n running f2: ")
   @time f2!(int1,struct1,struct2) 
 println("\n running f3")
   @time f3!(int2,struct1,struct2)
end

for i in 1:n
println("\n running f1")
@time f1()
end

This is a sample from one iteration:

 running f1: 
 running f2: 
  0.000006 seconds (30 allocations: 4.688 KiB)
 running f3: 
  0.000005 seconds (1 allocation: 160 bytes)
  0.000170 seconds (111 allocations: 8.297 KiB)
2

What’s unintuitive here?

3

Please include all code necessary to reproduce the data (see e.g. Please read: make it easier to help you). Note also that for microbenchmarking you probably want to use the BenchmarkTools.jl package and not @time.

1 Like
4

I just don’t know how f1 can take 1.7e-4 sec when it’s constituents only take 0.1e-4 sec.

5

You’re measuring printing also. Depending on the terminal, that can be surprisingly slow. You may also be measuring compilation time.

1 Like
6

Thanks, I’ll try BenchmarkTools.
I’m not claiming @time is in any way broken, just confused.

I’ll see what I can do as far as an MWE, it’s just that f2 and f3 are both many lines, the structs are very complicated, etc.

7

Ok, I guess printing could be the culprit. Compilation time unlikely f1 is getting executed repeatedly in a loop.
Sorry, just realized that the loop structure was excluded, now fixed.
Again I’ll see what I can do about adding MWE

8

As a side note, you probably want to benchmark this instead of measuring the times only once. You can do that with using BenchmarkTools and @btime instead of @time.

1 Like