Skip to main content
RunBook Academy

← All break/fix scenarios in PostgreSQL

advancedpg-statistics~40 min

A dashboard query went from 40 milliseconds to eleven minutes, and nothing was deployed

Reported symptoms

  • ●The operations dashboard, which has loaded in under a second for two years, begins timing out at 06:15 on a Tuesday
  • ●One query in the dashboard is responsible: it ran in 38 milliseconds on Monday and takes over eleven minutes on Tuesday
  • ●No application deployment has occurred and the query text is byte-identical to Monday
  • ●Database CPU is at 96 per cent with a single backend consuming most of it, and I/O is close to idle
  • ●The table involved has grown from 11 million rows to 51 million overnight as part of a planned historical data import
  • ●The team adds an index on the filtered column, which takes twenty minutes to build and changes nothing
  • ●Restarting PostgreSQL is proposed on the grounds that the plan may be cached

Evidence

  • · EXPLAIN ANALYZE shows a Nested Loop whose inner side is an Index Scan with loops equal to 40000000 and Index Searches equal to 40000000
  • · The outer node estimated rows=1 and produced 40000000 actual rows, a ratio of forty million to one
  • · The predicate on that node is status = imported and the value imported appears in no most_common_vals list and in no histogram for that column
  • · pg_stat_user_tables reports last_analyze and last_autoanalyze both null for the table, and n_mod_since_analyze equal to 40000000
  • · The bulk load ran between 02:10 and 05:40 and inserted 40 million rows all carrying status imported, a value that did not previously exist in the table
  • · autovacuum_analyze_scale_factor is 0.1 and autovacuum_naptime is 60, so an autoanalyze was scheduled but had not yet completed on a table of this size
  • · After a manual ANALYZE the same query plans as a Parallel Hash Join and completes in 2.4 seconds
  • · The load pipeline consists of a COPY into a staging table, an INSERT ... SELECT into the target, and a notification; it contains no ANALYZE
Diagnosis and resolutionclick to reveal

Root cause

A bulk load introduced forty million rows carrying a `status` value the planner's statistics had never seen, and the planner estimated that value would match one row. When a predicate names a value that appears in no most-common-values list and falls in no histogram bucket, the planner concludes the value is essentially absent and produces its smallest estimate. `rows=1` is not a failure of the planner; it is the correct conclusion from statistics that describe a table in which `imported` did not occur. Every decision above that node was then made on the premise that one row would arrive. A nested loop is an excellent choice for one row: run the inner index lookup once. It is a catastrophic choice for forty million, and that is what the plan did — `loops=40000000`, `Index Searches: 40000000`. The 38-millisecond runtime on Monday and the eleven-minute runtime on Tuesday are the same plan shape applied to two very different realities. The reason the statistics were absent is worth separating from the reason they were wrong. `pg_class.reltuples` scales: the planner divides the recorded tuples by the recorded pages and applies that density to the table's **current** physical size, which it measures rather than remembers. So cardinality estimates degrade gracefully when a table grows. What does not scale is the **distribution** — `n_distinct`, the most-common-values list, the histogram. Those describe the data as it was and cannot be corrected by measuring the file. This load changed the distribution. Forty million rows of a single new value is the worst case for stale statistics, and it is precisely the case where the graceful degradation does not apply. Autovacuum would have fixed it. `autovacuum_analyze_scale_factor` of 0.1 against a starting 11 million rows means an analyze was due, and it was scheduled — but an analyze of a 51-million-row table takes time, and the dashboard queries arrived first. The load pipeline had no `ANALYZE` step, so the window between "the data is visible" and "the statistics describe it" was left open. The index added during the incident could not help. The plan was already using an index on the inner side; the problem was that it was using it forty million times.

Remediation

