Skip to main content
RunBook Academy

← All labs in PostgreSQL

Lab · intermediate · ~55 min

Lab 12: Read a query plan the way the executor produced it

C · SimulationB · Nested virtualisation

Objectives

  • Distinguish EXPLAIN from EXPLAIN ANALYZE and know which one executes the query
  • Read cost, rows, actual time and loops, and compute the true row count in a looped node
  • Explain why BUFFERS appears without being asked for in PostgreSQL 18
  • Identify the common scan and join node types from their plan lines
  • Use Rows Removed by Filter to find work the query did and discarded
  • Demonstrate that Heap Fetches on an index-only scan depends on the visibility map

Prerequisites

  • A PostgreSQL 18 cluster with superuser access
  • Roughly 150 MB of free disk for the sample dataset
  • Completion of Lab 10, or equivalent familiarity with what vacuum maintains

Objective

A query plan is not a recommendation and it is not a summary. It is a tree of operations, each reporting what the planner expected and what actually happened, and reading it is a skill you can acquire in an hour and use for the rest of your career.

By the end of this lab you will be able to look at any plan and answer: which node consumed the time, how far the planner’s estimate was from reality, how much of the work was thrown away, and whether the data came from memory or from disk.

The last task is the one that changes how people think about plans. The same query, the same index, the same rows returned — and a five-fold difference in execution time, caused by something that is not in the query at all.

Architecture

Two tables with a realistic size difference, so that the planner has genuine choices to make between scan and join strategies.

flowchart TD
    C["customers\n100,000 rows\nindexed on id, country"] --> J["join on customer_id"]
    O["orders\n1,000,000 rows\nindexed on id, customer_id, placed"] --> J
    J --> P1["small selection\n-> Nested Loop"]
    J --> P2["large selection\n-> Parallel Hash Join"]
    O --> P3["covered by one index\n-> Index Only Scan"]
    P3 --> VM["visibility map\ndecides Heap Fetches"]

Requirements

  • A PostgreSQL 18 cluster with superuser access. The lab creates and drops a database called lab12.
  • Roughly 150 MB of free disk for the sample data.
  • At least three CPUs available if you want Task 5 to produce a parallel plan. With fewer, the plan will be correct but serial.

Scenario

A query is slow. You have its text and access to the database. Before changing an index, rewriting the SQL or asking for more memory, you want to know what the query is actually doing — because all three of those changes are guesses until you do.

Tasks

Task 1 — Build the dataset

LAB="$HOME/rbpg-lab-12"
mkdir -p "$LAB"

docker exec -i -u postgres rbpg-lab01 psql -X -c "CREATE DATABASE lab12;"
docker exec -i -u postgres rbpg-lab01 psql -X -d lab12 <<'SQL'
CREATE TABLE customers(id int PRIMARY KEY, name text, country text, created date);
INSERT INTO customers SELECT g, 'customer-'||g,
  (ARRAY['GB','US','DE','FR','BR'])[1+(g%5)],
  date '2020-01-01' + (g%2000) FROM generate_series(1,100000) g;

CREATE TABLE orders(id int PRIMARY KEY, customer_id int REFERENCES customers(id),
                    total numeric, placed date);
INSERT INTO orders SELECT g, 1+(g%100000), (g%500)*1.25, date '2024-01-01' + (g%700)
  FROM generate_series(1,1000000) g;

CREATE INDEX orders_customer_idx   ON orders(customer_id);
CREATE INDEX orders_placed_idx     ON orders(placed);
CREATE INDEX customers_country_idx ON customers(country);
SQL

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "VACUUM ANALYZE;"

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  SELECT relname, n_live_tup, pg_size_pretty(pg_total_relation_size(relid)) AS size
  FROM pg_stat_user_tables ORDER BY relname;"
Read-only / Safethe two tables
$ psql -X -d lab12 -c "SELECT relname, n_live_tup, pg_size_pretty(pg_total_relation_size(relid)) AS size FROM pg_stat_user_tables ORDER BY relname;"
  relname  | n_live_tup |  size   
