Explain Analyze is a sample-size of One

Summary for the Impatient

SELECT id FROM events WHERE tenant_id = 42 LIMIT 20 on a 1.5M-row, 249 MB table with no index on tenant_id. Run once: 78 ms, 1,485,000 rows removed by the filter, about 31,600 buffers touched, every one of them already in shared_buffers. Run again: 0.07 ms, 552 rows removed, 14 buffers. Nothing got cached between the two runs that wasn't cached before. The table was bigger than a quarter of shared_buffers, and above that line Postgres starts each new sequential scan where the previous one stopped (synchronize_seqscans, on by default). Ten runs with a standard deviation on every plan node made it visible without anyone having to guess: Execution Time: avg=7.86 ms stddev=24.63, a standard deviation three times the mean, which for n=10 is the fingerprint of exactly one run being different from the rest. The per-run samples on that line are 77.97, 0.07, 0.07, 0.07, 0.07, 0.07, 0.06, 0.07, 0.12, 0.06. SET synchronize_seqscans = off collapsed the stddev to 1.3% and made every run 80.8 ms. Two scans inside one statement returned different rows, with nothing writing. One EXPLAIN ANALYZE is a sample size of one. The rest of this post is about why that matters, and how to read the dispersion once you have more than one.

You run a query. 78 milliseconds. You run it again, because that is what everyone does, and it comes back in 0.07 milliseconds. You know what that is. The cache warmed up. First run cold, second run hot, story over, and you write down the second number because that is the "steady state."

Here is what the slow run's plan says, with BUFFERS. (These lines are from a control run described below in which all ten executions are forced to behave like the first one, so the numbers are exact rather than inferred; the avg= grammar is explained in a moment.)

Seq Scan on events
Filter: (tenant_id = 42)
Rows Removed by Filter: avg=1485000
Buffers: shared avg_hit=31598 -- read=[should be here!]
Execution Time: avg=80.84 ms stddev=1.06 n=10 samples=80.17,81.27,80.5,80.3,82.32,81.65,82.49,80.64,79.37,79.71

Every buffer is a hit. There is no read= on that line. Every one of the 31,598 pages the slow run touched was already in shared_buffers before it started. The first run was not slow because the data was cold. It was slow because it started at the beginning of the table, and the second run did not, because the table remembers where the last scan stopped.

I want to use this one query to make a broader point, because the mechanism is a good story but the method is the thing that transfers.

A single EXPLAIN ANALYZE is a sample size of one

Every number in an EXPLAIN ANALYZE is a single draw. We do not usually think of it that way, because the plan looks deterministic: the same SQL, the same data, the same planner, so surely the same numbers, give or take some noise. But between two executions of an identical statement against an identical database, a surprising amount of state can change, and none of it announces itself in the plan text:

• The plan cache. A prepared statement (which is what your driver is doing on your behalf, whether or not you asked) runs five custom plans and then may switch to a generic one. The sixth execution can have a different plan from the first five.
• Statistics. Autoanalyze can land between two runs. The next run re-plans on new numbers.
• The visibility map. Any UPDATE clears the all-visible bit on the pages it touches; an Index Only Scan that reported Heap Fetches: 0 starts fetching.
• Physical layout. Repeated writes grow the heap, break HOT chains, emit full-page images after a checkpoint. The first UPDATE you time is the cheapest one you will ever get.
• Hint bits. The first reader of a bulk-loaded table sets them and dirties pages. A SELECT that writes.
• The shared scan position. The subject of this post.
• Parallel scheduling, JIT compilation time, and ordinary platform noise.

Postgres itself already treats execution time as a distribution. pg_stat_statements gives you min_exec_time, max_exec_time, mean_exec_time, and stddev_exec_time for every normalized statement, and has for years. Almost nobody reads the last two. And EXPLAIN ANALYZE, the tool we actually use when a specific query is slow, gives you one draw with no error bar at all.

