Adding unrelated code affects benchmark

[ChristopherBiscardi]

Heya! I've been doing advent-of-code and trying out Divan while doing so. Someone showed me some code and I added it to my project to benchmark. Simply adding the code to lib.rs caused one of my benchmarks to rise by 100 microseconds. Commenting or uncommenting this one line (which is not used in the benchmark) in lib.rs causes the part2_nom benchmark to inflate or deflate accordingly.

// pub mod part2_subject;

I've pared the example down as much as I could at the moment. I can try to make a smaller one if I have more time.

https://github.com/ChristopherBiscardi/advent-of-code/tree/divan-benchmark-inflation

This should be enough to run the benchmarks:

cargo bench -p day-01

---

benchmarks with subject module

day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               35.7 µs       │ 93.41 µs      │ 36.14 µs      │ 37.26 µs      │ 100     │ 100
├─ part2               134.3 µs      │ 163.5 µs      │ 134.7 µs      │ 137.1 µs      │ 100     │ 100
├─ part2_aho_corasick  26.7 ms       │ 37.09 ms      │ 27.08 ms      │ 27.31 ms      │ 100     │ 100
├─ part2_nom           467.4 µs      │ 568.4 µs      │ 472.3 µs      │ 480.6 µs      │ 100     │ 100
╰─ part2_subject       135.7 µs      │ 183.7 µs      │ 136.2 µs      │ 138.5 µs      │ 100     │ 100

benchmarks without subject module

day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               33.58 µs      │ 99.66 µs      │ 33.99 µs      │ 35.05 µs      │ 100     │ 100
├─ part2               134.9 µs      │ 222.4 µs      │ 139.5 µs      │ 141.3 µs      │ 100     │ 100
├─ part2_aho_corasick  27.6 ms       │ 29.34 ms      │ 28.48 ms      │ 28.41 ms      │ 100     │ 100
╰─ part2_nom           361.2 µs      │ 455.5 µs      │ 375.9 µs      │ 378.3 µs      │ 100     │ 100

Here's each run side-by-side for ease of viewing

├─ part2_nom           467.4 µs      │ 568.4 µs      │ 472.3 µs      │ 480.6 µs      │ 100     │ 100
╰─ part2_nom           361.2 µs      │ 455.5 µs      │ 375.9 µs      │ 378.3 µs      │ 100     │ 100

[nvzqz]

Is the increase of 100µs consistent across multiple cargo bench invocations?

---

Also, I noticed the spike of downloads yesterday and found your AoC video. Thanks for trying it out! Currently in the growing pains phase. 😄

[ChristopherBiscardi]

The increase is consistent but I wasn't tracking the exact amount closely enough to say whether it was (for example) 100µs vs 130µs and such. It was not wildly fluctuating. At the very least I ran it multiple times in each configuration, in a row, one after the other, etc, etc. and the results seemed very consistent to me over many runs.

Also, I noticed the spike of downloads yesterday and found your AoC video. Thanks for trying it out! Currently in the growing pains phase. 😄

oh fun! glad I could point some people in your direction.

[nvzqz]

This might be a bit of work on your end, but could you please check if the same happens with Criterion?

[polarathene]

check if the same happens with Criterion?

I've encountered a similar experience and have provided a reproduction here with both divan and criterion consistently demonstrating a perf regression.

I've had some other users clone that and observe the same.

My reproduction is fairly simple, just copying a function that isn't used at all introduces a consistent overhead in timings measured on the actual benched function. I suspect it's due to compiler optimizations like this Criterion FAQ entry explains.

The reproduction I've linked identifies several changes that can be made to avoid the regression, so this sort of issue is unlikely anything to do with Divan (Criterion measures the same increase in timing).

[ChristopherBiscardi]

I've confirmed that the behavior does exist in divan and criterion. It is only for this one benchmark (part2_nom from 375 to 497). The other 3 benchmarks appear stable.

The relevant commit is: https://github.com/ChristopherBiscardi/advent-of-code/tree/26ae09c876602e405dc7943ef61764afd70d8838

Runs without part2_subject

run 1

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               39.95 µs      │ 98.29 µs      │ 40.33 µs      │ 41.24 µs      │ 100     │ 100
├─ part2               138.4 µs      │ 174.5 µs      │ 143.2 µs      │ 143.6 µs      │ 100     │ 100
├─ part2_aho_corasick  27.87 ms      │ 30.93 ms      │ 28.52 ms      │ 28.49 ms      │ 100     │ 100
╰─ part2_nom           365.5 µs      │ 522.1 µs      │ 376.2 µs      │ 380.4 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [28.212 µs 28.595 µs 28.999 µs]
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe

part2/part2             time:   [142.92 µs 143.11 µs 143.31 µs]
Found 11 outliers among 100 measurements (11.00%)
  2 (2.00%) low severe
  5 (5.00%) low mild
  4 (4.00%) high mild
part2/part2_nom         time:   [380.46 µs 380.83 µs 381.27 µs]
Found 5 outliers among 100 measurements (5.00%)
  3 (3.00%) low mild
  2 (2.00%) high mild
part2/part2_aho_corasick
                        time:   [28.350 ms 28.382 ms 28.413 ms]
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) low mild

run 2

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               38.16 µs      │ 61.91 µs      │ 45.79 µs      │ 44.69 µs      │ 100     │ 100
├─ part2               138.2 µs      │ 178 µs        │ 144.7 µs      │ 144.4 µs      │ 100     │ 100
├─ part2_aho_corasick  27.86 ms      │ 29.82 ms      │ 28.43 ms      │ 28.4 ms       │ 100     │ 100
╰─ part2_nom           359.7 µs      │ 507.4 µs      │ 374.2 µs      │ 377.3 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [28.309 µs 28.927 µs 29.598 µs]
                        change: [-3.7815% -1.2474% +1.3855%] (p = 0.35 > 0.05)
                        No change in performance detected.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild

part2/part2             time:   [143.46 µs 143.75 µs 144.06 µs]
                        change: [-0.0243% +0.2199% +0.4712%] (p = 0.11 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  3 (3.00%) low mild
  1 (1.00%) high mild
  3 (3.00%) high severe
part2/part2_nom         time:   [380.39 µs 383.26 µs 389.43 µs]
                        change: [-0.3633% +1.0289% +4.5633%] (p = 0.63 > 0.05)
                        No change in performance detected.
Found 10 outliers among 100 measurements (10.00%)
  9 (9.00%) low mild
  1 (1.00%) high severe
part2/part2_aho_corasick
                        time:   [28.401 ms 28.442 ms 28.483 ms]
                        change: [+0.0227% +0.2104% +0.3871%] (p = 0.02 < 0.05)
                        Change within noise threshold.

run 3

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               40.83 µs      │ 86.7 µs       │ 44.54 µs      │ 44.97 µs      │ 100     │ 100
├─ part2               138.7 µs      │ 173.4 µs      │ 144.3 µs      │ 144.2 µs      │ 100     │ 100
├─ part2_aho_corasick  27.6 ms       │ 28.76 ms      │ 28.43 ms      │ 28.37 ms      │ 100     │ 100
╰─ part2_nom           352.9 µs      │ 466.9 µs      │ 375.9 µs      │ 377.4 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [27.161 µs 27.608 µs 28.093 µs]
                        change: [-3.5336% -1.2345% +1.0798%] (p = 0.32 > 0.05)
                        No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild

part2/part2             time:   [143.06 µs 143.35 µs 143.69 µs]
                        change: [-0.3984% -0.0981% +0.2096%] (p = 0.54 > 0.05)
                        No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  1 (1.00%) high severe
part2/part2_nom         time:   [380.71 µs 382.71 µs 385.95 µs]
                        change: [-3.1649% -0.2636% +1.6587%] (p = 0.88 > 0.05)
                        No change in performance detected.
Found 16 outliers among 100 measurements (16.00%)
  3 (3.00%) low severe
  4 (4.00%) low mild
  2 (2.00%) high mild
  7 (7.00%) high severe
part2/part2_aho_corasick
                        time:   [28.366 ms 28.411 ms 28.465 ms]
                        change: [-0.3222% -0.1083% +0.1199%] (p = 0.36 > 0.05)
                        No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high severe

with part2_subject module

run 1 (immediately after the above runs)

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               27.79 µs      │ 107.9 µs      │ 30.87 µs      │ 35.63 µs      │ 100     │ 100
├─ part2               144.7 µs      │ 188 µs        │ 151.7 µs      │ 153.8 µs      │ 100     │ 100
├─ part2_aho_corasick  27.58 ms      │ 35.72 ms      │ 28.48 ms      │ 28.71 ms      │ 100     │ 100
╰─ part2_nom           482.2 µs      │ 583.9 µs      │ 498.6 µs      │ 500.6 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [28.547 µs 29.003 µs 29.489 µs]
                        change: [+0.9037% +2.8745% +4.8163%] (p = 0.01 < 0.05)
                        Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild

part2/part2             time:   [142.86 µs 143.10 µs 143.35 µs]
                        change: [-0.3534% -0.0867% +0.1954%] (p = 0.54 > 0.05)
                        No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  1 (1.00%) high severe
part2/part2_nom         time:   [499.69 µs 500.21 µs 500.70 µs]
                        change: [+28.932% +30.226% +31.214%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) low severe
  1 (1.00%) low mild
part2/part2_aho_corasick
                        time:   [28.407 ms 28.752 ms 29.277 ms]
                        change: [-0.0030% +1.1999% +3.2000%] (p = 0.13 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  2 (2.00%) low mild
  4 (4.00%) high severe

run 2

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               30.16 µs      │ 62.62 µs      │ 35.16 µs      │ 34.57 µs      │ 100     │ 100
├─ part2               136.1 µs      │ 169.4 µs      │ 144.7 µs      │ 143 µs        │ 100     │ 100
├─ part2_aho_corasick  27.24 ms      │ 28.73 ms      │ 28.41 ms      │ 28.3 ms       │ 100     │ 100
╰─ part2_nom           476.4 µs      │ 590.2 µs      │ 497.7 µs      │ 497.1 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [28.270 µs 28.877 µs 29.482 µs]
                        change: [-0.4674% +1.7851% +4.1144%] (p = 0.15 > 0.05)
                        No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
  3 (3.00%) high mild

part2/part2             time:   [142.71 µs 143.41 µs 144.72 µs]
                        change: [-0.4805% +0.4224% +1.7963%] (p = 0.57 > 0.05)
                        No change in performance detected.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) low mild
  1 (1.00%) high mild
  3 (3.00%) high severe
part2/part2_nom         time:   [499.59 µs 500.15 µs 500.68 µs]
                        change: [-0.2440% +0.0456% +0.3362%] (p = 0.76 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  3 (3.00%) low severe
  3 (3.00%) low mild
  1 (1.00%) high mild
part2/part2_aho_corasick
                        time:   [28.454 ms 28.580 ms 28.727 ms]
                        change: [-2.4332% -0.5968% +0.7186%] (p = 0.55 > 0.05)
                        No change in performance detected.
Found 12 outliers among 100 measurements (12.00%)
  2 (2.00%) low mild
  3 (3.00%) high mild
  7 (7.00%) high severe

run 3

Timer precision: 41 ns
day_01                 fastest       │ slowest       │ median        │ mean          │ samples │ iters
├─ part1               28.12 µs      │ 62.58 µs      │ 28.43 µs      │ 33.28 µs      │ 100     │ 100
├─ part2               139.3 µs      │ 184.6 µs      │ 145 µs        │ 145.7 µs      │ 100     │ 100
├─ part2_aho_corasick  27.9 ms       │ 28.93 ms      │ 28.44 ms      │ 28.39 ms      │ 100     │ 100
╰─ part2_nom           477 µs        │ 574.4 µs      │ 497.4 µs      │ 494.9 µs      │ 100     │ 100

     Running benches/benchmarks-criterion.rs (target/release/deps/day_01_bench_criterion-c9c1d8429cb6331d)
part1/part1             time:   [28.404 µs 28.897 µs 29.428 µs]
                        change: [-3.9832% -1.6333% +0.8383%] (p = 0.20 > 0.05)
                        No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
  4 (4.00%) high mild

part2/part2             time:   [143.02 µs 143.89 µs 144.99 µs]
                        change: [-1.6549% -0.2855% +0.7242%] (p = 0.70 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  3 (3.00%) low mild
  3 (3.00%) high severe
part2/part2_nom         time:   [499.47 µs 500.23 µs 501.16 µs]
                        change: [-0.0951% +0.2081% +0.5882%] (p = 0.22 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  3 (3.00%) high mild
  1 (1.00%) high severe
part2/part2_aho_corasick
                        time:   [28.380 ms 28.436 ms 28.498 ms]
                        change: [-1.0464% -0.5065% -0.0087%] (p = 0.06 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  4 (4.00%) high severe