Reading EXPLAIN and EXPLAIN ANALYZE

EXPLAIN is the single most useful command in this course. It is also the one people bounce off, because the output looks like machine noise. It is not — it is a tree, printed sideways, and once you can see the tree you can read any plan.

Three forms

EXPLAIN SELECT ...;                            -- plan only, does not run
EXPLAIN ANALYZE SELECT ...;                    -- runs it, shows real timings
EXPLAIN (ANALYZE, BUFFERS) SELECT ...;         -- ← use this one

Use (ANALYZE, BUFFERS) as your default. ANALYZE gives you reality instead of estimates; BUFFERS tells you how much data was actually touched, which is the number that explains why something is slow.

Two warnings about ANALYZE:

It really runs the query. EXPLAIN ANALYZE DELETE FROM loans deletes the rows. Wrap it in a transaction and roll back:

BEGIN;
EXPLAIN (ANALYZE, BUFFERS) DELETE FROM loans WHERE id = 1;
ROLLBACK;

The timing instrumentation itself costs something, sometimes a lot on a plan with millions of node executions. A query that reports 50ms under EXPLAIN ANALYZE may take 30ms normally. Use it to compare plans, not to certify a latency figure.

Reading the tree

 Aggregate  (cost=15507.00..15507.01 rows=1 width=8)
   ->  Seq Scan on big  (cost=0.00..15507.00 rows=500000 width=0)

Indentation is depth. -> marks a child. Children run first, and data flows upward.

So: the sequential scan runs, feeding rows to the aggregate, which produces one row. Read a plan bottom-up and innermost-first to follow the execution, and top-down to see the shape.

Every number on a node

Here is the same query with an index, fully annotated:

EXPLAIN (ANALYZE, BUFFERS) SELECT count(*) FROM big WHERE member_id = 42;

 Aggregate  (cost=14.40..14.41 rows=1 width=8) (actual time=0.113..0.114 rows=1 loops=1)
   Buffers: shared hit=4
   ->  Index Only Scan using idx_big_mt on big  (cost=0.42..13.15 rows=499 width=0)
                                     (actual time=0.017..0.083 rows=527 loops=1)
         Index Cond: (member_id = 42)
         Heap Fetches: 0
         Buffers: shared hit=4
 Planning Time: 0.062 ms
 Execution Time: 0.135 ms

The four things to look for, in order

This is the actual procedure. Do these four checks and you will diagnose most slow queries.

1. Estimated rows versus actual rows

rows=499 estimated, 527 actual. That is a 6% error — excellent, and it means the planner made its decision with good information.

Now compare with a bad case:

 ->  Seq Scan on big  (cost=... rows=5 ...) (actual ... rows=106992 loops=1)

Estimated 5, got 106,992. A four-order-of-magnitude misestimate is the single most common root cause of a bad plan, because every decision above that node — join type, join order — was made believing there would be five rows.

Causes, in the order worth checking: stale statistics (run ANALYZE); correlated columns (city = 'Pune' AND state = 'Maharashtra' — the planner multiplies the probabilities as if independent, so it badly underestimates; fix with CREATE STATISTICS ... (dependencies) ON city, state FROM addresses); and expressions the planner cannot see through, like WHERE lower(email) = ....

A large discrepancy low in the tree is where to look first. Errors amplify upward.

2. loops, because it hides the real cost

 ->  Nested Loop  (actual time=0.03..842.11 rows=1000 loops=1)
       ->  Seq Scan on members  (actual time=0.01..0.41 rows=1000 loops=1)
       ->  Index Scan on loans  (actual time=0.82..0.84 rows=1 loops=1000)

The index scan says actual time=0.82..0.84, which looks trivial. But loops=1000. The timings and row counts on a node are per loop, averaged, so the true cost is 0.84 × 1000 ≈ 840ms — which is exactly where the parent's 842ms went.

This is the most misread thing in EXPLAIN output. Always multiply by loops.

3. Buffers, which is the real work

Buffers: shared hit=492 read=0 dirtied=2 written=0

• hit — found in PostgreSQL's cache. Cheap.
• read — had to go to the operating system, and possibly to disk. Expensive.
• dirtied — pages this query modified, which must be written eventually.
• temp read/written — spilled to disk because work_mem was too small. Always worth fixing.

Each buffer is 8 KB. This is the number I trust most, because unlike time it does not vary with cache state and other load. Two plans, same query:

The 7.5× reduction in buffers is why it is faster, and it is a stable, reproducible number. Judging by time alone, a warm cache can make a terrible plan look fine.

4. Where the time actually goes

actual time is cumulative including children. To get a node's own cost, subtract its children. A node showing 900ms whose child shows 890ms is not the problem — the child is.

Look for the node where the inclusive time jumps.

Node types you will meet

Scans

• Seq Scan — every row. Fine on a small table, or when most rows match.
• Index Scan — index, then fetch each row. Good for few rows.
• Index Only Scan — the index had every column needed, so the table was never read. Confirmed by Heap Fetches: 0. The fastest scan there is; see the covering-index idea in the next lesson.
• Bitmap Heap Scan + Bitmap Index Scan — collect locations, sort, then read the table in order. The middle ground, and it is what lets PostgreSQL combine two indexes with BitmapAnd.