So the question is: if you run it N times, what do the aggregate statistics tell you that one run cannot? The answer is more interesting than "the mean is more accurate," and the rest of this post is one worked example.

How to read a standard deviation on a plan

Suppose you have N executions and a mean and a sample standard deviation of some quantity, say execution time. A large stddev is produced by very different histories, and the stddev alone will not tell you which. But the ratio of stddev to mean is a usable fingerprint. For a step of size M among otherwise-equal runs:

What actually happened across N runs	mean	stddev	stddev / mean	If you double N
Nothing; ordinary noise	the level	small	a few percent	unchanged
One run paid M, the rest paid ~0	M / N	≈ M / √N	≈ √N (3.2 for N = 10)	mean halves
A steady ramp from 0 to M	M / 2	≈ 0.29 M	≈ 0.58	mean grows
Two regimes, split at a fixed run	somewhere between them	≈ half the gap	0.2 to 1.0	mean drifts toward the late regime

Two of those rows are worth memorizing. A stddev/mean near √N means one run was different. A stddev/mean near 0.6 that grows when you add runs means something is accumulating. Neither is noise, and neither is visible in a single run, and both are common in databases because the state list above is a list of things that happen once (first run) or accumulate (every run).

That table is not about any particular tool. You can compute it from pg_stat_statements on a production system. You can compute it from a psql loop. I happened to compute it from an instrument that puts avg and stddev on every line of an EXPLAIN ANALYZE, which is how I found the example below.

The experiment

A 1.5-million-row table, about 170 bytes per row, so roughly 250 MB. No index on tenant_id. Tenant 42 owns exactly the last 1% of ids, so its rows sit physically at the end of the heap. (That clustering is what makes the effect large; it is also perfectly ordinary: anything inserted in time order that filters on something correlated with time has this shape.)

CREATE TABLE events (
  id         INT PRIMARY KEY,
  tenant_id  INT NOT NULL,
  created_at TIMESTAMP NOT NULL,
  payload    TEXT NOT NULL
);
-- tenant 42 owns the LAST 1% of ids: physically clustered at the end of the heap
INSERT INTO events
SELECT i,
       CASE WHEN i > (1500000 * 0.99)::int THEN 42 ELSE 1 + (i % 41) END,
       NOW() - (i * interval '1 second'),
       repeat('x', 120)
FROM generate_series(1, 1500000) i;
VACUUM ANALYZE;

The query, with parallelism off so there is exactly one scan to reason about:

SET max_parallel_workers_per_gather = 0;
EXPLAIN (ANALYZE, BUFFERS) SELECT id FROM events WHERE tenant_id = 42 LIMIT 20;

Platform: shared_buffers = 456 MB. That number matters: a quarter of it is 114 MB, or 14,592 pages, and the table is 31,915 pages. We are above the line.

I ran the statement ten times on one connection with no warm-up, and rendered the ten plans as one plan with the mean, the sample standard deviation, and the per-run samples on every number. Here are the lines that move. Sample lists on costs and widths are flat, so they are not in this block. The card under it is the payload, worker id included.

Limit  (avg_cost=0.00..61.79 avg_rows=20 avg_width=4) (actual avg_time=7.840..7.845 stddev_time=24.629..24.629 avg_rows=20 avg_loops=1)
  Buffers: shared avg_hit=3172.4 stddev_hit=9987.7 samples_hit=31598,14,14,14,14,14,14,14,14,14
  ->  Seq Scan on events  (avg_cost=0.00..50665.06 avg_rows=16400 avg_width=4) (actual avg_time=7.840..7.842 stddev_time=24.629..24.629 avg_rows=20 avg_loops=1)
        Filter: (tenant_id = 42)
        Rows Removed by Filter: avg=148996.8 stddev=469423.675 samples=1485000,552,552,552,552,552,552,552,552,552
        Buffers: shared avg_hit=3172.4 stddev_hit=9987.7 samples_hit=31598,14,14,14,14,14,14,14,14,14
