# Benchmarking with @time @btime and subsequent runs return shorter execution time

**URL:** <https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580>\
**Category:** New to Julia\
**Tags:** benchmark, benchmarktools\
**Created:** [December 29, 2020, 5:47pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580 "2020-12-29T17:47:27Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![neo\_abs](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/neo_abs/32/16672_2.png) [@neo\_abs](https://discourse.julialang.org/u/neo_abs)\
**Post date:** [December 29, 2020, 5:47pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/1 "2020-12-29T17:47:27Z")

</div>

I am using @time and @btime macros to determine how my function preforms on different number of threads. I am mostly interested not in specific time but relative values. Threads aside, I noticed that the more times I run tests the faster the function gets. Below with @time:

```julia
julia> @time modeltest(mdl_init);
 20.720889 seconds (214.16 M allocations: 7.629 GiB, 31.47% gc time)
julia> @time modeltest(mdl_init);
  2.384151 seconds (174.74 M allocations: 5.730 GiB, 55.80% gc time)
julia> @time modeltest(mdl_init);
  2.171960 seconds (174.74 M allocations: 5.725 GiB, 65.92% gc time)

```

Similar outcome with @btime:

```julia
julia> @btime modeltest(mdl_init);
  6.387 s (174732441 allocations: 5.72 GiB)
julia> @btime modeltest(mdl_init);
  657.132 ms (174730885 allocations: 5.72 GiB)
julia> @btime modeltest(mdl_init);
  632.269 ms (174731867 allocations: 5.72 GiB)

```

Differences in execution times in @time and @btime aside (), where does differences between consecutive runs come from? Is Julia Compiler learning how to run function more efficiently? Or is it re-using RAM garbage?

Julia Version 1.5.3

---

<div class="post-metadata">

**Author:** ![lmiq](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lmiq/32/18314_2.png) [@lmiq](https://discourse.julialang.org/u/lmiq)\
**Post date:** [December 29, 2020, 5:56pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/2 "2020-12-29T17:56:42Z")

</div>

The difference between the first `@time` and the others is due to the fact that in the first run of the function it gets compiled. Thus, in the first run you are measuring the compilation time and its allocations.

The differences between subsequent `@time` executions (after the first one) are probably random noise.

The benchmarks with `@btime` are probably wrong, because you need to interpolate the variables there, with `$`:

```julia
@btime modeltest($mdl_init)

```

be careful also if the function `modeltest` modifies the content of `mdl_init`, because `@btime` executes the function multiple times, thus times may vary because the input is different. This may be also a reason for such a disparity in the first and subsequent calls of `@btime`.

By the way: That amount of allocations and that amount of garbage collection probably indicate that there is something wrong (type instabilities) in your code.

---

<div class="post-metadata">

**Author:** ![neo\_abs](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/neo_abs/32/16672_2.png) [@neo\_abs](https://discourse.julialang.org/u/neo_abs)\
**Post date:** [December 29, 2020, 9:33pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/3 "2020-12-29T21:33:48Z")

</div>

Additional question:

See table:

| Number of threads | Relative speed | Share of time used by Garbage Collector |
| --- | --- | --- |
| 1 | 19.89 | 4.02% |
| 4 | 8.22 | 32.55% |
| 8 | 6.76 | 46.96% |
| 16 | 4.88 | 56.88% |
| 32 | 1.31 | 69.62% |
| 64 | 1.0 | 59.17% |

Just based on a table above, without looking into code, can you tell me: does my code has problem with GC or is it `@Threads` related? Or a bit of both?

If relative speed and share of GC are multiplied the results are moreless consistent across nthreads.

---

<div class="post-metadata">

**Author:** ![lmiq](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lmiq/32/18314_2.png) [@lmiq](https://discourse.julialang.org/u/lmiq)\
**Post date:** [December 29, 2020, 9:49pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/4 "2020-12-29T21:49:52Z")

</div>

In my not so long experience, I would say that 4% of GC is not necessarily an indication of a problem, but it may be. I had a similar situation and in my case I finally found where those allocations where occuring and fixed them, making the threaded version much better. Ideally one would like a code that does not allocate anything in the performance-critical parts.

I would try to track those allocations and be sure that they are strictly necessary.

Take a look at this thread: [Track memory usage](https://discourse.julialang.org/t/track-memory-usage/52158)

---

<div class="post-metadata">

**Author:** ![neo\_abs](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/neo_abs/32/16672_2.png) [@neo\_abs](https://discourse.julialang.org/u/neo_abs)\
**Post date:** [December 30, 2020, 1:15am UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/5 "2020-12-30T01:15:24Z")

</div>

So I should expect to see increase GC given more threads?

---

<div class="post-metadata">

**Author:** ![lmiq](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lmiq/32/18314_2.png) [@lmiq](https://discourse.julialang.org/u/lmiq)\
**Post date:** [December 30, 2020, 1:20am UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/6 "2020-12-30T01:20:23Z")

</div>

That probably indicates that many allocations occur in a part of the code that is being split through the threads.

---

<div class="post-metadata">

**Author:** ![pixel27](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/pixel27/32/8902_2.png) [@pixel27](https://discourse.julialang.org/u/pixel27)\
**Post date:** [December 30, 2020, 7:31pm UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/7 "2020-12-30T19:31:57Z")

</div>

> [@neo\_abs](#):
>
> So I should expect to see increase GC given more threads?

I think the question here is, when you have 1 thread, is it doing the same number of calculations as when you have 64 threads? Or is the 64 thread version doing 64 times the number of calculations as when you have 1 thread?

To test apples to apples you would need to ensure that in the 64 thread version each thread is doing 1/64th the number of calculations as the thread in the single thread version. Otherwise you are looking at the GC time between two totally different calculations.

---

<div class="post-metadata">

**Author:** ![lmiq](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lmiq/32/18314_2.png) [@lmiq](https://discourse.julialang.org/u/lmiq)\
**Post date:** [December 31, 2020, 10:11am UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/8 "2020-12-31T10:11:19Z")

</div>

I had that kind of GC increase when I had a type instability in the container of the results of the calculation, which was copied for each thread to avoid racing conditions. It smells something like that there.

---

<div class="post-metadata">

**Author:** ![kristoffer.carlsson](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/kristoffer.carlsson/32/22_2.png) [@kristoffer.carlsson](https://discourse.julialang.org/u/kristoffer.carlsson)\
**Post date:** [December 31, 2020, 10:33am UTC](https://discourse.julialang.org/t/benchmarking-with-time-btime-and-subsequent-runs-return-shorter-execution-time/52580/9 "2020-12-31T10:33:20Z")

</div>

> [@neo\_abs](#):
>
> So I should expect to see increase GC given more threads?

Yes. Reducing allocations is quite important to speed up multi threaded code in my experience.