-----------+------------+---------
customers |     100000 | 8824 kB
orders    |    1000000 | 87 MB
(2 rows)

The VACUUM ANALYZE matters. Without statistics the planner is guessing, and every plan in this lab would be about the wrong thing.

Task 2 — EXPLAIN, which does not run the query

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c \
  "EXPLAIN SELECT * FROM orders WHERE customer_id = 42;" | tee "$LAB/plans.txt"
Read-only / Safeestimates only
$ psql -X -d lab12 -c "EXPLAIN SELECT * FROM orders WHERE customer_id = 42;"
                                    QUERY PLAN                                     
-----------------------------------------------------------------------------------
Bitmap Heap Scan on orders  (cost=4.50..43.44 rows=10 width=18)
 Recheck Cond: (customer_id = 42)
 ->  Bitmap Index Scan on orders_customer_idx  (cost=0.00..4.50 rows=10 width=0)
       Index Cond: (customer_id = 42)
(4 rows)

Read the tree from the inside out: the most indented node runs first, and feeds its parent. So the index is scanned, producing a bitmap of matching page locations, and the heap scan then visits those pages.

The numbers in parentheses are all estimates:

  • cost=4.50..43.44 — two numbers. The first is the cost to return the first row, the second to return them all. The units are arbitrary and only comparable to other costs on the same server; they are not milliseconds.
  • rows=10 — how many rows the planner expects this node to emit.
  • width=18 — the average row size in bytes.

The startup cost matters more than it looks. A plan with a high startup cost and a low total cost is a bad choice for a query with LIMIT 1 and a good one for a query that reads everything, which is exactly why the planner tracks both.

Task 3 — EXPLAIN ANALYZE, and what PostgreSQL 18 adds for free

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c \
  "EXPLAIN ANALYZE SELECT * FROM orders WHERE customer_id = 42;" | tee -a "$LAB/plans.txt"
Read-only / Safethe same plan, with what actually happened
$ psql -X -d lab12 -c "EXPLAIN ANALYZE SELECT * FROM orders WHERE customer_id = 42;"
 Bitmap Heap Scan on orders  (cost=4.50..43.44 rows=10 width=18) (actual time=0.021..0.062 rows=10.00 loops=1)
 Recheck Cond: (customer_id = 42)
 Heap Blocks: exact=10
 Buffers: shared hit=13
 ->  Bitmap Index Scan on orders_customer_idx  (cost=0.00..4.50 rows=10 width=0) (actual time=0.009..0.009 rows=10.00 loops=1)
       Index Cond: (customer_id = 42)
       Index Searches: 1
       Buffers: shared hit=3
Planning:
 Buffers: shared hit=95
Planning Time: 0.224 ms
Execution Time: 0.090 ms
(12 rows)

Three things here are worth pointing out explicitly.

Buffers appeared without being asked for. In PostgreSQL 18, EXPLAIN ANALYZE includes buffer statistics by default. Confirm it by turning them off:

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c \
  "EXPLAIN (ANALYZE, BUFFERS OFF) SELECT * FROM orders WHERE customer_id = 42;"
Read-only / SafeBUFFERS OFF removes them, which proves they were on
$ psql -X -d lab12 -c "EXPLAIN (ANALYZE, BUFFERS OFF) SELECT * FROM orders WHERE customer_id = 42;"
 Bitmap Heap Scan on orders  (cost=4.50..43.44 rows=10 width=18) (actual time=0.021..0.062 rows=10.00 loops=1)
 Recheck Cond: (customer_id = 42)
 Heap Blocks: exact=10
 ->  Bitmap Index Scan on orders_customer_idx  (cost=0.00..4.50 rows=10 width=0) (actual time=0.009..0.009 rows=10.00 loops=1)
       Index Cond: (customer_id = 42)
       Index Searches: 1
