# Different times with @elapsed, @time and @benchmark

**URL:** <https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381>\
**Category:** Performance\
**Tags:** question\
**Created:** [September 13, 2024, 5:51pm UTC](https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381 "2024-09-13T17:51:48Z")\
**Posts on this page:** 4\
**Page:** 1

<div class="post-metadata">

**Author:** ![odddot](https://avatars.discourse-cdn.com/v4/letter/o/ecd19e/32.png) [@odddot](https://discourse.julialang.org/u/odddot)\
**Post date:** [September 13, 2024, 5:51pm UTC](https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381/1 "2024-09-13T17:51:49Z")

</div>

Hi,

I am a little confused by some results that I obtain comparing `@time`, `@elapsed` and `@benchmark`. I am aware of some differences between this macros, but I suppose that I am not really understanding what is happening here, and what should I consider a good estimate.

I have the following code:

```julia
using SparseArrays, FFTW, BenchmarkTools

function gen_matrix(n,m)
    x = rand(1:n,m); y = rand(1:n,m)
    z = ones(m)
    sparse(x,y,z,n,n)
end

function test_fft(n,m)
    A = gen_matrix(n,m)
    @elapsed fft(A)
end

```

Essentially, I want to run `fft` on some sparse matrices. The function `gen_matrix` produces a random sparse matrix for testing, whereas `test_fft` creates such a matrix and test the time of `fft` using `@elapsed`.

In what follows, all measurements are given in seconds.

Now, if I run

```julia
julia> A = gen_matrix(50,1000)
julia> @time fft(A)

```

I obtain consistent measurements of around 1e-4 seconds (the same happens if `@time` is replaced by `@elapsed`). I am aware of certain overhead due to the handling of the global variable `A`, so I also tested

```julia
julia> @benchmark fft($A)

```

and, alternatively

```julia
julia> @benchmark fft(B) setup(B=gen_matrix(50,1000))

```

In both cases I obtain a pretty narrow histogram with median around 5e-5, i.e.: half the time than reported by `@time`. So far, this looks reasonable.

The weird thing, al least for me, is that I assumed that `test_fft` should report something similar to `@benchmark`. My reasoning is that `@elapsed` does the same thing that `@time` does, but now it is running inside the local scope of `test_fft`. However… this does not happen, and `test_fft` returns consistently times of around 2e-4, i.e.: twice the time reported by `@time`. I even run `test_fft` in a loop to check this.

However, if I run:

```julia
julia> @time test_fft(50,1000)

```

I get something even weirder: `@time` reports times of around 1e-4, but the output of `test_fft` is now around 9e-5. So, the same call to `@elapsed` is returning different values (by a factor of 2) if it is run alone or under the macro `@time`.

Evidently there is something that I am missing.  
Can someone explain this behaviour?  
And more importantly: what should I take as the most reliable measument for a realistic situation, where the matrix is produced or loaded inside a function that also runs `fft`?

Thanks!

---

<div class="post-metadata">

**Author:** ![mauro3](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mauro3/32/292_2.png) [@mauro3](https://discourse.julialang.org/u/mauro3)\
**Post date:** [September 17, 2024, 11:36am UTC](https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381/2 "2024-09-17T11:36:21Z")

</div>

I think you should generate the matrix separately. I don’t know, but fft may depend on the random matrix details.

You can have a look with `@macroexpand` into what the macros are translated to. Maybe that gives some clues, in particular with respect to `@time` vs `@elapsed`.

One issue might be that `@time` is not very good with short execution times, so, I would try with larger matrices for which runtimes are around 1s.

---

<div class="post-metadata">

**Author:** ![odddot](https://avatars.discourse-cdn.com/v4/letter/o/ecd19e/32.png) [@odddot](https://discourse.julialang.org/u/odddot)\
**Post date:** [September 17, 2024, 5:08pm UTC](https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381/3 "2024-09-17T17:08:41Z")

</div>

I do not see any significant variation if I change the matrix: running the code many many times, I always obtain that `@time` reports around 1e-4 seconds. In fact, if I create the matrix using `m=100` instead of `m=1000` the results are the same.  
I have also checked `@be` (from `Chairmarks.jl`) and the results are consistent with `@benchmark` so I assume those are the most reliable measuments.  
What baffles me is the fact that the `@elapsed` inside the function returns consistently values around `2e-4` but if I run the function under `@time` the same `@elapsed` returns `9e-5`. That is weird.

---

<div class="post-metadata">

**Author:** ![dqeeq](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@dqeeq](https://discourse.julialang.org/u/dqeeq)\
**Post date:** [September 17, 2024, 8:51pm UTC](https://discourse.julialang.org/t/different-times-with-elapsed-time-and-benchmark/119381/4 "2024-09-17T20:51:01Z")

</div>

This is not an answer, but for

```julia
function test_fft2(n,m)
    A = gen_matrix(n,m)
    @time @elapsed fft(A)
end

```

I can get

```julia
julia> test_fft2(50,1000)
  0.000099 seconds (8 allocations: 78.578 KiB)
9.87e-5

```

I can also get

```julia
julia> @time test_fft2(50,1000)
  0.000089 seconds (8 allocations: 78.578 KiB)
  0.000291 seconds (41 allocations: 134.594 KiB)
8.85e-5

```

I think your last question (and my question) is: why the time of `@time @elapsed` is lower if another `@time` is also added before the function call?