Planning Time: avg=0.06 ms stddev=0.02 n=10 samples=0.11,0.06,0.05,0.05,0.08,0.05,0.04,0.04,0.05,0.03
Execution Time: avg=7.86 ms stddev=24.63 n=10 samples=77.97,0.07,0.07,0.07,0.07,0.07,0.06,0.07,0.12,0.06

Nothing about the shape changed. Ten times: Limit over Seq Scan, same filter. If you were looking for a plan flip, there is nothing to see. Now read the dispersion:

• Execution Time: avg=7.86 stddev=24.63. stddev / mean = 3.13. √10 = 3.16. One run was different. The samples name it: 77.97 ms, then nine runs from 0.06 ms to 0.12 ms.
• Rows Removed by Filter: avg=148996.8. Multiply by 10: 1,489,968. The table has 1,485,000 non-tenant-42 rows. One run removed the whole table's worth of rows; nine runs removed 552 each (1,489,968 − 1,485,000 = 4,968; 4,968 / 9 = 552). The sample list is that arithmetic written out: 1485000 once, then 552 nine times.
• Buffers: shared avg_hit=3172.4. Times 10 is 31,724. The heap is 31,915 pages. One run read the heap; nine runs read 14 pages. The samples are 31598 once, then 14 nine times.
• No avg_read anywhere. Everything was in shared_buffers on every run, including the slow one.

The sample list and the three aggregates say the same thing. Run 1 took 77.97 ms, removed 1,485,000 rows, and hit 31,598 buffers. Runs 2 through 10 took 0.06 to 0.12 ms, removed 552 rows, and hit 14 buffers. 77.97 / 0.07 is about 1,100×, which is the figure in the title. The two controls pin the same two levels on their own: 80.84 ms when every run is forced to start at block 0, and 0.08 ms when the first run is skipped. It is not a cache effect, because the cache was already full.

I know what you did last table-scan

When a table is larger than a quarter of shared_buffers, Postgres assumes that concurrent sequential scans of it should share their I/O. So, with synchronize_seqscans = on (the default since 8.3, in 2008), each new sequential scan of that table starts at the block where the most recent scan reported its position and wraps around at the end. Scans report their position every 16 pages (128 kB). The manual says this plainly, in the paragraph for that setting, and then says the part nobody reads: "This can result in unpredictable changes in the row ordering returned by queries that have no ORDER BY clause."

Run 1 starts at block 0, wades through 1,485,000 rows that fail the filter, reaches tenant 42's cluster at the end of the heap, fills LIMIT 20, and stops. The shared position for events is now the last 16-page multiple it passed, a dozen blocks short of the cluster. Run 2 starts there, skips those dozen pages, finds 20 matching rows, and is done. So are runs 3 through 10. The aggregate even shows the report interval: the fast runs removed about 552 rows each over 14 pages, and at 1,500,000 rows in 31,915 pages, 47 rows per page, 552 rows is twelve pages of misses before the cluster begins.

In production this table would not sit idle between your two runs. Any other sequential scan of it, a report, a COUNT(*), an analytics job, moves the start position under your LIMIT query. Your query's runtime depends on what the last unrelated scan of the same table happened to be doing. That is the state channel, and no single EXPLAIN ANALYZE can show it, because a single run has nothing to be different from.

Checking our sanity....

An anecdote becomes a mechanism when you can turn it off. Same table, same ten runs, SET synchronize_seqscans = off added:

Execution Time: avg=80.84 ms stddev=1.06 n=10 samples=80.17,81.27,80.5,80.3,82.32,81.65,82.49,80.64,79.37,79.71
Rows Removed by Filter: avg=1485000 samples=1485000,1485000,1485000,1485000,1485000,1485000,1485000,1485000,1485000,1485000
Buffers: shared avg_hit=31598 samples_hit=31598,31598,31598,31598,31598,31598,31598,31598,31598,31598