Planning Time: 0.219 ms
Execution Time: 0.094 ms
(8 rows)

rows=10.00 — actual row counts are reported with two decimal places. On a node that runs once this looks odd; Task 5 shows why it is necessary.

Index Searches: 1 — how many times the index was descended. On a nested loop or a scan with an = ANY(...) condition this can be much larger than 1, and it is the number to check when an index scan is slower than its row count suggests it should be.

Buffers: shared hit=13 means 13 pages were found in shared buffers. The counterpart, read, means the page was not in shared buffers and had to be requested from the operating system — which may still have served it from its own cache, so read is not the same as “went to disk”.

Note also the Planning: Buffers: shared hit=95. Planning this trivial query touched 95 pages of catalog. On a first-of-its-kind query against a cold catalog, planning can genuinely dominate.

Task 4 — A nested loop

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE
  SELECT c.name, o.total FROM customers c
  JOIN orders o ON o.customer_id = c.id
  WHERE c.id = 42;" | tee "$LAB/join-plans.txt"
Read-only / Safeone customer, ten orders, two index lookups
$ psql -X -d lab12 -c "EXPLAIN ANALYZE SELECT c.name, o.total FROM customers c JOIN orders o ON o.customer_id = c.id WHERE c.id = 42;"
 Nested Loop  (cost=4.79..51.85 rows=10 width=20) (actual time=0.031..0.076 rows=10.00 loops=1)
 Buffers: shared hit=16
 ->  Index Scan using customers_pkey on customers c  (cost=0.29..8.31 rows=1 width=18) (actual time=0.009..0.009 rows=1.00 loops=1)
       Index Cond: (id = 42)
       Index Searches: 1
       Buffers: shared hit=3
 ->  Bitmap Heap Scan on orders o  (cost=4.50..43.44 rows=10 width=10) (actual time=0.019..0.063 rows=10.00 loops=1)
       Recheck Cond: (customer_id = 42)
       Heap Blocks: exact=10
       Buffers: shared hit=13
       ->  Bitmap Index Scan on orders_customer_idx  (cost=0.00..4.50 rows=10 width=0) (actual time=0.010..0.010 rows=10.00 loops=1)
             Index Cond: (customer_id = 42)
             Index Searches: 1
             Buffers: shared hit=3
Planning:
 Buffers: shared hit=170
Planning Time: 0.402 ms
Execution Time: 0.123 ms
(18 rows)

A Nested Loop takes each row from its first child and runs its second child for that row. Here the first child returns exactly one customer, so the second child runs once, and the whole join costs 16 buffer hits.

That is the right plan for this query, and the wrong plan if the first child returns a million rows — which is the single most common cause of a query that was fast in testing and is catastrophic in production. Task 6 shows how to spot it before it happens.

Task 5 — A parallel hash join, and why rows can be fractional

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE
  SELECT c.country, count(*), sum(o.total)
  FROM customers c JOIN orders o ON o.customer_id = c.id
  WHERE o.placed >= date '2025-01-01'
  GROUP BY c.country;" | tee -a "$LAB/join-plans.txt"
