The spill that was never on the clock

Counting blocks without counting time

A query that cannot fit a sort or a hash in memory writes the overflow to temporary files and reads it back. Everyone knows this happens, everyone knows the lever is the working-memory setting, and up to PostgreSQL 14 the server would tell you how many blocks went out and came back but not how long any of it took.

That asymmetry mattered more than it sounds, because the two numbers answer different questions. A block count tells you the plan spilled. A time tells you whether the spilling is what is making the query slow, which on a machine with a fast local disk it frequently is not, and on a machine with network-attached storage it frequently is. Without the time, the only way to weigh a working-memory increase against its memory cost was to make the change and see.

PostgreSQL 15 put temporary block I/O on the clock in two places at once: in the statements extension as a pair of new columns, and in plans as an extra term in the timing line. The Additional Modules section of the PostgreSQL 15 release notes records the first, and the second sits in the Monitoring section as a line about buffer output for temporary file block I/O.

A plan that spills, on each version

The fixture is four hundred thousand rows and a working-memory setting small enough that the sort has nowhere to go but disk. The server is running with a deliberately small buffer pool, so the scan reads from storage rather than from cache and both kinds of I/O appear in one plan.

CREATE EXTENSION pg_stat_statements;
CREATE TABLE sort_source (id bigint, label text, amount numeric);
INSERT INTO sort_source SELECT g, md5(g::text), g::numeric / 3 FROM generate_series(1, 400000) AS g;
VACUUM ANALYZE sort_source;

CREATE EXTENSION
CREATE TABLE
INSERT 0 400000
VACUUM

SET work_mem = '64kB';
SET max_parallel_workers_per_gather = 0;
EXPLAIN (ANALYZE, BUFFERS, COSTS OFF, TIMING OFF, SUMMARY OFF)
SELECT label FROM sort_source ORDER BY label;

On 14:

SET
SET
                             QUERY PLAN                             
--------------------------------------------------------------------
 Sort (actual rows=400000 loops=1)
   Sort Key: label
   Sort Method: external merge  Disk: 16864kB
   Buffers: shared hit=1901 read=2102, temp read=9988 written=10764
   I/O Timings: read=311.084
   ->  Seq Scan on sort_source (actual rows=400000 loops=1)
         Buffers: shared hit=1898 read=2102
         I/O Timings: read=311.084
 Planning:
   Buffers: shared hit=73 read=3
   I/O Timings: read=8.295
(11 rows)

On 15:

SET
SET
                            QUERY PLAN                             
-------------------------------------------------------------------
 Sort (actual rows=400000 loops=1)
   Sort Key: label
   Sort Method: external merge  Disk: 16904kB
   Buffers: shared hit=1903 read=2100, temp read=8425 written=9205
   I/O Timings: shared read=21.967, temp read=28.919 write=50.276
   ->  Seq Scan on sort_source (actual rows=400000 loops=1)
         Buffers: shared hit=1900 read=2100
         I/O Timings: shared read=21.967
 Planning:
   Buffers: shared hit=71 read=4
   I/O Timings: shared read=0.797
(11 rows)

Two things changed in that line, and the second is the one worth stopping on.

The label acquired a qualifier. What used to be a bare read and write is now explicitly shared read and shared write, because there is now something else it could be confused with.

And the something else is there: the temporary read and write times, which on 14 do not appear at all. Look at the block counts on the 14 plan and then at its timing line. Thousands of temporary blocks moved, and the timing line accounts for none of them. Every millisecond spent on the spill was outside the only I/O number the plan offered.

On this fixture the temporary read and write times together exceed the shared read time, so the spill is the larger half of the plan’s I/O cost. The two plans ran on different servers and the absolute milliseconds are not comparable between them; what is comparable is the accounting. On 14 the spill contributes nothing to the only I/O figure the plan offers. On 15 it is the biggest thing in it.

The silent part

The qualifier is why this page is marked as a quiet break rather than a clean addition.

Nothing errors. The plan is still produced, EXPLAIN still accepts the same options, and a human reading the output sees strictly more information than before. What stops working is anything that reads the output as text. A log pipeline that extracts I/O time by matching the string that used to precede the number does not match after the upgrade, and a metric derived from it goes to zero or disappears. That is the same failure mode as an absent exporter, and on a graph the two look identical.

Automatic plan capture makes this worse rather than better, because the extension that logs plans is configured once and then not looked at for years. If anything in your pipeline parses plan text, this is the release that breaks it, and the parser will not tell you.

The fix is to match on the number’s label allowing the qualifier to be present or absent, rather than to match both spellings as alternatives. Matching both hides the moment the old form stops appearing, which is the moment you would want to know you are now on the new version.

The columns, and the setting they depend on

