Skip to content
Jot
Home
Trending
Top
Tags
Groups
Theme
Privacy·Terms
Sign in
Home
Search
Trending
Sign in
EXPLAIN ANALYZE has never lied to me — Jot

EXPLAIN ANALYZE has never lied to me

D
Dan Whitlock
·February 19, 2026·1,360 words·7 min read
debuggingmeasurementpostgressretools
☆stars: 12⑂forks: 0

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

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.

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;
 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:

create index concurrently payment_attempt_merch_cur_status_time_idx
  on payment_attempt (merchant_id, currency, status, created_at desc);
 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.

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.

->  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.

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

LineWhat it means
Rows Removed by FilterTuples fetched from the heap then discarded. Compare it against actual rows before you read anything else.
Rows Removed by Index RecheckThe bitmap went lossy. Postgres is re-evaluating the condition against every tuple on whole pages.
Heap Blocks: exact=N lossy=NAny lossy count means the bitmap did not fit in work_mem.
Index Searches: NSeparate descents of the index, new in 18. Well above loops means something like = ANY (...) is doing one descent per array element.
Buffers: shared hit / readWork 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 UsageOn a Hash node, Batches above 1 means the hash spilled to temp files.
loops=NThe 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:

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.

 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.

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.

On this page

  • The tables
  • Read Rows Removed by Filter first
  • Estimated against actual
  • Where a bad estimate comes from
  • Buffers
  • What each line is telling you
  • The index that made things worse