Read-only / Safethree processes, a hash table, and averages per loop
$ EXPLAIN ANALYZE on an aggregate over both tables
 Gather Merge  (cost=17587.38..17588.77 rows=12 width=43) (actual time=56.197..59.247 rows=15.00 loops=1)
 Workers Planned: 2
 Workers Launched: 2
 ->  Sort  (cost=16587.35..16587.36 rows=5 width=43) (actual time=54.931..54.933 rows=5.00 loops=3)
       Sort Key: c.country
       Sort Method: quicksort  Memory: 25kB
       ->  Partial HashAggregate  (cost=16587.23..16587.29 rows=5 width=43) (actual time=54.915..54.918 rows=5.00 loops=3)
             Group Key: c.country
             Batches: 1  Memory Usage: 32kB
             ->  Hash Join  (cost=2985.00..15088.06 rows=199889 width=9) (actual time=11.225..40.186 rows=158995.67 loops=3)
                   Hash Cond: (o.customer_id = c.id)
                   ->  Parallel Seq Scan on orders o  (cost=0.00..11578.33 rows=199889 width=10) (actual time=0.009..13.117 rows=158995.67 loops=3)
                         Filter: (placed >= '2025-01-01'::date)
                         Rows Removed by Filter: 174338
                   ->  Hash  (cost=1735.00..1735.00 rows=100000 width=7) (actual time=11.031..11.032 rows=100000.00 loops=3)
                         Buckets: 131072  Batches: 1  Memory Usage: 4931kB
                         ->  Seq Scan on customers c  (cost=0.00..1735.00 rows=100000 width=7) (actual time=0.010..4.276 rows=100000.00 loops=3)
Planning Time: 0.591 ms
Execution Time: 59.404 ms

There is a lot here, and every piece is useful.

rows=158995.67 loops=3. This is the fractional-rows question answered. loops=3 means three processes ran this node — the leader and two workers — and actual rows is the average per loop, not the total. The real number is 158995.67 × 3 ≈ 476,987.

This is the most misread number in all of EXPLAIN ANALYZE. The same applies to actual time: it is per loop, so a node showing 2 ms with 5,000 loops consumed 10 seconds.

Workers Planned: 2 and Workers Launched: 2. When these differ, the query wanted more parallelism than the server could give it — max_parallel_workers was exhausted by other queries — and the plan’s cost estimate was based on parallelism it did not get.

Buckets: 131072 Batches: 1 Memory Usage: 4931kB. The hash table fitted in memory in one batch. Batches greater than 1 means the hash spilled to disk, which Lab 14 covers in detail.

Rows Removed by Filter: 174338. The scan read 333,334 rows per worker and discarded 174,338 of them. That is more than half the work thrown away, and it is the clearest possible signal that an index on placed might be worth considering for this query.

Task 6 — Compare the estimate against reality

The planner’s estimate is the input to every decision it makes. When it is wrong, the plan is wrong, and the plan output tells you.

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE
  SELECT * FROM orders
  WHERE total > 100 AND placed >= date '2025-01-01' AND customer_id < 500;" \
  | tee "$LAB/estimates.txt"
Read-only / Safea healthy estimate, and the discarded work underneath it
$ EXPLAIN ANALYZE on a three-predicate query
 Bitmap Heap Scan on orders  (cost=70.20..6582.04 rows=2221 width=18) (actual time=0.102..0.427 rows=1712.00 loops=1)
 Recheck Cond: (customer_id < 500)
 Filter: ((total > '100'::numeric) AND (placed >= '2025-01-01'::date))
 Rows Removed by Filter: 3278
 Heap Blocks: exact=43
 Buffers: shared hit=46 read=5
 ->  Bitmap Index Scan on orders_customer_idx  (cost=0.00..69.64 rows=5496 width=0) (actual time=0.069..0.069 rows=4990.00 loops=1)
       Index Cond: (customer_id < 500)
       Index Searches: 1
       Buffers: shared hit=3 read=5
Planning Time: 0.317 ms
Execution Time: 0.482 ms
(14 rows)

Estimated 2,221, actual 1,712 — a ratio of 1.3. That is a good estimate, and the plan derived from it is sound.

Note the split between Index Cond and Filter. Only customer_id < 500 could be answered by the index, so the index produced 4,990 rows; the other two predicates were then applied to the fetched rows, removing 3,278 of them.

Task 7 — Index-only scans and the visibility map

An index-only scan answers the query from the index alone, without reading the table.

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE SELECT count(*) FROM orders
  WHERE placed BETWEEN date '2025-06-01' AND date '2025-06-30';" | tee "$LAB/index-only.txt"
