# Curious case of FFTW performance benchmarking

**URL:** <https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215>\
**Category:** Performance\
**Created:** [May 22, 2023, 12:31pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215 "2023-05-22T12:31:28Z")\
**Posts on this page:** 7\
**Page:** 1

<div class="post-metadata">

**Author:** ![vvbond](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/vvbond/32/10105_2.png) [@vvbond](https://discourse.julialang.org/u/vvbond)\
**Post date:** [May 22, 2023, 12:31pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/1 "2023-05-22T12:31:28Z")

</div>

While benchmarking FFTW’s rfft() transform, I’ve stumbled upon an interesting behaviour that I’d like to pick the collective brain about.  
The behaviour goes as follows:

1. `bm = @benchmark rfft(A,1) setup=(A=rand(Float32, nfft, howmany))` shows a bimodal times distribution:

```julia
julia> bm
BenchmarkTools.Trial: 3060 samples with 1 evaluation.
 Range (min … max): 822.167 μs … 2.177 ms ┊ GC (min … max): 0.00% … 40.78%
 Time (median): 1.013 ms ┊ GC (median): 0.00%
 Time (mean ± σ): 1.151 ms ± 309.666 μs ┊ GC (mean ± σ): 11.68% ± 16.34%

          ▁▆█▇▄▂▁ ▂▄▄▃▂ ▁
  ▃▁▁▁▁▁▁▁████████▇▄▄▄▄▃▁▁▁▁▁▃▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▃▁▁▁▄▇██████ █
  822 μs Histogram: log(frequency) by time 1.9 ms <

 Memory estimate: 3.92 MiB, allocs estimate: 27.

```

1. However, when assessing the elapsed time in a single run, `@elapsed` _always_ returns a larger figure. E.g.:

```julia
julia> A = rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.002405417

julia> A = rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.003051375

julia> A = rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.002866084

julia> A = rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.002906042

julia> A = rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.00287125 

```

The expected behaviour would be for `@elapsed` to return samples from the above bimodal distribution. This expectation turns out to be wrong. I wonder why?

1. Trying to understand, what’s going inside benchmarking, I’ve rolled out a custom loop that incorporates some sleep time between the calls to rfft(). The script is listed in the 1st comment to this post. The results are shown in the figure below  
 ![image](https://global.discourse-cdn.com/julialang/original/3X/0/8/08b6af7dcaf23bbfee43a4deb6879b4bfa712180.jpeg)  
The left subplot confirms that the custom loop’s timings agree with those obtained with the `@benchmark` macro. The right subplot shows the impact of the “nap times” on the transform’s apparent performance.

The questions which I’d love to get some help in understanding are:

1. The reason(s) for bimodal distribution of the rfft() timings.
2. The observed dependence of the rfft() timings on temporal frequency of rfft() calls.
3. Ultimately, how such observations could inform a design of a high-performance computing system.

---

<div class="post-metadata">

**Author:** ![vvbond](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/vvbond/32/10105_2.png) [@vvbond](https://discourse.julialang.org/u/vvbond)\
**Post date:** [May 22, 2023, 12:32pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/2 "2023-05-22T12:32:21Z")

</div>

The script used to produce the plots in the OP:

```julia
using FFTW, BenchmarkTools, GLMakie

nfft, howmany = 1024, 1000

@info "Benchmarking FFTW.rfft()"
bm = @benchmark rfft(A,1) setup=(A=rand(Float32, nfft, howmany))

@info "Custom loop"
n = 3000; 
te = zeros(n)

for i in 1:n
  A = rand(Float32, nfft, howmany)
  te[i] = @elapsed rfft(A,1); 
end

sleeptimes = [0.0, 0.001, 0.01]
te_sleep = zeros(n, length(sleeptimes))
for (runix, nap) in enumerate(sleeptimes)
  @show nap
  for i in 1:n
    A = rand(Float32, nfft, howmany)
    te_sleep[i, runix] = @elapsed rfft(A,1); 
    sleep(nap)
  end
end

@info "Plotting" 
fig = Figure()
ax1 = Axis(fig[1,1]; xlabel = "Iteration", ylabel = "Elapsed [s]", title = "FFTW.rfft() timings")
ax2 = Axis(fig[1,2]; xlabel = "Iteration", ylabel = "Elapsed [s]", title = "FFTW.rfft() timings")
scatter!(ax1, bm.times*1e-9, label="@benchmark")
scatter!(ax1, te, label="custom loop")
scatter!(ax2, te_sleep[:, 1], label="sleep(0.0)")
scatter!(ax2, te_sleep[:, 2], label="sleep(0.001)")
scatter!(ax2, te_sleep[:, 3], label="sleep(0.01)")
axislegend(ax1)
axislegend(ax2)
fig

```

The script was executed in the following environment:

```julia
julia> versioninfo()
Julia Version 1.9.0
Commit 8e630552924 (2023-05-07 11:25 UTC)
Platform Info:
  OS: macOS (arm64-apple-darwin22.4.0)
  CPU: 8 × Apple M1
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, apple-m1)
  Threads: 1 on 4 virtual cores
Environment:
  JULIA_EDITOR = gvim

```

---

<div class="post-metadata">

**Author:** ![jishnub](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jishnub/32/33620_2.png) [@jishnub](https://discourse.julialang.org/u/jishnub)\
**Post date:** [May 22, 2023, 12:46pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/3 "2023-05-22T12:46:08Z")

</div>

I can’t really reproduce this, but in any case, for single benchmarks, I’d use `@btime` instead of `@elapsed` to avoid random noise in the measurements.

```julia
julia> bm = @benchmark rfft(A,1) setup=(A=rand(Float32, nfft, howmany))
BenchmarkTools.Trial: 1861 samples with 1 evaluation.
 Range (min … max): 2.032 ms … 4.395 ms ┊ GC (min … max): 0.00% … 0.00%
 Time (median): 2.179 ms ┊ GC (median): 0.00%
 Time (mean ± σ): 2.246 ms ± 215.493 μs ┊ GC (mean ± σ): 2.51% ± 4.89%

    ▁▅▂ ▄█▇▄▁                                                 
  ▄▆████▇█████▆▅▄▃▃▃▃▃▂▂▂▂▃▃▃▃▄▄▃▃▅▅▄▄▃▃▃▃▂▂▂▂▁▂▂▁▁▁▁▁▂▂▁▁▂▁▂ ▃
  2.03 ms Histogram: frequency by time 3 ms <

 Memory estimate: 3.92 MiB, allocs estimate: 27.

julia> @btime rfft(A,1) setup=(A=rand(Float32, nfft, howmany));
  2.032 ms (27 allocations: 3.92 MiB)

julia> @btime rfft(A,1) setup=(A=rand(Float32, nfft, howmany));
  2.058 ms (27 allocations: 3.92 MiB)

julia> A=rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.002532687

julia> A=rand(Float32, nfft, howmany); @elapsed rfft(A, 1)
0.003060502

```

---

<div class="post-metadata">

**Author:** ![robsmith11](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/robsmith11/32/29641_2.png) [@robsmith11](https://discourse.julialang.org/u/robsmith11)\
**Post date:** [May 22, 2023, 12:49pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/4 "2023-05-22T12:49:32Z")

</div>

My guess is the variable performance is related to CPU frequency scaling. Can enable a fixed frequency and repeat the tests?

---

<div class="post-metadata">

**Author:** ![vvbond](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/vvbond/32/10105_2.png) [@vvbond](https://discourse.julialang.org/u/vvbond)\
**Post date:** [May 22, 2023, 2:04pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/5 "2023-05-22T14:04:14Z")

</div>

Well, that’s the reason for my confusion: I was expecting to observe noise, but instead found a genuine bias.

---

<div class="post-metadata">

**Author:** ![vvbond](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/vvbond/32/10105_2.png) [@vvbond](https://discourse.julialang.org/u/vvbond)\
**Post date:** [May 22, 2023, 2:13pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/6 "2023-05-22T14:13:05Z")

</div>

Good point. I’ll try to find out how to disable cpu frequency scaling on my Mac-M1.  
Should anyone have done it before, an advice would be appreciated.

---

<div class="post-metadata">

**Author:** ![vvbond](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/vvbond/32/10105_2.png) [@vvbond](https://discourse.julialang.org/u/vvbond)\
**Post date:** [May 22, 2023, 5:06pm UTC](https://discourse.julialang.org/t/curious-case-of-fftw-performance-benchmarking/99215/7 "2023-05-22T17:06:41Z")

</div>

Apparently, it is not easy to disable the frequency scaling on a Mac-M1. However, monitoring the cpus frequency did confirm your guess: when the sleep() command is involved, the cpu gets throttled.  
Thanks for that!

 ![FFTW_rfft() benchmarking 2023-05-22 at 17.46.52](https://global.discourse-cdn.com/julialang/original/3X/5/e/5e8e3f942d810a6e1de5884cc7804b07e71f9a3e.png)