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;"
$ 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"
$ 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"
$ 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;"
$ 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"
$ 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"
$ 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 msThere 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"
$ 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"
$ 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 msHeap 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"
$ the identical query after an UPDATE, then after a VACUUMUPDATE 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 ms2.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:
- 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? cost=4.50..43.44— what are the two numbers, and when does the first one decide the plan?- A node estimated 50 rows and produced 200,000. Why is it pointless to look at the join method chosen above it?
Rows Removed by Filter: 900000on a table of a million rows. What does that suggest, and what would you check before adding an index?- 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:
- Execution Time — is the problem even in execution, or in planning?
- The deepest node with
actual rows × loopsfar fromrows— that is the cause; everything above it is a consequence. Rows Removed by Filter— work done and thrown away.Buffers: readversushit— whether the data was in memory.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_costand 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 Filteris 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 ANALYZEon a writing statement in production outside an explicit transaction you intend to roll back. It is not a read-only diagnostic. Buffers: readversushitanswers “was this slow because of I/O”, which is usually the first question and is now free on 18.
What You Learned
EXPLAINestimates;EXPLAIN ANALYZEexecutes. The second one runs your statement, writes included.- PostgreSQL 18 includes
BUFFERSby default withANALYZE, and reports anIndex Searchescount — both new, and both changing what a plan tells you at a glance. actual rowsis per loop and can be fractional. The true count isrows × 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 Fetchesis where that shows. - A plan is evidence only with its context — the settings, the statistics age, and whether the buffers were already warm.