Read-only / Safe42,840 rows counted without touching the table
$ psql -X -d lab12 -c "EXPLAIN ANALYZE SELECT count(*) FROM orders WHERE placed BETWEEN date '2025-06-01' AND date '2025-06-30';"
 Aggregate  (cost=1119.72..1119.73 rows=1 width=8) (actual time=2.938..2.939 rows=1.00 loops=1)
 Buffers: shared hit=41
 ->  Index Only Scan using orders_placed_idx on orders  (cost=0.42..1012.25 rows=42991 width=0) (actual time=0.022..1.685 rows=42840.00 loops=1)
       Index Cond: ((placed >= '2025-06-01'::date) AND (placed <= '2025-06-30'::date))
       Heap Fetches: 0
       Index Searches: 1
       Buffers: shared hit=41
Planning Time: 0.255 ms
Execution Time: 2.968 ms

Heap Fetches: 0 and only 41 buffers for 42,840 rows. The index alone answered the question.

Now update a few thousand rows in that range — not enough to change the result, just enough to dirty some pages — and run exactly the same query:

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c \
  "UPDATE orders SET total = total WHERE placed BETWEEN date '2025-06-01' AND date '2025-06-05';"

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE SELECT count(*) FROM orders
  WHERE placed BETWEEN date '2025-06-01' AND date '2025-06-30';" \
  | grep -E "Index Only Scan|Heap Fetches|Execution Time" | tee -a "$LAB/index-only.txt"

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "VACUUM orders;"

docker exec -u postgres rbpg-lab01 psql -X -d lab12 -c "
  EXPLAIN ANALYZE SELECT count(*) FROM orders
  WHERE placed BETWEEN date '2025-06-01' AND date '2025-06-30';" \
  | grep -E "Index Only Scan|Heap Fetches|Execution Time" | tee -a "$LAB/index-only.txt"
Service impact possiblethe same query, five times slower, then fast again
$ the identical query after an UPDATE, then after a VACUUM
UPDATE 7140

 ->  Index Only Scan using orders_placed_idx on orders  (cost=0.42..1202.32 rows=43295 width=0) (actual time=6.145..13.301 rows=42840.00 loops=1)
       Heap Fetches: 47022
Execution Time: 14.678 ms

VACUUM

 ->  Index Only Scan using orders_placed_idx on orders  (cost=0.42..1012.25 rows=42991 width=0) (actual time=0.032..1.603 rows=42840.00 loops=1)
       Heap Fetches: 0
Execution Time: 2.811 ms

2.968 ms, then 14.678 ms, then 2.811 ms. Same query text, same plan node, same 42,840 rows returned. The only thing that changed is Heap Fetches: 0, then 47,022, then 0.

Validation

test -s "$LAB/plans.txt"      && echo "OK plans"
test -s "$LAB/join-plans.txt" && echo "OK join-plans"
test -s "$LAB/estimates.txt"  && echo "OK estimates"
test -s "$LAB/index-only.txt" && echo "OK index-only"

grep -q "Bitmap Index Scan"     "$LAB/plans.txt"      && echo "OK bitmap scan captured"
grep -q "Workers Launched"      "$LAB/join-plans.txt" && echo "OK parallel plan captured"
grep -q "Rows Removed by Filter" "$LAB/estimates.txt" && echo "OK discarded work captured"
grep -c "Heap Fetches"          "$LAB/index-only.txt"  # expect 3

Questions to answer without looking anything up:

  1. A node reports (actual time=0.5..2.1 rows=300.00 loops=4000). How many rows did it produce in total, and roughly how long did it take?
  2. cost=4.50..43.44 — what are the two numbers, and when does the first one decide the plan?
  3. A node estimated 50 rows and produced 200,000. Why is it pointless to look at the join method chosen above it?
  4. Rows Removed by Filter: 900000 on a table of a million rows. What does that suggest, and what would you check before adding an index?
  5. An index-only scan shows Heap Fetches: 2000000. Is the query wrong, the index wrong, or neither?

Expected Outcome

