Alex Verhoevenbackend & data · amsterdam

· postgres

Reading EXPLAIN (ANALYZE, BUFFERS) without panicking

A plan is a tree of numbers that all look important. Most of them aren't. This is the order I read them in.

  1. Find the node where rows= and actual rows= disagree by ten times or more. That's where the planner was wrong, and every node above it inherited the mistake. It's almost always a stale statistic, two correlated columns the planner thinks are independent (CREATE STATISTICS exists for this), or a function wrapped around a column.
  2. Look at loops=. The times and rows on a node are per loop. rows=1 loops=48213 is 48,213 index lookups, and the 0.016 ms next to it needs multiplying before it means anything.
  3. Look at Rows Removed by Filter. A large number here means the index fetched the wrong rows and the filter threw them away. Usually the column order in a composite index, sometimes a missing index entirely.
  4. Only now, Buffers. shared read is what came from disk or the OS cache rather than shared buffers; a node with millions of reads is I/O-bound and no amount of CPU will help. temp read/written means a sort or hash spilled; that's work_mem.
  5. Last, the total time. It's the number everyone looks at first and it tells you the least, because you already knew the query was slow.

An example, trimmed:

Nested Loop  (cost=0.86..5240.12 rows=12 width=64)
             (actual time=0.091..812.330 rows=48213 loops=1)
  ->  Index Scan using orders_created_idx on orders o
        (cost=0.43..184.20 rows=12 width=40)
        (actual time=0.030..9.412 rows=48213 loops=1)
        Index Cond: (created_at >= '2023-11-01')
        Filter: (status = 'paid')
        Rows Removed by Filter: 3120
  ->  Index Scan using customers_pkey on customers c
        (cost=0.43..0.47 rows=1 width=24)
        (actual time=0.015..0.016 rows=1 loops=48213)
        Index Cond: (id = o.customer_id)
        Buffers: shared hit=192851 read=1044

The whole story is rows=12 against rows=48213 on the first index scan. The planner expected twelve orders since the first of the month, chose a nested loop on that basis, and then did 48,213 primary-key lookups into customers. With a correct estimate it would have hashed customers once. ANALYZE orders fixed it; the statistics had gone stale after a bulk load the night before, and autovacuum hadn't caught up. Nothing about the query was wrong. Nothing about the indexes was wrong. Step one, every time.