Reading a query plan

Article.

A query is slow. You have its plan. Everything after that is a method, and the method is not “look for Seq Scan” — it is finding which node actually consumed the time, then asking why the planner chose it. Most people never get past the first step, because the two numbers that tell you where the time went are both easy to misread.

Every plan below is real output from PostgreSQL 18.4.

Get a plan worth reading

EXPLAIN (ANALYZE, BUFFERS, SETTINGS) SELECT ...;   -- BUFFERS is the default from 18

EXPLAIN alone shows what the planner intends — estimates only, no execution. That is enough to check whether an index would be used, and it is all you get for a query you dare not run.

ANALYZE executes the query and adds what really happened. BUFFERS adds the I/O, which is the difference between “slow” and “slow because it read 40,000 pages off disk”. SETTINGS reports any non-default planner configuration, which matters when a plan differs between two machines and nobody remembers that one has random_page_cost = 1.1.

Turn on track_io_timing as well, and BUFFERS gains I/O Timings: how long the reads actually took, not only how many there were.

ANALYZE really runs it. On a DELETE that is not a drill:

BEGIN;
EXPLAIN ANALYZE DELETE FROM invoice WHERE created_at < '2020-01-01';
ROLLBACK;

The two numbers that lie

A join of 100,000 orders to their customers, half of them pending. The statistics were taken when the table held 50 rows:

Nested Loop (cost=0.29..887.44 rows=1 width=6)
            (actual time=0.053..71.320 rows=49975.00 loops=1)
  Buffers: shared hit=150466
  ->  Seq Scan on orders2 o (cost=0.00..879.12 rows=1 width=4)
                            (actual time=0.017..10.400 rows=49975.00 loops=1)
        Filter: (status = 'pending'::text)
        Rows Removed by Filter: 50025
  ->  Index Scan using customer_pkey on customer c
        (cost=0.29..8.31 rows=1 width=10)
        (actual time=0.001..0.001 rows=1.00 loops=49975)
        Index Cond: (id = o.customer_id)
        Index Searches: 49975
        Buffers: shared hit=149925
Execution Time: 73.027 ms

The index scan reports actual time=0.001..0.001. One microsecond. It is also where most of the time and nearly all of the I/O went. (Since 18, row counts print with two decimals, because they are averages over loops.)

loops multiplies

On an inner node, actual time and rows are per-loop averages, not totals. That index scan ran 49,975 times:

0.001 ms × 49,975 loops ≈ 50 ms of the 73 ms
149,925 buffers out of 150,466

That is the query. The Seq Scan everyone’s eye jumps to cost 10 ms and 541 buffers.

So the first rule of reading a plan: multiply by loops before comparing anything. A node showing microseconds and a six-figure loop count is the usual culprit, and it never looks like one.

actual time is inclusive

The second misread: a node’s actual time includes all of its children. The Nested Loop above shows 71 ms, but it did almost no work itself — it inherited the time from the scans it drove.

To get a node’s own cost, subtract its children:

own = actual_time × loops
      - Σ(child actual_time × child loops)

Read a plan inside-out, from the most deeply nested node upward. The outermost line is a total, not a suspect.

Why the planner chose it

Now the diagnosis. The plan above says rows=1 estimated against rows=49975 actual on the Seq Scan — off by four orders of magnitude.

That single bad estimate caused everything else. Believing it would get one row, a nested loop with an indexed inner side is genuinely the best plan. At 49,975 rows it is the worst one available; a hash join would have read customer once. The planner was not wrong about strategy, it was wrong about size, and row estimates compound upward — a bad number at a leaf produces a catastrophic join order at the top.

So the question is never “why did it pick a nested loop”. It is “where did the estimate first go wrong” — find the deepest node whose estimate is badly off, and fix that.

What the three join strategies mean when you see them

The estimate decides the strategy, so recognising the strategy tells you what the planner believed.

Nested Loop scans the inner side once per outer row. With an index that is cheap per iteration, which is why it wins on small outer inputs — and why it degrades so violently when the estimate is wrong, since cost scales linearly with a row count the planner underestimated.

Hash join and its memory

Hash Join builds a hash table from the smaller side, then streams the larger one past it. It reads each side once, so it does not care how bad the outer estimate was.

