# Surprising test timings

**URL:** <https://discourse.julialang.org/t/surprising-test-timings/129437>\
**Category:** Tooling\
**Tags:** testing\
**Created:** [May 29, 2025, 1:53pm UTC](https://discourse.julialang.org/t/surprising-test-timings/129437 "2025-05-29T13:53:28Z")\
**Posts on this page:** 5\
**Page:** 1

<div class="post-metadata">

**Author:** ![TimG](https://avatars.discourse-cdn.com/v4/letter/t/82dd89/32.png) [@TimG](https://discourse.julialang.org/u/TimG)\
**Post date:** [May 29, 2025, 1:53pm UTC](https://discourse.julialang.org/t/surprising-test-timings/129437/1 "2025-05-29T13:53:28Z")

</div>

When I run tests on a package I’ve been working on, the output shows (for a subset of tests):

```julia
Test Summary: | Pass Total Time
Styles | 775 775 49.0s
Test Summary: | Pass Total Time
Conditional Formats | 462 462 3.7s
  DataBar | 59 59 1.5s
  colorScale | 53 53 0.7s
  iconSet | 94 94 0.1s
  cellIs | 40 40 0.6s
  containsText | 34 34 0.1s
  top10 | 34 34 0.0s
  aboveAverage | 42 42 0.5s
  timePeriod | 37 37 0.0s
  expression | 34 34 0.0s
  containsErrors | 35 35 0.0s

```

Now, when I compare with times on a wall clock, 49 seconds is well within a factor of 2 of the actual time taken for the 775 `Styles` tests. However, the 462 `Conditional Formats` tests take 2 minutes and 45 seconds to run according to the wall clock - 45 times longer than reported!

If I wrap these two `@testset` groups with @time, the reported times agree with the time reported in the test not the wall clock time.

What might give rise to the significant difference between measured and actual elapsed time? What does such a big discrepancy for `Conditional Formats` betide?

---

<div class="post-metadata">

**Author:** ![mbauman](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mbauman/32/31082_2.png) [@mbauman](https://discourse.julialang.org/u/mbauman)\
**Post date:** [May 29, 2025, 2:08pm UTC](https://discourse.julialang.org/t/surprising-test-timings/129437/2 "2025-05-29T14:08:09Z")

</div>

If I had to guess, I’d suspect the “missing” time is all compilation time. It can sometimes be tricky to ensure compilation time gets tracked appropriately, and tests are often exercising lots of new types and functions. It’s not unlikely for one testset to have lots more compilation time than another.

Depending upon how you’ve written things — and how the `@testset` macro itself works — it can be very easy to have Julia start compiling _before_ it starts timing. The timing loop itself can get compiled! It’d probably be good for the `@testset` macro to try harder to catch this… if my guess is indeed right.

---

<div class="post-metadata">

**Author:** ![TimG](https://avatars.discourse-cdn.com/v4/letter/t/82dd89/32.png) [@TimG](https://discourse.julialang.org/u/TimG)\
**Post date:** [May 30, 2025, 8:04am UTC](https://discourse.julialang.org/t/surprising-test-timings/129437/4 "2025-05-30T08:04:17Z")

</div>

I learned yesterday ([here](https://discourse.julialang.org/t/type-instability-with-type-t-selectors-in-keyword-arguments/129439/5)):

> Keyword input types _are_ specialized for compilation (this is different from the “method specialization” where you _write_ multiple methods with varied positional arguments)

The functions in the `Conditional Formats` tests make extensive use of a mixed set of keywords to control the formatting options. There are very many combinations of different keywords possible. I guess this means that almost every invocation of each function will need compiling separately. I modelled this (very loosely) on my experience with Makie.jl.

Maybe there is a more efficient way?

---

<div class="post-metadata">

**Author:** ![jules](https://avatars.discourse-cdn.com/v4/letter/j/41988e/32.png) [@jules](https://discourse.julialang.org/u/jules)\
**Post date:** [May 31, 2025, 6:12pm UTC](https://discourse.julialang.org/t/surprising-test-timings/129437/5 "2025-05-31T18:12:27Z")

</div>

Keyword arguments in Julia are geared towards performance, while you can’t dispatch on them directly you do get specialization for each combination of types. This can be problematic if you have a ton of keyword arguments but they don’t have a big performance impact. Then you just pay for a lot of compilation.

In AlgebraOfGraphics for example, I avoid this problem by converting keyword arguments to dicts as the first step in the pipeline. That means only a tiny function gets compiled multiple times, and the big functions after that only ever see the same dict type, like `Dict{Symbol,Any}`. If you later do need type stability for a hot loop or so, you can just extract the relevant keyword from the dict in front of a function barrier. Then inside that inner function, you regain stability, but you only compile that localized part with different specializations instead of everything.

> <https://github.com/MakieOrg/AlgebraOfGraphics.jl/blob/master/src/draw.jl#L91-L95>

---

<div class="post-metadata">

**Author:** ![TimG](https://avatars.discourse-cdn.com/v4/letter/t/82dd89/32.png) [@TimG](https://discourse.julialang.org/u/TimG)\
**Post date:** [June 1, 2025, 7:06am UTC](https://discourse.julialang.org/t/surprising-test-timings/129437/6 "2025-06-01T07:06:31Z")

</div>

Thank you @jules. This is very helpful and looks like it will suit my situation well.

I have a pipeline of functions for each method. The first one chooses the desired method and then calls one or two functions resolve the function arguments into a standard form. These pre-processor functions don’t use the keyword arguments at all. In turn, they then call the main worker method, which is informed by the keywords to process the desired action.

It doesn’t sound too hard to use the first function in the pipeline to pack keywords into a `Dict` and have the workers either unpack them again or just to use them from the `Dict` directly. All but one of my keywords are strings, so I could use `Dict{String, String}` and keep the lone `Vector{Int}` out of it.

I’ll definitely give it a go!