Run `ANALYZE` on the affected table. That is the entire fix and it takes seconds to minutes: ```sql ANALYZE VERBOSE billing.transactions; ``` Confirm the statistics now describe the data before re-testing the query: ```sql SELECT attname, n_distinct, most_common_vals::text::text[] AS mcv, most_common_freqs FROM pg_stats WHERE tablename = 'transactions' AND attname = 'status'; ``` The value that was absent should now appear in the most-common-values list with a frequency close to its true proportion. Re-run `EXPLAIN ANALYZE` and check the estimate rather than only the runtime. A query that is fast because the data happens to be cached is not the same as a query that is fast because the plan is correct. Do not restart PostgreSQL. Plans are not cached across sessions in a way a restart would clear, and the proposal reflects a mental model that will send the next investigation in the same wrong direction. A prepared statement in a long-lived session can hold a generic plan, which `DISCARD PLANS` clears without a restart, but that is not what happened here — the plan was being generated fresh for each new dashboard connection from statistics that were genuinely wrong. Consider dropping the index added during the incident. It was built on a misdiagnosis, it did not help, and every index on a table is maintained on every write and disables HOT updates for any statement touching its columns. Then fix the pipeline, which is where the incident actually is.

Verification

`EXPLAIN ANALYZE` of the affected query shows an estimate within an order of magnitude of actual on every node, and a plan appropriate to the real row counts — here a hash join rather than a nested loop with forty million iterations. The runtime returns to a range consistent with the work being done. 2.4 seconds against 38 milliseconds is expected and correct: the table is five times larger and the query now matches forty million rows rather than none. `pg_stats` for the affected column contains the new value in its most-common-values list with a plausible frequency. `pg_stat_user_tables` shows a recent `last_analyze` and `n_mod_since_analyze` near zero. The dashboard loads. And the check that matters for next time: a repeat of the load into a staging copy, followed by the same query **before** any analyze, reproduces the bad plan. That confirms the mechanism rather than assuming it.

Prevention

**Put `ANALYZE` at the end of every bulk load.** It is one line, it costs seconds, and it closes the entire window between the data becoming visible and the planner knowing about it. This is the single highest-value change and it belongs in the pipeline, not in a runbook. ```sql COPY staging FROM ...; INSERT INTO target SELECT ... FROM staging; ANALYZE target; -- this line ``` **Analyze after every restore, too.** `pg_restore` leaves a database with no statistics at all, and the same failure mode is waiting there. **Alert on estimate-to-actual ratio, not only on duration.** A query slower than a threshold tells you something is wrong; a node whose actual row count is a hundred times its estimate tells you what. `auto_explain` with `auto_explain.log_min_duration` set captures the plan of the slow execution, which is otherwise unavailable after the fact. **Watch `n_mod_since_analyze`.** A large value on a large table is a statistics gap in progress, and it is visible before any query is affected. **Understand which staleness matters.** A table that has grown ten times since its last analyze still gets a reasonable cardinality estimate, because the planner scales by measured physical size. A table whose **distribution** has changed does not, and cannot. The dangerous loads are the ones that introduce new values or change the frequency of existing ones — which is most bulk loads. **Do not add an index during an incident on the theory that it might help.** It cost twenty minutes here, achieved nothing, and left behind write overhead that will outlive everyone who remembers why it exists.

Reported symptoms

The operations dashboard has loaded in under a second for two years. At 06:15 on Tuesday it starts timing out.

One query is responsible. It ran in 38 ms on Monday. On Tuesday it takes over eleven minutes. The query text is byte-identical and nothing has been deployed.

Database CPU is at 96% with a single backend consuming most of it. I/O is close to idle.

The table involved grew from 11 million rows to 51 million overnight, as part of a planned historical import.

The team adds an index on the filtered column. It takes twenty minutes to build and changes nothing. Somebody proposes restarting PostgreSQL because “the plan may be cached”.

Evidence provided

Read-only / Safeone row estimated, forty million produced
$ EXPLAIN ANALYZE on the dashboard query
 Nested Loop  (cost=0.86..18.94 rows=1 width=48) (actual time=0.041..664218.552 rows=40000000.00 loops=1)
 ->  Index Scan using transactions_status_idx on transactions t  (cost=0.43..8.45 rows=1 width=24) (actual time=0.019..21188.401 rows=40000000.00 loops=1)
       Index Cond: (status = 'imported'::text)
       Index Searches: 1
 ->  Index Scan using accounts_pkey on accounts a  (cost=0.43..10.48 rows=1 width=32) (actual time=0.014..0.014 rows=1.00 loops=40000000)
       Index Cond: (id = t.account_id)
       Index Searches: 40000000
Execution Time: 668402.113 ms

Illustrative output