Every run is run 1. The stddev collapses to 1.3% of the mean. A 544 ms serial aggregate measured 20 times came in at 0.9%, and 1.3% is that neighborhood. Rows Removed by Filter is exactly 0.99 × 1,500,000 with no stddev at all, because every sample is 1,485,000. The mean went from 7.86 ms to 80.84 ms, 10.3×, which is what you would predict if one run in ten had been paying the full cost before.

Second control, and this one is about method rather than mechanism: same as the original, but with one warm-up execution before the ten timed runs, which is what every benchmarking guide tells you to do.

Execution Time: avg=0.08 ms stddev=0.0099 n=10 samples=0.1,0.07,0.07,0.07,0.08,0.09,0.09,0.09,0.08,0.09
Rows Removed by Filter: avg=552 samples=552,552,552,552,552,552,552,552,552,552
Buffers: shared avg_hit=14 samples_hit=14,14,14,14,14,14,14,14,14,14

The warm-up consumed the slow scan. All ten timed runs start in the cluster. The effect is gone from the data, and a careful person following standard advice would report 0.08 ms and be wrong by three orders of magnitude about what the first request after any competing scan will cost. The scan node itself is avg_time=0.055..0.060. The footer is 0.08 ms. "Warm the cache first" is good advice for measuring a cache. It is exactly the wrong advice for measuring a state channel, because it is one.

The rows are different for "no reason"

Runtime is the smaller devil here. The manual's warning is about row order, and it means it. Two scans of the same table inside one statement, even on a quiet database, with nothing else running:

WITH first_scan AS MATERIALIZED (
  SELECT id FROM events WHERE tenant_id = 42 LIMIT 10000
),
second_scan AS MATERIALIZED (
  SELECT id FROM events WHERE tenant_id = 42 LIMIT 5
)
SELECT (SELECT min(id)       FROM first_scan)  AS first_min,
       (SELECT max(id)       FROM first_scan)  AS first_max,
       (SELECT array_agg(id) FROM second_scan) AS second_scan;

 first_min | first_max |               second_scan
-----------+-----------+-----------------------------------------
   1485001 |   1495000 | {1494977,1494978,1494979,1494980,1494981}

The first scan started at the beginning of tenant 42's cluster and returned ids 1485001 through 1495000. The second scan, same predicate, same table, same statement, returned ids starting at 1494977, because it started where the first one left off. If you had written LIMIT 5 for both, you would have seen the same five ids twice. That's what happened on my first three attempts: a 5-row scan finishes inside one page and never crosses a 16-page report boundary, so it does not move the shared position. A 10,000-row scan does. (The CTEs are evaluated in the order the outer query references them; if you want to be certain, run the two SELECTs as consecutive statements in one session.)

Everybody "knows" that LIMIT without ORDER BY is non-deterministic but the cause they have in mind is a concurrent write, or a parallel worker. A quiet database should be immune to this form of devilishness. So a test fixture or a "give me a sample row" admin query is enough to see it. The engine keeps a shared per-table starting block for sequential scans and moves it on every scan, and it switches that behavior on at a size threshold: your development database is probably under it, and your production database is probably over it.

The other two shapes, briefly

The single-outlier fingerprint is one row of the table above. The other two rows have measurements of their own, and they show the opposite lesson: statistics can also mislead you if you read the mean without the shape.

Two regimes. A prepared statement, EXECUTE tenant_report(1), run twelve times on a 2M-row table where tenant 1 owns 40% of rows. The plan shape changed at run 6, so the renderer split the runs:

Plan changed across runs: 2 distinct plans; A: runs 1-5, B: runs 6-12 (n=12)
--- Plan A (5 of 12 runs) ---   ... Parallel Hash Join ... Filter: (tenant_id = 1)
Execution Time: avg=273.678 ms stddev=3.571 n=5
--- Plan B (7 of 12 runs) ---   ... Nested Loop ... Recheck Cond: (tenant_id = $1)
Execution Time: avg=2318.664 ms stddev=59.318 n=7
--- All runs (n=12) ---
Execution Time: avg=1466.587 ms stddev=1053.935 n=12

