Postgres – EXPLAIN and Query Performance

When a query is slow, there are two things you can do: guess, or ask. EXPLAIN is how you ask. This post is how to read the answer.

EXPLAIN and EXPLAIN ANALYZE

EXPLAIN SELECT b.id FROM bookings b WHERE b.property_id = 4242;

Bitmap Heap Scan on bookings b  (cost=4.58..81.68 rows=20 width=4)
  Recheck Cond: (property_id = 4242)
  ->  Bitmap Index Scan on ix_bookings_property_id  (cost=0.00..4.57 rows=20 width=0)
        Index Cond: (property_id = 4242)

Plain EXPLAIN shows the plan without running it. Everything in it is an estimate:

cost=4.58..81.68 — startup cost, then total cost, in arbitrary units. Only useful for comparing two plans for the same query.
rows=20 — how many rows the planner expects.
width=4 — expected average row size in bytes.

EXPLAIN ANALYZE actually runs the query and adds what really happened. It runs the query. On an UPDATE or DELETE that means the rows change — wrap it in a transaction you roll back:

BEGIN;
EXPLAIN ANALYZE DELETE FROM outbox WHERE status = 'DONE';
ROLLBACK;

Reading a plan

Plans are trees, printed with children indented under their parent. Read them inside-out and bottom-up: the most indented node runs first and passes its rows up.

EXPLAIN (ANALYZE, BUFFERS, COSTS OFF)
SELECT p.city, count(*) FROM bookings b
JOIN   properties p ON p.id = b.property_id
WHERE  b.status = 'PENDING'
GROUP  BY p.city ORDER BY 2 DESC LIMIT 3;

Limit (actual time=29.476..29.478 rows=3 loops=1)
  ->  Sort (actual time=29.475..29.477 rows=3 loops=1)
        Sort Key: (count(*)) DESC
        Sort Method: top-N heapsort  Memory: 25kB
        ->  HashAggregate (actual time=29.452..29.455 rows=16 loops=1)
              Group Key: p.city
              ->  Hash Join (actual time=12.971..26.971 rows=25482 loops=1)
                    Hash Cond: (b.property_id = p.id)
                    ->  Bitmap Heap Scan on bookings b (actual rows=25482 loops=1)
                          Heap Blocks: exact=4213
                          Buffers: shared hit=4235
                          ->  Bitmap Index Scan on ix_bookings_status (actual rows=25482 loops=1)
                                Index Cond: (status = 'PENDING')
                    ->  Hash (actual time=11.644..11.645 rows=20000 loops=1)
                          Buckets: 32768  Batches: 1  Memory Usage: 1131kB

Bottom-up: find 25,482 pending bookings through the status index; build a hash of all 20,000 properties; join them; group into 16 cities; sort; take 3.

actual time=12.971..26.971 is startup..total, per loop. The first number is when the node produced its first row, the second when it finished. And because a child's time is included in its parent's, the cost of one node alone is its total minus its children's.

loops=1 matters more than it looks. On the inner side of a nested loop it is not 1, and the times shown are per loop — a node reading actual time=0.05 with loops=20000 took a second, not 0.05ms.

The single most useful signal

Add ANALYZE and compare rows= (estimated) with actual rows=. When they are close, the planner understood the data and its choices were reasonable. When they are out by an order of magnitude, everything above that node is built on a wrong assumption — and that is nearly always the real problem.

A planner expecting 20 rows and getting 200,000 will have picked a nested loop, and it will now run 200,000 times. The fix is rarely a different index; it is usually one of:

ANALYZE the_table; — the statistics are stale.
ALTER TABLE t ALTER COLUMN c SET STATISTICS 500; — the default sample is too small for a skewed column.
CREATE STATISTICS — for correlated columns. Postgres assumes independence, so it multiplies selectivities: WHERE city = 'Oslo' AND country = 'Norway' is estimated as far rarer than it is, because those two are not independent at all.

CREATE STATISTICS stat_property_place (dependencies)
    ON city, country FROM properties;
ANALYZE properties;

BUFFERS

Always add it. BUFFERS reports pages read, and pages are the actual work:

shared hit — found in the cache. Cheap.
shared read — went to the operating system, and possibly to disk. Expensive.
temp read/written — a sort or hash spilled to disk. This is the finding, and the fix is usually more work_mem.

Timing varies with cache state, so the same query looks fast on the second run and you conclude you fixed it. Buffer counts barely move, which makes them the honest measure of whether a change helped.

The nodes you will meet

Node	Means
Seq Scan	Read the whole table. Correct for small tables and for queries returning most rows.
Index Scan	Walk the index, fetch each row. Good for few rows.
Index Only Scan	Answered from the index alone. Check `Heap Fetches`.
Bitmap Heap Scan	Collect row locations from the index, then read the table in physical order. The middle ground.
Nested Loop	For each outer row, look up inner rows. Fast when the outer side is small, catastrophic when the estimate was wrong.
Hash Join	Build a hash of one side, probe with the other. The usual choice for two large sets.
Merge Join	Both sides sorted, walked together. Good when they are sorted already.

None of these is a defect on its own. A Seq Scan on a 12-row table is right, and a Nested Loop over a 200,000-row estimate error is wrong even though nested loops are usually fine.

The settings that change what you see

Two knobs are worth knowing before you conclude a plan is the best available.

SHOW work_mem;                 -- memory per sort or hash node, per query
SET  work_mem = '64MB';        -- for this session only
EXPLAIN (ANALYZE, BUFFERS, COSTS OFF)
SELECT property_id, count(*) FROM bookings GROUP BY property_id ORDER BY 2 DESC LIMIT 5;
RESET work_mem;

work_mem is allocated per node, per parallel worker, not per query — a plan with three sorts and two workers can use many times the number you set. That is why the global default is small and why raising it for one heavy query in its own session is the safer move.

The other is a diagnostic trick rather than a fix. To find out whether an index would actually help, ask the planner to avoid the alternative and compare:

SET enable_seqscan = off;
EXPLAIN (ANALYZE, COSTS OFF) SELECT count(*) FROM bookings WHERE guests = 3;
RESET enable_seqscan;

These enable_* settings do not truly disable a node type; they make it enormously expensive, so the planner uses it only when there is no other way. Never leave one set in production. They exist to answer "would the other plan have been faster", and when the answer is yes, the fix is an index or better statistics — not the setting.

Finding the query worth fixing

Everything above assumes you know which query is slow. pg_stat_statements tells you — it aggregates by normalised query text, so a thousand executions of the same statement with different parameters are one row:

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

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

Sort by total_exec_time, not mean_exec_time. A 2-second report run once a day matters less than a 4-millisecond query run two million times, and only the total tells you which is which.

It needs shared_preload_libraries = 'pg_stat_statements' and a restart, so it is something to turn on before you need it. Every managed Postgres offers it; it is the first thing to enable on a new database.

Reset the counters when you start looking at something, so the numbers describe the period you care about rather than everything since the server last restarted:

SELECT pg_stat_statements_reset();

One habit ties this post together. When a query is slow, resist changing anything until you have the plan, the buffer counts, and the estimated-versus-actual row counts in front of you. Adding an index because a query is slow is guessing; adding one because the plan shows 200,000 rows removed by a filter is engineering — and the second kind of change is the one you can explain afterwards and undo when it turns out not to help.