Reading an EXPLAIN plan · PostgreSQL

EXPLAIN prints a tree with the root at the top. Execution goes the other way: leaves first, each node feeding its parent. Reading it in printed order is the most common reason people look at a plan and take nothing from it.

The shape

 Aggregate  (cost=56.57..56.58 rows=1 width=8) (actual time=0.146..0.146 rows=1.00 loops=1)
   Buffers: shared hit=3 read=3
   ->  Index Only Scan using ordersx_customer_idx on ordersx
         (cost=0.43..51.67 rows=1962 width=0) (actual time=0.010..0.088 rows=2010.00 loops=1)
         Heap Fetches: 0
         Buffers: shared hit=3 read=3

The Index Only Scan runs first and hands its rows to the Aggregate. Indentation is depth: a node’s children are the more-indented -> entries directly beneath it.

Read from the deepest, last-listed node upward. That is execution order.

Every number on a node line

(cost=0.43..51.67 rows=1962 width=0) (actual time=0.010..0.088 rows=2010.00 loops=1)

Field	Meaning
`cost=0.43..51.67`	Estimated startup cost .. estimated total cost
`rows=1962`	Estimated rows this node will produce
`width=0`	Estimated average row width in bytes
`actual time=0.010..0.088`	Real milliseconds to first row .. to last row
`rows=2010.00`	Actual rows produced, per loop
`loops=1`	How many times this node was executed

The pairing to internalise is rows=1962 against rows=2010.00. That is the estimate against reality, and lesson X-04 is entirely about it.

Loops multiply everything, and this is where people misread plans

On a node with loops greater than 1, actual time and actual rows are per iteration.

From a real plan in this course:

->  Bitmap Heap Scan on ev  (cost=4.66..122.37 rows=30 width=4)
      (actual time=0.061..0.276 rows=30.00 loops=1000)
      Buffers: shared hit=6082 read=26918

Read casually: “30 rows, 0.276 ms, fine.”

Read correctly: 30,000 rows and about 276 ms, because it ran a thousand times. The Buffers line is the giveaway — 33,000 buffer accesses is not what a 30-row node does.

The rule:

Total rows = rows × loops
Total time ≈ actual time (the second figure) × loops
Buffers is already cumulative across all loops, which is precisely why it is the most reliable number in the plan.

A slow query whose plan appears to contain only fast nodes is nearly always this. Look for a large loops count.

The options worth using

EXPLAIN (ANALYZE, BUFFERS, VERBOSE, SETTINGS, WAL, FORMAT TEXT) SELECT …;

Option	Gives you
`ANALYZE`	Actually runs it, adds actual rows and timing
`BUFFERS`	Pages hit, read, dirtied and written per node
`VERBOSE`	Output column lists, schema-qualified names
`SETTINGS`	Any planner setting that differs from its default
`WAL`	WAL generated, for `INSERT`/`UPDATE`/`DELETE`
`COSTS OFF`	Suppresses estimates — useful for stable test output
`TIMING OFF`	Suppresses per-node timing, reducing measurement overhead
`FORMAT JSON`	Machine-readable, for tooling

BUFFERS should be automatic. Timing varies with cache state and system load; buffer counts do not. A query reading 16,667 buffers is doing more work than one reading 6, on any hardware, at any time of day.

SETTINGS is the one nobody uses and should. It reveals that the session you are debugging has enable_seqscan = off or a modified work_mem — which explains a plan you could not otherwise account for.

Node types you will meet

Scans. Seq Scan, Index Scan, Index Only Scan, Bitmap Heap Scan, Bitmap Index Scan, CTE Scan, Function Scan, Values Scan.

Joins. Nested Loop, Hash Join (with a Hash child that builds the table), Merge Join (with Sort children unless input is already ordered).

Aggregation. Aggregate (one result), GroupAggregate (needs sorted input), HashAggregate (builds a hash table, no sort needed).

