Where the time went: BUFFERS

The timing showed you what every node of the route costs. But one riddle is left: the same query on the same plan goes sometimes quickly and sometimes noticeably slower — as though the machine had moods.

QUERY leads you further into the engine room, to where the hum is steadier and the air colder. Along the walls are racks of identical containers. The station's whole archive is cut into blocks like these: pages of eight kilobytes.

QUERY: Machines do not have moods. They have a cache. A stopwatch measures the weather: a warm page is milliseconds, a cold one means waiting for the disk. Work is not measured in seconds. Work is measured in pages.

Today you add a third dimension to the timing — the input and output: how many pages the query hauled about, where it got them and how many it hauled for nothing.

Pages: the currency of input and output

Postgres never reads "one row". A table is stored in pages of 8 KB, and a page is the minimum unit of reading: whether you need one row out of it or all hundred and twenty — the whole container comes off the rack. The ls_readings log of a hundred and eighty thousand rows is 1513 pages, about a hundred and twenty rows in each.

Between the disk and the executor stands the buffer cache — an area of memory where recently touched pages live. Hence two tariffs for one and the same page:

• shared hit — the page was found in the cache. Fast: it is just memory.
• read — the page was not in the cache and had to be lifted off the disk. Slower — sometimes by orders of magnitude.

The BUFFERS flag writes these counters onto every node of the plan:

EXPLAIN (ANALYZE, BUFFERS) <your query>;

The plan turns into a map of input and output: you can see not only where a node spent its time but how many pages it hauled about to do it.

Open such a map for a familiar route — a full pass over the log. The condition is deliberately narrow — readings with the warn status, only two per cent of the log — but the log has no index on status, and the machine has one route: lift every page off the racks.

Reading the delivery note

Take apart the three lines under Seq Scan — the delivery note of this run:

• Filter: (status = 'warn') — the condition the executor checked on every row.
• Rows Removed by Filter: 176400 — the rows that were read and thrown away. The query needs 3600 rows, and the whole log was read: ninety-eight of every hundred rows lifted went into the bin. That is "read for nothing" — the chief counter of a route's wastefulness.
• Buffers: shared hit=1513 — all 1513 pages of the log. Multiply by eight kilobytes: the query shifted almost twelve megabytes to hand you a few dozen kilobytes of result. And there is the answer to the price tag from two lessons back: the scan's 3763 parrots are 1513 pages at the price of a page plus the processor's per-row work over a hundred and eighty thousand rows.

Notice: there is no read counter in the output at all. The log has just been sown by the sandbox and is hot all the way through — every page was found in the cache, so the whole pass fitted into a handful of milliseconds. In production you are not always so lucky: the first query of the morning finds the cache cold, those same 1513 pages turn from hit into read — and the time jumps several times over. The same plan, the same work — different weather. Which is why an engineer compares routes by pages rather than by the stopwatch.

A small detail: the Planning: block has Buffers of its own — those are the pages the planner itself touched while consulting the catalogue. They have nothing to do with the route.

A pinpoint run

Now the opposite pole. The only index the log already has is the index of the primary key reading_id. Ask for one specific row and the navigator will lay a route not along the racks but up the index's staircase: from storey to storey, one page per step, and at the end the single page of the log where the row itself lies.

The cell holds two commands — a device you will see constantly in this course: the first executes the query itself, and the navigator, preparing it, leafs through its catalogue pages in advance; the second takes the map of that same query. A node's own Buffers do not change with the warm-up, but without it a Planning: block with a few dozen service pages would have grown under the map. You already know they have nothing to do with the route — and a clean delivery note, four pages and nothing else, speaks louder.

Megabytes against kilobytes

Put the two delivery notes side by side. The full pass: 1513 pages — almost twelve megabytes of archive shifted. The pinpoint run: four pages — thirty-two kilobytes. Two routes to one and the same table differ in input and output by almost four hundred times.

And here is what matters: to the eye both queries are "instant" — milliseconds there, fractions of a millisecond here; a hot cache hides the difference. The stopwatch is almost blind here. The map of input and output is not: it shows the work the machine performs in any weather. A query that hauls megabytes for the sake of kilobytes is a bill that will arrive one day: on a cold morning, on a log that has grown, in the crush of neighbouring queries.

QUERY: A bad route on a warm cache is like a leak in the hold in a flat calm. Invisible. Right up to the first storm.

One detail in closing. In the first line of the full pass's map the navigator promised a few thousand rows — and almost guessed it: exactly 3600 arrived. So far the estimate and the fact are on good terms. In the next lesson you will see what happens to routes when the estimate and the fact fall out — and why that pair is the most important one on the whole blueprint.