Joins

• Nested Loop — for each row on the left, look up the right. Great when the left side is tiny and the right is indexed. Catastrophic when the left side turns out to be 100,000 rows instead of the estimated 5 — this is the classic misestimate failure.
• Hash Join — build a hash table from the smaller side, probe with the larger. The usual choice for large unsorted joins.
• Merge Join — both sides sorted, walk them together. Good when they are already sorted.

Other

• Sort — watch Sort Method. quicksort Memory: 25kB is good; external merge Disk: 4920kB means it spilled, and raising work_mem will help.
• Hash — also reports Batches. Batches: 1 is good; more means it spilled.
• Gather / Parallel ... — parallel execution; row counts are per worker.
• Materialize, Memoize — caching a child's output so it need not be recomputed.

Two more flags worth knowing

EXPLAIN (ANALYZE, BUFFERS, VERBOSE, FORMAT TEXT) SELECT ...;

VERBOSE adds the output column list, which is how you find out you are pulling 40 columns when you need 3.

FORMAT JSON is for tooling. And paste the text form into explain.dalibo.com or explain.depesz.com — they colour the expensive nodes and do the loops multiplication for you. On a plan with 40 nodes this is not laziness, it is the only sane approach.

Finding the queries to explain

EXPLAIN needs a query. pg_stat_statements tells you which one:

CREATE EXTENSION pg_stat_statements;   -- needs a config change and restart

SELECT calls, round(total_exec_time) AS total_ms, round(mean_exec_time, 2) AS mean_ms, query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

Order by total_exec_time, not mean_exec_time. A query taking 2ms called 500,000 times costs more than one taking 900ms called twice, and it is invisible if you only look at slow queries. This is the N+1 problem of the last lesson, and this is how you find it.

Also enable slow-query logging:

ALTER SYSTEM SET log_min_duration_statement = '500ms';
SELECT pg_reload_conf();

What good looks like

• Estimates within about 10× of actual.
• No node where actual rows × loops is unexpectedly enormous.
• Buffers roughly proportional to the rows you asked for, not to the table.
• No external merge Disk and no Batches above 1.
• Execution Time mostly in one identifiable node.

Check your work

The default form to use. EXPLAIN (ANALYZE, BUFFERS).

The danger of EXPLAIN ANALYZE. It runs the query — wrap writes in BEGIN/ROLLBACK.

Why its reported time can exceed the real time. Instrumentation overhead.

How to read the tree. Indentation is depth, -> marks a child, children run first, data flows up.

The four checks. Estimate versus actual; loops; Buffers; where the time jumps.

The most misread field. loops — per-node times and rows are per-loop averages.

What hit and read mean. Cache, and going to the OS. A buffer is 8 KB.

Why Buffers beats time as a metric. It does not vary with cache state or load.

Why actual time on a parent is not its own cost. It includes children.

What Heap Fetches: 0 proves. An index-only scan — the table was never read.

When a nested loop is catastrophic. When the outer side is far bigger than estimated.

What external merge Disk means. The sort spilled; raise work_mem.

Two causes of a bad estimate besides stale statistics. Correlated columns, and expressions the planner cannot see through.

Why to order pg_stat_statements by total, not mean. A fast query called half a million times is the bigger cost.

Practice

1. Run EXPLAIN and then EXPLAIN (ANALYZE, BUFFERS) on the same query and list what the second adds.
2. Draw the tree for a three-node plan on paper, with arrows for data flow.
3. Find a query whose estimate is more than 10× wrong. Run ANALYZE and re-check.
4. Write a query with correlated conditions and measure the misestimate. Add CREATE STATISTICS and measure again.
5. Find a Nested Loop with loops above 100 and calculate the true cost of its inner node.
6. Compare Buffers for the same query with and without a useful index.
7. Run a query twice in a row and watch read turn into hit.
8. Force a disk sort with SET work_mem = '64kB' and find external merge in the output. Raise it and watch the method change.
9. Find a plan with an Index Only Scan and confirm Heap Fetches: 0.
10. EXPLAIN ANALYZE a DELETE inside a transaction, then ROLLBACK and confirm the rows are still there.
11. Paste a plan into explain.dalibo.com and find the node it highlights.
12. Add VERBOSE and check whether you are selecting columns you do not use.
13. Install pg_stat_statements and list your top ten queries by total time.
14. Set log_min_duration_statement and find the slow queries in the log.
15. Take the slowest query you own and work the four checks in order. Write down which check found the problem.

Official documentation

• PostgreSQL — Using EXPLAIN — Worked examples of every node type, and the best single page on this topic anywhere.
• PostgreSQL — EXPLAIN reference — Every option, including BUFFERS, VERBOSE, SETTINGS and WAL.
• PostgreSQL — pg_stat_statements — Setup and every column.
• PostgreSQL — Extended statistics — The fix for correlated-column misestimates.
• explain.dalibo.com — Paste a plan, get it visualised.

Next: what an index actually is.