The pooled mean, 1,467 ms, is a duration that never occurred on any run. Inside each regime the stddev is small. Across them it is enormous. The pooled numbers say the distribution has two humps (stddev/mean 0.72). The shape split says what the humps are. This is the generic-plan switch after five custom plans, which has its own post. A mean taken across that switch averages two durations, and neither of them is 1,467 ms.

A ramp. From the September session, a data-modifying CTE that updates 1,000 random rows and then runs a covering-index report, repeated with N = 5, 10, and 20:

Heap Fetches: avg=4230.6   stddev=2015.456   (n=5)
Heap Fetches: avg=6815.8   stddev=3156.801   (n=10)
Heap Fetches: avg=10529.3  stddev=4465.843   (n=20)

When every run does the same work, adding runs doesn't move the average. It just pins it down more precisely, increasing averages could me a couple of different things but ultimately, something must be growing.

In this case, the growing-thing is the visibility map. The same report without the UPDATE in front of it says Heap Fetches: avg=0 on all twenty runs. With the UPDATE, every run clears the all-visible bit on the pages its 1,000 rows sit on, and those pages stay cleared in subsequent runs. Run 20 inherits the damage from runs 1 through 19. A stddev/mean around 0.42 plus an average that rises is a simple ramp. A single EXPLAIN ANALYZE on that freshly vacuumed table says Heap Fetches: 0 and that's the truth exactly once in time.

Do this yourself, in psql

None of this needs anything but Postgres. First, check whether your table is over the line:

SELECT pg_relation_size('events') / 8192                      AS table_pages,
       current_setting('shared_buffers')                       AS shared_buffers,
       (SELECT setting::bigint / 4 FROM pg_settings
        WHERE name = 'shared_buffers')                         AS sync_threshold_pages;
-- synchronize_seqscans engages when table_pages > sync_threshold_pages

If your shared_buffers is large, the 1.5M-row table above will be under the threshold and you will see nothing. Either raise the row count or widen payload. Then:

SET max_parallel_workers_per_gather = 0;
EXPLAIN (ANALYZE, BUFFERS) SELECT id FROM events WHERE tenant_id = 42 LIMIT 20;  -- run this twice
SET synchronize_seqscans = off;
EXPLAIN (ANALYZE, BUFFERS) SELECT id FROM events WHERE tenant_id = 42 LIMIT 20;  -- and twice more

And if you want the N-run statistics rather than eyeballing two plans, EXPLAIN will hand you JSON and PL/pgSQL will loop:

SET max_parallel_workers_per_gather = 0;   -- one scan to reason about, and a fixed plan shape for the JSON paths below
CREATE TEMP TABLE runs (n int, plan json);

DO $$
DECLARE p json;
BEGIN
  FOR i IN 1..10 LOOP
    EXECUTE 'EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) '
         || 'SELECT id FROM events WHERE tenant_id = 42 LIMIT 20' INTO p;
    INSERT INTO runs VALUES (i, p);
  END LOOP;
END $$;

-- per run
SELECT n,
       (plan->0->>'Execution Time')::numeric                          AS exec_ms,
       (plan->0->'Plan'->'Plans'->0->>'Rows Removed by Filter')::bigint AS rows_removed,
       (plan->0->'Plan'->>'Shared Hit Blocks')::bigint                 AS shared_hit
FROM runs ORDER BY n;

-- the two numbers this post is about
SELECT round(avg((plan->0->>'Execution Time')::numeric), 3)    AS avg_ms,
       round(stddev((plan->0->>'Execution Time')::numeric), 3) AS stddev_ms,
       round(stddev((plan->0->>'Execution Time')::numeric)
             / avg((plan->0->>'Execution Time')::numeric), 2)   AS ratio
FROM runs;