Ordering and limiting. Sort with Sort Method and Memory or Disk — a Sort Method: external merge Disk: 84320kB line is a work_mem problem, covered in Part XI. Limit, Incremental Sort.

Parallelism. Gather and Gather Merge collect from workers. Anything below them named Parallel … runs in each worker.

Other. Materialize caches a subtree’s output for reuse. Memoize caches lookups on the inner side of a nested loop — a node whose Hits and Misses counts tell you whether it was worth it. Subquery Scan, Append and Merge Append for partitions and unions.

Reading a parallel plan without double counting

 Finalize Aggregate  (cost=30169.26..30169.27 rows=1) (actual time=22.681..25.979 rows=1.00 loops=1)
   Buffers: shared hit=12487 read=4180
   ->  Gather  (cost=30169.04..30169.25 rows=2)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (actual time=21.442..21.443 rows=1.00 loops=3)
               ->  Parallel Seq Scan on ordersx  (actual rows=670.00 loops=3)

Three points.

loops=3 means the leader plus two workers. The leader participates in the scan; it is not a coordinator that sits idle.

Rows below Gather are per worker. 670 rows × 3 loops = 2,010 rows total, which matches what the non-parallel plan produced.

Workers Planned against Workers Launched is the first thing to check on a parallel plan that is intermittently slow. Planned 2, launched 0 means the pool was exhausted and the query ran single-threaded.

The Buffers line at the top is cumulative across all workers, so it is again the number that needs no adjustment.

Finding the expensive node

A procedure that works:

Read Buffers at the top. That is the total work. If it is small, the query is not doing much I/O and the problem is elsewhere.
Find the node with the largest Buffers. Buffer counts are cumulative up the tree, so the node whose count is much larger than its parent’s other children is where the work happened.
Check its loops. A modest node executed thousands of times is the commonest cause.
Compare its estimate to its actual. If they diverge, the problem is upstream — statistics, not execution.
Only then look at timing. Time is a consequence; buffers and row counts are causes.

What ANALYZE's timing costs, and when to turn it off

EXPLAIN ANALYZE instruments every node, reading the clock twice per row per node. On a plan processing millions of rows through several nodes that is tens of millions of clock reads, and on some systems gettimeofday() is far more expensive than on others.

The consequence is that Execution Time under ANALYZE can substantially exceed the query’s real duration, and the distortion is not uniform — it falls hardest on nodes processing many rows, which are usually the ones under suspicion.

Measure your own system’s clock cost:

pg_test_timing

It reports the per-call duration and a histogram. On a system where the result is dominated by the fastest bucket, the overhead is small. Where it is not, EXPLAIN ANALYZE timings should be treated as relative rather than absolute.

Two ways to avoid the problem:

-- keep row counts and buffers, drop per-node timing
EXPLAIN (ANALYZE, BUFFERS, TIMING OFF) SELECT …;

This still reports total Execution Time and every actual rows, which is usually all you needed. Buffers are unaffected by timing overhead entirely.

There is also a session-level equivalent for the same trade: track_io_timing adds I/O timing to BUFFERS output and carries the same clock cost, which is why it is off by default and why measuring with pg_test_timing is worth doing before enabling it cluster-wide.

What to take from this

Read bottom up and inside out. Indentation is depth.
loops > 1 means actual rows and actual time are per iteration. Multiply.
Buffers is cumulative and unaffected by clock overhead. It is the most trustworthy number in the plan.
Always pass BUFFERS. Consider SETTINGS when a plan makes no sense.
On parallel plans, loops=3 is the leader plus two workers, and Workers Launched may be lower than Workers Planned.
TIMING OFF removes measurement overhead while keeping row counts.

Cross-course references

Observability for Production Sysadmins — Part CII (Slow queries) covers getting from a latency series to the individual statement whose plan you then read, which is the step before this one.
Linux for Production Sysadmins — Part LXXIX (Troubleshooting methodology) covers reading evidence bottom-up, which is exactly how a plan tree is read.