Unreliable Benchmarks

[krakow10]

It seems to me that a couple of the benchmarks toggle between one of two speeds randomly, notably "1,000 Parts/Deserialize" (±70%) and maybe "100 100-line ModuleScripts/Serialize" (±10%). Have you also experienced this? I'm not sure how to go about debugging this.

[Dekkonot]

In a Windows 10 system with the following specs:

• Ryzen 7840HS @ 3.80GHz
• 32 GB of DDR5 @ 5600 MHz

I'm not experiencing this noise. All of the benchmarks are within 5% of eachother except for the Miner's Haven deserialize benchmark, which is within 10%. That one is probably something we should fix.

Probably what you are seeing is the consequence of other stuff happening in the background of your system, which introduces noise.

I generally run benchmarks with everything possible on the system closed (including background processes like Steam and Discord) and in a single terminal window. If you're running it with an embedded shell like the one in VSCode, or with an editor or browser open in the background you will probably see noise that is caused by things like your system allocator or CPU scheduler. You might even see them caused by interrupts from input devices if the benchmark is sensitive enough.

If you close everything and run them without touching your computer, is there still this level of noise? If so, can you give your system stats?

[krakow10]

I'm running the benches with the following specs:

• Arch Linux
• 5950X
• 48GB DDR4 3200Mhz (3 sticks, 1 broken slot)

The background process noise floor is currently sitting at 0.5-1.0%.
I could imagine background processes affecting the benchmark by a few percent, but 70%?

Here's how I'm testing:

git checkout master
cargo bench
git checkout entry
cargo bench

Here's the results from the entry branch:

     Running benches/suite/main.rs (target/release/deps/suite-4220ebfc15de915e)
Gnuplot not found, using plotters backend
100 Folders/Serialize   time:   [20.455 µs 20.477 µs 20.498 µs]
                        thrpt:  [36.802 MiB/s 36.840 MiB/s 36.879 MiB/s]
                 change:
                        time:   [-3.6020% -3.3558% -3.1167%] (p = 0.00 < 0.05)
                        thrpt:  [+3.2169% +3.4723% +3.7366%]
                        Performance has improved.
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild
100 Folders/Deserialize time:   [37.694 µs 37.746 µs 37.803 µs]
                        thrpt:  [19.223 MiB/s 19.252 MiB/s 19.279 MiB/s]
                 change:
                        time:   [-0.4182% -0.2624% -0.1033%] (p = 0.00 < 0.05)
                        thrpt:  [+0.1034% +0.2631% +0.4200%]
                        Change within noise threshold.
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe

100 Deep Folders/Serialize
                        time:   [23.105 µs 23.120 µs 23.136 µs]
                        thrpt:  [32.605 MiB/s 32.628 MiB/s 32.650 MiB/s]
                 change:
                        time:   [-0.4973% -0.3704% -0.2301%] (p = 0.00 < 0.05)
                        thrpt:  [+0.2306% +0.3718% +0.4998%]
                        Change within noise threshold.
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe
100 Deep Folders/Deserialize
                        time:   [43.330 µs 43.370 µs 43.419 µs]
                        thrpt:  [16.759 MiB/s 16.778 MiB/s 16.793 MiB/s]
                 change:
                        time:   [-0.1932% +0.1867% +0.4962%] (p = 0.31 > 0.05)
                        thrpt:  [-0.4937% -0.1864% +0.1936%]
                        No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
  2 (2.00%) low mild
  1 (1.00%) high mild
  1 (1.00%) high severe

100 100-line ModuleScripts/Serialize
                        time:   [78.498 µs 78.603 µs 78.717 µs]
                        thrpt:  [46.862 MiB/s 46.930 MiB/s 46.993 MiB/s]
                 change:
                        time:   [-11.260% -10.969% -10.754%] (p = 0.00 < 0.05)
                        thrpt:  [+12.050% +12.320% +12.688%]
                        Performance has improved.
Found 5 outliers among 100 measurements (5.00%)
  4 (4.00%) high mild
  1 (1.00%) high severe
100 100-line ModuleScripts/Deserialize
                        time:   [153.74 µs 153.94 µs 154.21 µs]
                        thrpt:  [23.655 MiB/s 23.696 MiB/s 23.727 MiB/s]
                 change:
                        time:   [-0.0828% +0.1823% +0.4055%] (p = 0.15 > 0.05)
                        thrpt:  [-0.4038% -0.1820% +0.0829%]
                        No change in performance detected.
