A/B timings on a busy shared machine both hide and fake regressions
Symptom#
An A/B benchmark of two builds of the same program gives results that change from run to run:
- One run showed differences of -18% to +19% on queries that the code change did not touch.
- Another case showed +3.3%, then a steady-looking +5% at a lower load, with the new build slower in nearly every run. A third run with per-phase timing showed no regression: the gap came from a step whose time varies by more than 10x from run to run in both builds.
Cause#
Other users and apps on the machine (7 or 8 logged-in users, browsers, sync tools) raise the load average to 15 to 42. Under that load, the time of each run depends more on the load than on the code. A median of a few runs can move either way, and overlapping ranges cannot tell noise from a small real change.
A step with large natural variance can also fake a steady difference over a few runs. In dftracer-utils the RocksDB compaction after an aggregated build took 0.6 s to 9.7 s in both builds, which is larger than the effect being measured.
Other work by the agent adds load too: rebuilding one of the benchmarked binaries replaces it between rounds and adds a heavy compile, and rkb search or rkb add run the laya reranker model. Rounds that ran during such work are not valid.
Fix#
- Run
uptimeat the start and end of every benchmark and record the load average with the numbers. - Interleave the builds (A, B, A, B, ...) so that load changes hit both builds alike.
- Look at the per-run times of each build, not only the medians. A build that is slower in nearly every run is a lead, not a proof: before you call it a regression, time the phases of one run (temporary log lines around each step) and check that one phase is slower in every run of that build.
- When the load average is well above the number of free cores, or the ranges overlap, rerun the case in question when the machine is quieter before you call it noise or a regression.
- Do not build, test, run
rkbsearches or start other heavy work while a benchmark runs. Stop the benchmark before you rebuild its binaries, and discard the rounds that ran during other work. A run whose every phase is slower (for example a parse that took 66 s instead of 25 s) was slowed from outside the process.
Evidence#
- dftracer-utils
index_benchA/B, stage 8: at load average above 15, queries moved by -18% to +19%; the rerun at load about 7 moved by at most 2.7%. - Stage 10a aggregated build, 4 rounds at load 25 to 42: A median 29.88 s, B 30.86 s (+3.3%), ranges A 28.25 to 32.47 s and B 29.15 to 33.2 s.
- Rerun at load about 11: A 28.1 to 28.95 s (median 28.51), B 28.36 to 30.57 s (median 29.93). B was slower in nearly every run, which looked like a real regression.
- During that rerun, both release binaries were rebuilt with timing logs; the rerun was stopped and its later rounds discarded.
- Third run with per-phase timing, 4 interleaved rounds: the merge took 1 to 6 ms and the time-bounds write about 1 ms in both builds, and the compaction took 0.6 to 9.7 s in both. The two B runs of round 2 took 72.8 s and 90.7 s because every phase slowed while
rkbcommands ran; without round 2, the medians were A 34.6 s and B 33.0 s. So there was no regression.