Dynamic EXECUTE in PL/pgSQL is re-planned each time and has no parameters, so it does not drag the plan cache into an experiment about something else. The per-run query is the honest version of what the aggregate hides: you will see one row with ~78 ms and nine with ~0.07.

The instrument, and a disclosure

The avg= / stddev= plan text above comes from ExoBench, a benchmarking sandbox I built. You describe a schema and a data shape, it builds a temporary Postgres at the scales you name, generates the rows, runs your EXPLAIN (ANALYZE, BUFFERS), and returns the plans. Using a repetitions parameter: it runs the statement N times on one connection, parses each plan, and figures out the stats to show for it.

Two honest notes about the instrument, since the point of this post is method. First, the flip banner is the more readable output when the shape changes: "plan changed at run 6" needs no interpretation. A single-outlier history does not change shape, so the banner stays quiet, and what you have is a stddev. On this run the plan also printed samples= on the execution-time line, 77.97,0.07,0.07,0.07,0.07,0.07,0.06,0.07,0.12,0.06, which shows the data but you don't actually need to see it. The √N arithmetic gives the data a plot-line and all you need for it is a mean and standard deviation, pg_stat_statements can give you that. Also, I used a warm-up as a control here, deliberately, to show that it deletes the effect. The common advice to warm up before measuring is right for cache behavior but wrong for everything in the state list. An instrument that only offers a warmed mode cannot see any of it.

Caveats

The performance part of this story (or lack thereof) needs a sequential scan, which needs the absence of a useful index on the filter column. In production you would usually have one, and then the shared scan position is irrelevant to that query. The queries that actually get bitten are the ones nobody indexes for: "give me a sample of rows," "does any row match," admin one-offs, test fixtures, ad-hoc analytics against a big table. The correctness issues, i.e. getting different rows from the same statement, apply to every LIMIT without ORDER BY on a table over the threshold, indexed or not, whenever the planner chooses a sequential scan.

The threshold is a quarter of your shared_buffers, so the same table can be over it in one environment and under it in another. This ran with shared_buffers = 456 MB. The table was 31,915 pages, the threshold was 14,592 pages, and the 249 MB table fit entirely in shared_buffers, which is why every run was all hits and the bulk-read ring buffer did not enter the picture. On a table larger than shared_buffers you would additionally see read= on run 1 and the picture gets muddier, which is an argument for better controls.

The √N fingerprint is a heuristic with n=10 behind it. It told me where to look; the controls are what made it a claim. Confirm with a warm-up-of-one (does the stddev vanish?), with the N-trick (does the mean fall as 1/N?), or with the per-run listing, before you tell anyone a query is bimodal.

Go read the column you have been ignoring

If you have pg_stat_statements, you already have dispersion for every statement in production, and the ratio from the table above is one ORDER BY away:

SELECT left(query, 60)                        AS query,
       calls,
       round(min_exec_time::numeric, 2)       AS min_ms,
       round(mean_exec_time::numeric, 2)      AS mean_ms,
       round(max_exec_time::numeric, 2)       AS max_ms,
       round(stddev_exec_time::numeric, 2)    AS stddev_ms,
       round((stddev_exec_time
              / GREATEST(mean_exec_time, 0.01))::numeric, 2) AS ratio
FROM pg_stat_statements
WHERE calls >= 20
ORDER BY ratio DESC
LIMIT 15;

A ratio near 1 with max_ms a hundred times min_ms is a statement with two personalities: a plan that flips, a cache that is sometimes cold, a parameter that is sometimes a whale, or a sequential scan whose starting block depends on what ran before it. pg_stat_statements cannot tell you which. The way to find out is the loop above: rebuild the shape somewhere disposable, run it more than once, and read the dispersion on the plan, not just the mean.

One EXPLAIN ANALYZE is a photograph. A good photograph, of one instant. The database you are trying to understand is a film, and the interesting frames are the ones where something you did not do changed the picture.