Read-only / Safethe statistics have never seen this value
$ psql -c "SELECT attname, n_distinct, most_common_vals::text::text[] AS mcv FROM pg_stats WHERE tablename='transactions' AND attname='status';"
 attname | n_distinct |                  mcv                   
---------+------------+----------------------------------------
status  |          4 | {settled,pending,reversed,disputed}
(1 row)

Illustrative output

pg_stat_user_tables reports last_analyze and last_autoanalyze both null, and n_mod_since_analyze of 40,000,000.

The load ran 02:10 to 05:40 and inserted 40 million rows all carrying status = 'imported' — a value that did not previously exist.

The load pipeline is: COPY into staging, INSERT ... SELECT into the target, notify. No ANALYZE.

Work the evidence before reading on

  1. The estimate is rows=1 and the actual is 40,000,000. Is that a planner bug?
  2. Index Searches: 40000000. What decision produced that number, and which node made it?
  3. The table grew from 11 to 51 million rows. Why is that not the problem?
  4. An index was added on the filtered column and nothing changed. Why was that predictable from the plan?

Root cause

A value the statistics had never seen

The predicate is status = 'imported'. That value appears in no most-common-values list and in no histogram bucket, because when the statistics were gathered it did not exist in the table.

The planner concluded the value is essentially absent and produced its smallest estimate: rows=1.

That is not a bug. It is the correct conclusion from the information available.

Growth would have been survivable; the distribution change was not

This distinction is the useful part of the incident.

pg_class.reltuples is not trusted literally. The planner takes the density implied by the recorded tuples and pages, and applies it to the table’s current physical size, which it measures. So a table that has grown ten times since its last analyze still produces a reasonable cardinality estimate.

What cannot be scaled is the distribution — n_distinct, the most-common-values list, the histogram. Those describe the data as it was, and no amount of measuring the file corrects them.

The window was left open

autovacuum_analyze_scale_factor of 0.1 against a starting 11 million rows means an analyze was due, and it was scheduled. An analyze of a 51-million-row table takes time, and the 06:15 dashboard queries arrived first.

The pipeline had no ANALYZE. That left a window between “the data is visible to queries” and “the planner knows what the data looks like”, and the dashboard fell into it.

Resolution

ANALYZE VERBOSE billing.transactions;

Confirm the statistics describe the data before re-testing:

SELECT attname, n_distinct, most_common_vals::text::text[] AS mcv, most_common_freqs
FROM pg_stats WHERE tablename = 'transactions' AND attname = 'status';

imported should now appear with a frequency near its true proportion.

Re-run EXPLAIN ANALYZE and read the estimates, not only the runtime. A query that is fast because the data is cached is not the same as a query that is fast because the plan is right.

Consider dropping the index added during the incident. It was built on a misdiagnosis, achieved nothing, and every index is maintained on every write and disables HOT updates for statements touching its columns.

Verification

EXPLAIN ANALYZE shows estimates within an order of magnitude of actual on every node, and a plan suited to the real row counts — a hash join rather than forty million nested-loop iterations.

Runtime is consistent with the work: 2.4 seconds against Monday’s 38 milliseconds is correct, because the table is five times larger and the query now matches forty million rows rather than none.

pg_stats contains the new value with a plausible frequency.

last_analyze is recent and n_mod_since_analyze is near zero.

The dashboard loads.

And, to confirm the mechanism rather than assume it: repeat the load into a staging copy and run the same query before analyzing. The bad plan should reproduce.

Prevention

ANALYZE at the end of every bulk load. One line, seconds of cost, and it closes the entire window:

COPY staging FROM ...;
INSERT INTO target SELECT ... FROM staging;
ANALYZE target;          -- this line

Analyze after every restore. pg_restore leaves a database with no statistics at all.

Alert on estimate-to-actual ratio, not only duration. auto_explain with auto_explain.log_min_duration captures the plan of the slow execution, which is otherwise unavailable afterwards.

Watch n_mod_since_analyze. A large value on a large table is a statistics gap in progress, visible before any query is affected.

Know which staleness matters. Growth degrades gracefully; distribution change does not.

Do not add an index during an incident on a hunch. Twenty minutes, no benefit, and permanent write overhead that will outlive everyone who remembers why it exists.