Found 5 outliers among 100 measurements (5.00%)
  2 (2.00%) low mild
  1 (1.00%) high mild
  2 (2.00%) high severe

1,000 Parts/Serialize   time:   [1.7486 ms 1.7585 ms 1.7705 ms]
                        thrpt:  [2.3642 MiB/s 2.3803 MiB/s 2.3937 MiB/s]
                 change:
                        time:   [-1.0634% -0.4168% +0.2830%] (p = 0.22 > 0.05)
                        thrpt:  [-0.2822% +0.4185% +1.0748%]
                        No change in performance detected.
Found 8 outliers among 100 measurements (8.00%)
  1 (1.00%) high mild
  7 (7.00%) high severe
1,000 Parts/Deserialize time:   [1.8428 ms 1.9021 ms 1.9724 ms]
                        thrpt:  [2.0602 MiB/s 2.1363 MiB/s 2.2052 MiB/s]
                 change:
                        time:   [-39.857% -37.865% -35.608%] (p = 0.00 < 0.05)
                        thrpt:  [+55.300% +60.941% +66.271%]
                        Performance has improved.
Found 10 outliers among 100 measurements (10.00%)
  1 (1.00%) high mild
  9 (9.00%) high severe

Benchmarking Miner's Haven/Serialize: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 15.6s, or reduce sample count to 30.
Miner's Haven/Serialize time:   [154.85 ms 155.54 ms 156.32 ms]
                        thrpt:  [48.447 MiB/s 48.688 MiB/s 48.905 MiB/s]
                 change:
                        time:   [-3.4432% -2.5878% -1.8454%] (p = 0.00 < 0.05)
                        thrpt:  [+1.8801% +2.6565% +3.5660%]
                        Performance has improved.
Found 8 outliers among 100 measurements (8.00%)
  3 (3.00%) high mild
  5 (5.00%) high severe
Benchmarking Miner's Haven/Deserialize: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 24.8s, or reduce sample count to 20.
Miner's Haven/Deserialize
                        time:   [238.36 ms 240.09 ms 242.61 ms]
                        thrpt:  [31.249 MiB/s 31.578 MiB/s 31.806 MiB/s]
                 change:
                        time:   [-0.8028% -0.0274% +1.1035%] (p = 0.96 > 0.05)
                        thrpt:  [-1.0914% +0.0274% +0.8093%]
                        No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
  3 (3.00%) high severe

[kennethloeffler]

As Micah mentioned, there are many factors that can influence the data the benchmarks collect. The fact that results fluctuate between two different speeds for you suggests that your processor might be clocking up or clocking down during the runs. You can probably change frequency scaling settings in your OS to get more consistent results from the benchmarks.

[krakow10]

After reading your analysis, I was convinced that the root cause could be the cpu governor and tried it out as I mentioned in #525 (comment). However, the issue persisted and the tests I did then showed that the issue was not present on my properties branch on #525.

Today I revisited it seeking vengeance upon ustr. I ran 5 benchmarks on commit 9739d9f, which is just before ustr was added, and they were within 10%. I then proceeded to bisect the issue over the course of a few hours with the aid of watching television. As much as I wanted it to be commit 942531f, that was not it. I think I ran 15 benchmarks to try to force the issue. Lo and behold, the true culprit was 9cbfcd5, which explains why the properties branch does not evince the issue because it effectively reverts that change.

It is noteworthy that the issue only happens when running the full benchmark suite with cargo bench, it does not happen with just cargo bench "1,000 Parts/Deserialize". This leads me to believe it is related to the state of the global cache in ustr. Perhaps it actually is quadratic hashtable behaviour like I mentioned before? Or perhaps the extremely bare bones inlined hashtable implementation in ustr is lopsided sometimes, and this amplified by decoding 1000 identical parts? InstanceBuilder.has_property? If it can actually be traced back to ustr, it's worth reporting upstream.

[krakow10]

The issue is not because of ustr. In #533 ustr is dropped entirely, and the issue persists. This affirms (or at least does not dispute) my above result that the issue is 9cbfcd5.

[krakow10]

I was still seeing this as recently as yesterday, but I found a new tool called cpupower-gui, and when I set it to "performance" I can no longer reproduce the ±70% or even ±10% benchmarking issues. I ran the master branch benchmarks at least 20 times. I'm going to ignore the reproducibility of the issue being resolved on the #525 branch and assume that was because of the different build tickling the cpu performance governor in just the right way, and close this as user error. It was all in my headcpu.