The catch is memory. A hash table may use work_mem × hash_mem_multiplier (2.0 by default); beyond that it splits into batches written to disk. With work_mem = 256kB, the 100,000-customer hash showed:

Hash (actual rows=100000.00 loops=1)
  Buckets: 16384  Batches: 16  Memory Usage: 399kB

Batches: 1 means it fitted. Raise work_mem for the session or role rather than globally — it applies per sort or hash node, per connection, so a global increase multiplies by concurrency.

Merge Join needs both inputs sorted on the join key. It is uncommon in OLTP, because a sort is expensive unless an index supplies the order for free. Seeing one usually means both sides came off indexes in the right order, or the planner decided the data was large enough that sorting beat hashing.

A hash join that turned into a nested loop is the classic overnight regression. Nothing changed but the statistics.

The fix ladder

1. Stale statistics. The cheapest and most common cause.

ANALYZE orders2;

On the plan above it changed everything: the estimate became 50,127 rows, the plan a Hash Join, and the buffers fell from 150,466 to 1,082.

If the table changes fast and this keeps recurring, autovacuum is not analysing often enough — lower autovacuum_analyze_scale_factor for that table rather than running ANALYZE from cron.

2. Correlated columns. This one is invisible until you know it exists. The planner assumes columns are independent and multiplies their selectivities:

SELECT * FROM address WHERE city = 'Paris' AND country = 'France';

If 1% of rows are Paris and 5% are France, the planner estimates 0.05% — but every Paris row is a France row, so the true answer is 1%. It underestimates by twentyfold, and on a bigger schema by far more. Extended statistics teach it the dependency:

CREATE STATISTICS addr_city_country (dependencies)
    ON city, country FROM address;
ANALYZE address;

When it is not the statistics

3. An expression the planner cannot see through. WHERE lower(email) = $1 has no statistics on lower(email), so it falls back to a fixed guess. An expression index both fixes the estimate and enables the scan:

CREATE INDEX ON users (lower(email));

4. The estimate is right and the plan is still bad. Rare, and this is where you look at work_mem, random_page_cost, or whether the query itself should change.

Nodes worth recognising

All of these lines are from runs on the tables above:

Sort Method: external merge  Disk: 2080kB     the sort spilled to disk
Sort Method: top-N heapsort  Memory: 25kB     LIMIT kept only the top rows
Heap Blocks: exact=285 lossy=815              the bitmap outgrew work_mem
Rows Removed by Index Recheck: 25             the price of lossy pages
Memoize  Hits: 19899  Misses: 100             inner lookups cached (14+)
Incremental Sort                              input sorted on a prefix (13+)
Workers Planned: 2  Workers Launched: 0       no parallel workers free
Heap Fetches: 999000                          an index-only scan that was not

• Lossy bitmaps. When the bitmap of matching rows does not fit in work_mem, it remembers whole pages instead of rows, and every row on a lossy page is rechecked.
• Workers Launched: 0. Parallel workers come from max_parallel_workers (8) and max_worker_processes, shared by every session. When they are used up, the query runs serially with a plan costed for parallelism. Per-worker rows are averaged across loops, like inner nodes.
• JIT. Above jit_above_cost (100,000) PostgreSQL compiles expressions to machine code. On a small query with the thresholds forced to zero:

JIT:
  Functions: 3
  Timing: Generation 0.517 ms, Inlining 59.866 ms, Optimization 9.496 ms,
          Emission 14.722 ms, Total 84.601 ms
Execution Time: 150.409 ms          -- 0.058 ms with jit = off

Mid-size OLTP queries whose estimated cost crosses the threshold can pay that compilation on every execution. If the JIT: block shows compile time larger than the work, set jit = off for the database or role.

Fast in EXPLAIN, slow in the application

EXPLAIN ANALYZE in psql says 40 ms; the endpoint spends two seconds on the same SQL. Three common reasons, all measurable.

A generic plan

Drivers prepare statements: psycopg 3 after 5 executions (prepare_threshold), asyncpg always, PgBouncer 1.21+ passes them through. After five executions PostgreSQL may switch a prepared statement to a generic plan, one plan for every parameter value. On a skewed column (999 of 1,000 jobs done), the generic plan used the index that suits the rare value:

PREPARE q(text) AS SELECT count(*) FROM jobs WHERE status = $1;
EXPLAIN EXECUTE q('done');                       -- what the app runs
EXPLAIN (GENERIC_PLAN) SELECT count(*) FROM jobs WHERE status = $1;
SET plan_cache_mode = force_custom_plan;          -- per session or role

A psql EXPLAIN with a literal never shows the generic plan, so the reproduction is PREPARE and EXECUTE. Here the planner stayed on custom plans by itself, because it judged the generic plan more expensive; with a less obvious skew it switches, and the slow case is the one you cannot reproduce by pasting the query.

Sending the rows

Plain EXPLAIN ANALYZE runs the query but discards the output, so it never detoasts large values or converts them to text:

EXPLAIN ANALYZE SELECT * FROM docs;              Execution Time: 2.185 ms
EXPLAIN (ANALYZE, SERIALIZE) SELECT * FROM docs;
  Serialization: time=25.678 ms  output=250283kB  format=text
                                                 Execution Time: 28.495 ms

Twelve times longer, for 250 MB the application would have had to receive. SELECT * with large text or jsonb columns is this case.

Outside the database

What remains is the network and the client: rows sent over a slow link, and an ORM building objects from them. Compare pg_stat_statements’ time for the query with the time the application measures around it; the difference is not in the plan.

What BUFFERS tells you that timing cannot

Index Scan using idx_invoice_customer on invoice
  Buffers: shared hit=12 read=4820 dirtied=3

• hit — found in shared buffers. Effectively free.
• read — went to the OS or disk. The expensive one.
• dirtied — pages this query modified, which someone must write later.

Timing alone is not reproducible; buffer counts are. The same query is fast on the second run purely because the cache is warm, so a benchmark that runs a query twice and reports the second number is measuring your cache. Buffer counts barely move between runs, which makes them the honest metric when comparing two versions of a query.

Thousands of reads means the working set does not fit in shared_buffers, or you are touching far more of the table than you need to.

Where this breaks in production

The plan you cannot reproduce. The query is slow in production and fast on your laptop, because production has different statistics, different data volume and a warm cache. Running EXPLAIN ANALYZE locally tells you about your laptop.

Capture the real thing:

-- postgresql.conf (restart), or LOAD 'auto_explain' in one session
shared_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '500ms'
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_timing = off          -- row counts without clock overhead
auto_explain.sample_rate = 0.1         -- instrument one statement in ten
auto_explain.log_nested_statements = on

auto_explain logs the plan for anything slower than the threshold, as it ran, with production data and with the parameters the application really sent, which also catches the generic plans above. log_analyze instruments every statement, not only the slow ones, so on a hot path keep log_timing off and sample. Pair it with pg_stat_statements for the aggregate view of which queries deserve attention at all.

Timing overhead distorting the measurement. On a plan with millions of loops, the instrumentation itself is measurable. EXPLAIN (ANALYZE, TIMING OFF) keeps the row counts and drops the per-node clock reads, which is what you want when you only need to know where the rows went.

The plan that changes under you. Nothing pins a plan. An ANALYZE, a growing table, or a parameter value that lands in a different histogram bucket can flip a join strategy overnight. That is why a fix is “make the estimate right”, not “make it use the index this once”.

The trade Postgres did not take

Oracle and SQL Server let you pin a plan with hints. Core PostgreSQL deliberately has none, and the reasoning is that a hint is a lie that ages: it encodes today’s data distribution into the query text, and keeps being obeyed long after it stopped being right.

So the levers are indirect — statistics, indexes, work_mem, or rewriting the query. It is more work up front and it does not rot. When someone asks how to force an index, the answer is that you fix the reason the planner does not want it, and SET enable_seqscan = off is a diagnostic for confirming a hypothesis in a session, never a fix.

The escape hatches exist outside core: the pg_hint_plan extension adds hints in comments, and Aurora PostgreSQL has Query Plan Management to pin approved plans. They are worth knowing as the option you are choosing not to use, or the last resort for a plan regression in a query you cannot change.

Related

• How a B-tree index works - what the scan nodes are scanning
• CTEs and recursive queries - spotting a materialised CTE in a plan
• VACUUM, autovacuum, table bloat, and transaction wraparound - why statistics go stale
• pg_stat_statements - which queries to look at first