The same two times land in the statements extension, where they are cumulative per statement rather than per execution.

SELECT temp_blk_read_time, temp_blk_write_time FROM pg_stat_statements LIMIT 1;

ERROR:  column "temp_blk_read_time" does not exist
LINE 1: SELECT temp_blk_read_time, temp_blk_write_time FROM pg_stat_...
               ^

SET work_mem = '64kB';
SET max_parallel_workers_per_gather = 0;
SELECT pg_stat_statements_reset();
\o /dev/null
SELECT label FROM sort_source ORDER BY label;
\o
SELECT temp_blks_read, temp_blks_written,
       round(temp_blk_read_time::numeric, 1)  AS temp_read_ms,
       round(temp_blk_write_time::numeric, 1) AS temp_write_ms
FROM pg_stat_statements
WHERE query LIKE 'SELECT label FROM sort_source%';

SET
SET
 pg_stat_statements_reset 
--------------------------
 
(1 row)

 temp_blks_read | temp_blks_written | temp_read_ms | temp_write_ms 
----------------+-------------------+--------------+---------------
           8425 |              9205 |         45.5 |          99.9
(1 row)

Both of those depend on I/O timing being switched on. It is off by default, and with it off the block counts are still recorded and the times are all zero, which is a state worth recognising: zero temporary I/O time alongside a large temporary block count means the timer is off, not that the spill was free.

That setting has its own cost, which is a clock reading around each operation, and the cost is genuinely machine-dependent. PostgreSQL ships a tool for measuring it on the host before you switch it on in production, and running it is a much better use of twenty seconds than arguing about the overhead from first principles.

What the number is for

The decision it supports is the working-memory one, and it turns a guess into arithmetic. A statement with a large temporary block count and a temporary I/O time that is a meaningful share of its execution time is a statement that would get faster with more working memory. A statement that spills heavily and spends almost no time doing it is a statement where raising the setting buys nothing and costs memory on every other connection.

Three habits make the columns useful rather than decorative.

• Rank by temporary I/O time as a share of total time, not by block count. The largest spiller is often not the most damaged by spilling.
• Set working memory per role or per statement rather than globally. The setting is multiplied by concurrent sort and hash nodes, and a global increase is the most common way to turn a query problem into a memory problem.
• Re-read after a change rather than assuming. The counters are cumulative, so reset the extension when you change the setting and let it accumulate a fresh window.

The block-timing columns for shared buffers gained the same qualifier treatment in the extension two releases later, when they were renamed to distinguish shared from local buffers. A fleet crossing both versions meets a quiet change here and a loud one there, and the loud one is the cheaper of the two.

The arithmetic behind the setting you are about to change

Working memory is the setting this measurement exists to inform, and it is the setting most often changed on the worst available evidence. Three properties of it decide whether a change is safe.

It is per operation, not per query. A plan with a sort feeding a hash join feeding another sort can allocate the full amount several times over, concurrently, in one statement. A parallel plan multiplies that again by the number of workers, each of which gets its own allowance. So the memory a single statement can consume is the setting multiplied by a number that is a property of its plan, and that number is not in the setting’s name.

It is per connection, so the cluster-wide exposure is that product multiplied again by how many sessions are running such a plan at once. On a pooled workload where every connection runs the same reporting query, that multiplication is the whole pool.

And it is a limit, not a reservation. Raising it costs nothing on queries that do not need it, which is what makes a global increase feel safe right up to the day several large queries arrive together.

The measurement on this page is what turns that from a gamble into a calculation. A statement whose temporary I/O time is a large share of its execution time will get faster with more memory, and the counters say how much time is available to win. A statement that spills a great deal and spends almost no time doing it will not, and raising the setting for it buys nothing while adding to the exposure above.

The safe shape of the change follows from that. Set it on the role that runs the reporting work, or in the session that runs the one statement, rather than in the configuration file. Then re-read the counters, which requires resetting the extension so the new window is clean.

Sorts and hashes behave differently here, which is worth knowing before reading a plan. A sort that exceeds the limit spills and still completes in one pass over the data if it can. A hash that exceeds it partitions the work into batches and reads its input more than once, so the block counts climb faster than the size of the data would suggest. A plan whose temporary block count is several times the size of its inputs is usually a hash, and for those the memory increase has a sharper effect.

What it costs

The columns themselves cost nothing beyond the extension already running. The timing they report costs whatever clock readings cost on your hardware, and that cost is paid whether or not any query spills, because it is the same setting that times ordinary buffer I/O.

There is no new setting, no restart and no extension upgrade needed for the plan-side change, which arrives with the server. The extension-side columns do need the extension to be at the definition that has them, which is the same one-statement step the JIT counters require and the same one that gets skipped.