You can now read a plan tree, tell estimates from measurements, compute true row counts through loops, and identify the two signals that most often explain a slow query: a bad estimate ratio, and work being read and discarded.

The reading order to carry away, for any plan:

  1. Execution Time — is the problem even in execution, or in planning?
  2. The deepest node with actual rows × loops far from rows — that is the cause; everything above it is a consequence.
  3. Rows Removed by Filter — work done and thrown away.
  4. Buffers: read versus hit — whether the data was in memory.
  5. Heap Fetches, Batches, Sort Method — the node-specific signals that a node is not doing what its name suggests.

Troubleshooting

EXPLAIN ANALYZE on a writing statement changed your data. It executes the statement. Wrap it in BEGIN; ... ROLLBACK; — this is the safety boundary, and it applies to every INSERT, UPDATE, DELETE and CREATE TABLE AS.

No Buffers line appears. PostgreSQL 18 includes BUFFERS with EXPLAIN ANALYZE by default; earlier versions need EXPLAIN (ANALYZE, BUFFERS). If you are on 17 or older, ask for it explicitly.

actual rows is fractional, for example rows=2.50. PostgreSQL 18 reports actual rows per loop as a fraction rather than rounding. Multiply by loops for the true total; a node reporting rows=2.50 loops=4 produced ten rows.

No parallel workers appear. The table is too small, or max_parallel_workers_per_gather is 0. Parallelism is chosen by cost; force it for the demonstration with SET parallel_setup_cost = 0; SET parallel_tuple_cost = 0; SET min_parallel_table_scan_size = 0;.

Workers Launched is lower than Workers Planned. The pool was exhausted. This is normal under concurrency and it means the plan ran with less parallelism than it was costed for.

An index-only scan reports a high Heap Fetches. The visibility map is not current, so the scan is visiting the heap anyway and the “only” is not being honoured. VACUUM the table and re-run.

The plan changes between two runs of the same query. Statistics were updated in between, or a parameter differs. EXPLAIN without ANALYZE is cheap — capture it alongside the settings that produced it.

Cleanup

docker exec -u postgres rbpg-lab01 psql -X -c "DROP DATABASE IF EXISTS lab12;"

Production notes

  • Capture the plan and the settings that produced it. A plan without work_mem, random_page_cost and the statistics timestamp is an anecdote, and the estimate that looks wrong may be correct for the configuration that produced it.
  • Read the deepest badly-estimated node first. Everything above it is a consequence, and fixing a join method chosen from a wrong row count treats the symptom.
  • Rows Removed by Filter is work done and thrown away. A large value is usually an index that does not exist, or an index the predicate cannot use.
  • Never run EXPLAIN ANALYZE on a writing statement in production outside an explicit transaction you intend to roll back. It is not a read-only diagnostic.
  • Buffers: read versus hit answers “was this slow because of I/O”, which is usually the first question and is now free on 18.

What You Learned

  • EXPLAIN estimates; EXPLAIN ANALYZE executes. The second one runs your statement, writes included.
  • PostgreSQL 18 includes BUFFERS by default with ANALYZE, and reports an Index Searches count — both new, and both changing what a plan tells you at a glance.
  • actual rows is per loop and can be fractional. The true count is rows × loops.
  • The estimate-versus-actual ratio at the deepest wrong node is the cause; the plan shape above it is the effect.
  • An index-only scan still reads the heap when the visibility map is not current, and Heap Fetches is where that shows.
  • A plan is evidence only with its context — the settings, the statistics age, and whether the buffers were already warm.

Deliverables

  • · plans.txt - the same query as EXPLAIN and as EXPLAIN ANALYZE
  • · join-plans.txt - a nested loop and a parallel hash join, annotated
  • · estimates.txt - a plan with its estimated and actual row counts side by side
  • · index-only.txt - Heap Fetches at 0, then 47022, then 0 again

Verification status

Last reviewed
2026-08-28
Executed end to end
2026-08-28