Four ways we fooled ourselves benchmarking a database

Pileon SQL went from 2,137 ms to 15.8 ms on a GROUP BY over two million rows, and most of that came from changes to the storage layout. A surprising amount of the time was spent chasing results that were not real. Four of those cases are worth writing down, because each one looked like a code problem and was a measurement problem.

1. The laptop was in low power mode

The development machine halves its throughput when it is unplugged. The same GROUP BY took 2.1 s on mains power and 4.3 s on battery with identical code. A change that appeared to make the query twice as slow was bisected over four rebuilds before anyone checked the power setting.

The fix is procedural. Before attributing any change in speed to the code, run a known good baseline again, or run both versions inside the same power window, one after the other. If the baseline moved, the code did not cause it.

2. One process per query

The command line tool can run a single query and exit, and that is a convenient way to script a benchmark. It is also wrong for anything with lazily built state. Starting a process costs about 25 ms, and every structure the engine builds on demand is built again on each run.

The clearest case was a self-join. The engine builds a primary key to block locator once per process, by scanning all two million rows. Run one query per process and the self-join measured 204 ms. Against a server that stays up and answers many queries, the same join takes 41 ms. The server is the way the database is meant to be used, so the server is what gets measured: start it with --serve and send queries to it with --connect.

3. EXPLAIN described a plan that did not run

An optimisation was added to the function that builds query plans, and EXPLAIN showed the new plan. The timing did not change. The cause was that execution did not go through that function at all. It called the planning steps directly and chose its own path, so the printed plan and the executed plan had come apart.

After that, a plan shown by EXPLAIN was not accepted as evidence that an optimisation ran. The accepted evidence is a time, measured before and after, on a query that should be affected.

4. More threads made the scan slower

A scan of two million rows looks like an obvious fit for parallelism, and the machine has 16 cores. A COUNT(*) with the thread count varied:

Past two workers the wall time gets worse while the CPU time keeps growing, to eight times as much at 16 threads. The scan was limited by memory bandwidth and allocator contention, not by arithmetic: materialising each batch allocated a string for every text value, and the workers spent their time waiting on each other. The scan worker count was set from this curve.

The useful changes were the ones that did less work. A COUNT(*) can be answered from counts held in the catalog without reading rows, and text columns need a dictionary or borrowed values and not a new string per row.

The checklist that came out of it

• Measure on mains power, and say so.
• Take the minimum of three warm runs. A cold run measures the disk.
• Benchmark through a long running server, not a process per query.
• Time a change before and after. Do not trust the plan printer.
• Vary the thread count before adding more of it.

The results that survived these checks are on the Pileon SQL page, and the storage change behind most of them is described in the post on block storage.

Written by Caisson AI. Questions or corrections go to hello@caissonai.co.