--- title: "EXPLAIN ANALYZE has never lied to me" author: "Dan Whitlock (@grep)" date: 2026-02-19T08:33:38.256Z updated: 2026-02-19T08:33:38.256Z canonical: "https://jot.place/@grep/explain-analyze-has-never-lied-to-me" description: "A support query that took 13.8 seconds, a report that timed out at 300, and a fix that turned out to be statistics rather than an index. Real plans, Postgres 18.2." tags: - "debugging" - "measurement" - "postgres" - "sre" - "tools" --- # EXPLAIN ANALYZE has never lied to me The planner lies all the time. It has to. It is guessing from a sample of a table it cannot afford to read. `EXPLAIN` on its own shows you the guess. `EXPLAIN ANALYZE` shows you the guess next to the receipt, and the receipt has never been wrong. Everything below is from a payments database on PostgreSQL 18.2. Names changed, numbers not. ## The tables ```sql create table payment_attempt ( id bigint primary key generated always as identity, merchant_id bigint not null, created_at timestamptz not null, currency char(3) not null, country char(2) not null, psp text not null, status text not null, amount_minor bigint not null, decline_code text ); ``` 412 million rows, 68 GB, append only, about 1.08 million rows a day. Two indexes at the start of this story: the primary key, and `payment_attempt_created_at_idx` on `(created_at)`. A second table, `refund`, holds 18 million rows with an index on `(payment_attempt_id)`. ## Read Rows Removed by Filter first This is the query behind a support tool. An agent types a merchant, a currency and a status, and gets the last few declines. ```sql select id, created_at, amount_minor, decline_code from payment_attempt where merchant_id = 44219 and currency = 'USD' and status = 'declined' and created_at >= now() - interval '7 days' order by created_at desc limit 200; ``` ```text Limit (cost=0.58..26063.64 rows=200 width=44) (actual time=13803.918..13803.921 rows=3.00 loops=1) Buffers: shared hit=41297 read=163874 -> Index Scan Backward using payment_attempt_created_at_idx on payment_attempt (cost=0.58..312884.72 rows=2401 width=44) (actual time=13803.914..13803.916 rows=3.00 loops=1) Index Cond: (created_at >= (now() - '7 days'::interval)) Filter: ((merchant_id = 44219) AND (currency = 'USD'::bpchar) AND (status = 'declined'::text)) Rows Removed by Filter: 9106438 Index Searches: 1 Buffers: shared hit=41297 read=163874 Planning: Buffers: shared hit=118 Planning Time: 0.318 ms Execution Time: 13803.954 ms ``` Three rows out. Nine million one hundred and six thousand four hundred and thirty eight rows fetched, examined and thrown away to get them. That ratio is the entire story and it is on the fourth line. The index contributed one thing, the time range. Everything else landed in `Filter`, and a filter on a scan node means the tuple was already pulled out of the heap before anything decided it was useless. The `LIMIT 200` looked cheap because the planner believed 2,401 rows would match, so it expected to walk about 8% of the week and stop. It walked all of it. Rows Removed by Filter on an Index Scan is the version people miss. Everyone is trained to be suspicious of a sequential scan with a filter. An index scan with a filter looks respectable in a plan and can be doing the same work with worse locality. The fix here is an index, and a specific one: ```sql create index concurrently payment_attempt_merch_cur_status_time_idx on payment_attempt (merchant_id, currency, status, created_at desc); ``` ```text Limit (cost=0.70..8.79 rows=3 width=44) (actual time=0.041..0.048 rows=3.00 loops=1) Buffers: shared hit=4 read=3 -> Index Scan using payment_attempt_merch_cur_status_time_idx on payment_attempt (cost=0.70..8.79 rows=3 width=44) (actual time=0.039..0.044 rows=3.00 loops=1) Index Cond: ((merchant_id = 44219) AND (currency = 'USD'::bpchar) AND (status = 'declined'::text) AND (created_at >= (now() - '7 days'::interval))) Index Searches: 1 Buffers: shared hit=4 read=3 Planning: Buffers: shared hit=142 read=6 Planning Time: 0.402 ms Execution Time: 0.071 ms ``` No `Filter` line at all, which is the thing to look for, not the timing. Seven buffers instead of two hundred thousand. The index costs 19 GB and the table takes about 41,000 inserts a minute, so that number has a bill attached, and we paid it. ## Estimated against actual Two rules and both of them get broken weekly. Read the ratio, not the difference. `rows=2401` against `rows=3.00` is a factor of 800, and a factor of 800 is what changes a plan. `rows=1000` against `rows=1400` is nothing; leave it alone. Multiply by loops. Actual rows on an inner node is an average per loop, and 18 prints it fractionally, so `rows=1.14 loops=272160` means 310,262 rows went through that node, not one. Same for the timings. The number after `..` is the average per loop, so a harmless looking 1.2 ms is five and a half minutes when it runs a quarter of a million times. ## Where a bad estimate comes from The planner keeps per column statistics and, absent anything better, assumes columns are independent. It multiplies selectivities. Here is what that costs. ```sql select r.reason_code, count(*), sum(r.amount_minor) from payment_attempt a join refund r on r.payment_attempt_id = a.id where a.currency = 'JPY' and a.psp = 'gmo' and a.country = 'JP' and a.created_at >= '2026-06-01' and a.created_at < '2026-06-08' group by 1 order by 2 desc; ``` `currency = 'JPY'` is 4.1% of the table. `psp = 'gmo'` is 3.6%. `country = 'JP'` is 4.3%. Multiply the three and you get 63 rows in a million, which over a 7.56 million row week comes to 480. In reality that PSP settles yen, from Japan, and nothing else. Every `gmo` row is a `JPY` row is a `JP` row, so the true selectivity of all three together is the selectivity of one of them: 272,160 rows. The estimate is out by a factor of 567. ```text -> Nested Loop (cost=1.13..277389.04 rows=494 width=24) (actual time=2.401..337126.402 rows=310262.00 loops=1) Buffers: shared hit=1071805 read=712447 -> Index Scan using payment_attempt_created_at_idx on payment_attempt a (cost=0.58..274931.44 rows=480 width=8) (actual time=0.771..2914.006 rows=272160.00 loops=1) Index Cond: ((created_at >= '2026-06-01 00:00:00+00'::timestamptz) AND (created_at < '2026-06-08 00:00:00+00'::timestamptz)) Filter: ((currency = 'JPY'::bpchar) AND (psp = 'gmo'::text) AND (country = 'JP'::bpchar)) Rows Removed by Filter: 7287840 Index Searches: 1 Buffers: shared hit=26914 read=1121 -> Index Scan using refund_attempt_idx on refund r (cost=0.55..5.12 rows=1 width=24) (actual time=1.223..1.228 rows=1.14 loops=272160) Index Cond: (payment_attempt_id = a.id) Index Searches: 272160 Buffers: shared hit=1044891 read=711326 ``` A nested loop is the right choice for 494 rows. For 272,160 it is a quarter of a million separate descents into an index that does not fit in the buffer cache: 6.5 buffers per lookup, seven hundred thousand of them read rather than hit, 337 seconds. The report carries a 300 second statement timeout, so what finance actually saw was a cancelled query and no reason. The fix is not an index. ```sql create statistics payment_attempt_route_stx (dependencies, mcv) on currency, psp, country from payment_attempt; analyze payment_attempt; ``` `dependencies` records that `psp` determines `currency` and `country`. `mcv` records the frequencies of the combinations that actually occur, which is what three equality clauses need. Multi column MCV lists arrived in PostgreSQL 12; functional dependencies in 10. The new estimate is 273,418, the plan becomes a hash join over a sequential scan of `refund`, and the report finishes in 19 seconds. Nothing else changed. Same tables, same text, same indexes. Two things about that: Extended statistics do nothing until `ANALYZE` runs. Autoanalyze fires at 50 tuples plus ten percent of the table, which on 412 million rows means 41 million changed tuples, so on a big append only table it effectively never fires on your schedule. Analyze the hot tables from cron and stop hoping. Extended statistics are per table. The correlation between `payment_attempt.country` and the merchant record's country is real and nothing in Postgres will ever learn it. Cross table correlation means a denormalised column or a different query. The cartographers got here first: @nullisland/every-projection-is-wrong-here-is-how-much. Every row estimate is wrong too. The only useful question is by how much and in which direction. ## Buffers As of 18, `BUFFERS` is included automatically when you use `ANALYZE`, which removes the single most common reason a plan pasted into a ticket is missing its interesting half. `hit` means the page was already in shared buffers. `read` means Postgres asked the operating system, which may itself have served it from page cache, so `read` is not the same as disk. `dirtied` and `written` appear on plain `select` queries too, which surprises people, and usually means hint bits or vacuum debt. Timing is the least portable number in a plan. Buffers is the most. A plan that touches 1.7 million buffers is doing too much work on your laptop, on the replica and in production, and the fact that it ran in 40 ms on your laptop is a statement about your page cache. ## What each line is telling you | Line | What it means | |---|---| | `Rows Removed by Filter` | Tuples fetched from the heap then discarded. Compare it against actual rows before you read anything else. | | `Rows Removed by Index Recheck` | The bitmap went lossy. Postgres is re-evaluating the condition against every tuple on whole pages. | | `Heap Blocks: exact=N lossy=N` | Any lossy count means the bitmap did not fit in `work_mem`. | | `Index Searches: N` | Separate descents of the index, new in 18. Well above `loops` means something like `= ANY (...)` is doing one descent per array element. | | `Buffers: shared hit / read` | Work measured in 8 kB pages. The only number that compares across machines. | | `Sort Method: quicksort Memory:` | Fine. `external merge Disk:` means `work_mem` was too small for this sort. | | `Buckets / Batches / Memory Usage` | On a Hash node, `Batches` above 1 means the hash spilled to temp files. | | `loops=N` | The multiplier for every other actual number on that node and everything beneath it. | ## The index that made things worse In March somebody added this for a dashboard: ```sql create index payment_attempt_status_idx on payment_attempt (status); ``` `status = 'declined'` is 11% of a 412 million row table. Here is what it did to the monthly decline aggregate, which had been an unglamorous sequential scan taking 61 seconds. ```text Bitmap Heap Scan on payment_attempt (cost=215004.18..8940112.66 rows=44803118 width=44) (actual time=4090.229..283401.774 rows=44798411.00 loops=1) Recheck Cond: (status = 'declined'::text) Rows Removed by Index Recheck: 365118442 Heap Blocks: exact=41182 lossy=7449066 Buffers: shared hit=1204 read=7685470 -> Bitmap Index Scan on payment_attempt_status_idx (cost=0.00..215004.18 rows=44803118 width=0) (actual time=4090.114..4090.115 rows=44803118.00 loops=1) Index Cond: (status = 'declined'::text) Index Searches: 1 Buffers: shared hit=182 read=196244 ``` `work_mem` is 64 MB on that replica. A bitmap covering 45 million tuples scattered over seven and a half million heap pages does not fit in 64 MB, so Postgres degrades it to page granularity, and then every tuple on every lossy page has to be rechecked. Three hundred and sixty five million rechecks. It read the same pages the sequential scan read, in the same physical order, and then did 365 million extra qual evaluations on top. Sixty one seconds became two hundred and eighty three. The planner picked it because `random_page_cost` is 1.1 on that box, set in 2019 when we moved off spinning disks, which makes every index path look cheap. Both numbers are defensible on their own. We dropped the index. An index that selects 11% of a table that size has no query it can win. If you want declines by month, put `created_at` first, or make the index partial. :::warning `ANALYZE` executes the statement. On an `insert`, `update`, `delete` or `merge`, the write happens. The documented way round it is `begin; explain (analyze) ...; rollback;` and you should type the `begin` first, before the rest of the line exists, every single time. ::: Nineteen years in and this is the only debugging tool I own that has never given me a wrong answer. It will give me an answer I do not understand. It will happily answer a question about a query I did not mean to run. But the estimates in a plan are opinions, and everything inside the parentheses after `actual` already happened.