TT Lab
Get started
Learn Learning paths Courses

PostgreSQL Incident Response

The Query Is Unchanged but the Plan Is Not

Continue in TT Lab

In one line

If the query and the index are unchanged but it suddenly becomes slow one day, what changed is the numbers the optimizer holds. And if a table does not shrink, it is not because there is nothing to delete but because it is not yet known whether it is safe to delete.

Why this was needed

An aggregation API took 40 milliseconds yesterday and takes 6 seconds today. There was no deployment. The index is unchanged. The data did grow, but about threefold, not a hundredfold.

The most common response in a case like this is to create one more index, and usually that is not the answer. If you open the execution plan, the reason is written on a single line.

How it works

If you add EXPLAIN (ANALYZE, BUFFERS), each plan node shows two sets of numbers. The rows= in the first parentheses is the estimate, and the rows= in the second parentheses is the actual. This was captured as is in the lab environment.

 Aggregate  (cost=1988.00..1988.01 rows=1 width=8) (actual time=8.282..8.282 rows=1 loops=1)
   Buffers: shared hit=988
   ->  Seq Scan on events  (cost=0.00..1988.00 rows=1 width=0) (actual time=0.925..5.801 rows=60000 loops=1)
         Filter: (tenant_id = 41)
         Rows Removed by Filter: 20000

Estimated 1 row, actual 60000 rows. This one line explains the whole incident of that day. The optimizer believed this condition would return a single row, so it chose a nested loop that matches that one row against every row of the other table. In reality 60,000 rows came back, so that loop ran 60,000 times.

Why did it think 1? Because a new tenant was bulk loaded and ANALYZE was not run. pg_stats still holds the distribution from before the load, and tenant_id = 41 does not exist in it. When you ask about a value that does not exist, the optimizer answers "almost none."

These are values measured in the same environment.

통계가 낡은 상태   Nested Loop   실행 3059 ms
analyze events;
통계를 고친 뒤     Hash Join     실행   66 ms

All that changed was the numbers the optimizer holds, not the query or the index. The first number fluctuated between 1.5 and 6 seconds over repeated measurements. It is correct to look at the ratio, not the absolute value.

There is one trap when reading. If loops= in the plan is not 1, the displayed rows and time are a per-loop average. In a parallel plan each worker runs once, so rows=100000 loops=2 actually means 200,000 rows. It is a confusing spot, so when you need to read the numbers exactly, it is better to turn parallelism off with set max_parallel_workers_per_gather = 0 and produce the plan once more.

Does adding an index help

For the same incident, I created an index on events(tenant_id) and measured again. The values below were measured with 200,000 rows.

인덱스 없음 · 통계 낡음    9774 ms   Nested Loop / Seq Scan     예상      1행
인덱스 있음 · 통계 낡음     205 ms   Nested Loop / Index Scan   예상      1행
인덱스 없음 · 통계 정상      60 ms   Hash Join  / Seq Scan      예상 234564행

The index clearly helps. 9.7 seconds became 0.2 seconds. But the plan is still wrong. The estimate is still 1 row, and the optimizer still chooses a nested loop. The one with corrected statistics is more than three times faster even without the index.

This is why you must not touch the index first. The symptom shrinks but the cause remains, and an index charges a cost on every write. The next time a bulk load lands in the same table, the same thing repeats.

To add to that, it is not true that an index is always a loss either. With the index left in place and the statistics fixed, the optimizer decided not to use the index and produced 46 milliseconds, but when I forced it to use it with enable_seqscan = off, it was actually faster at 33 milliseconds. That was because the whole table was inside shared_buffers and the rows being looked for were physically clustered together. Neither "it is fast if there is an index" nor "an index is a loss for large results" can be known until you measure on the spot. The order is to first get the plan's estimate and actual to agree, and only then measure.

Why does the table grow even though you updated it

PostgreSQL does not modify rows. It writes a new version and leaves a mark on the old version saying "not visible after this transaction." So UPDATE is effectively an insert, and DELETE does not free the space either. The old versions that remain are dead tuples.

This is the result of running an update that changes just one column on 60,000 rows.

갱신 전   9,945,088 바이트
갱신 후  17,358,848 바이트     n_dead_tup = 60000

Without adding a single character, the table became 1.7 times larger. Undoing this is the job of VACUUM, and normally autovacuum does it on its own.

The horizon — why vacuum cannot clean up

But there are cases where running VACUUM by hand does not shrink anything. Vacuum tells you the reason itself.

tuples: 0 removed, 131456 remain, 60000 are dead but not yet removable
removable cutoff: 970, which was 10 XIDs old when operation ended

It is not "there is nothing to delete" but "it cannot be deleted yet." That is because a transaction that is still open might yet see those old versions. That boundary is the removable cutoff, and its value is set by the oldest live transaction.

When you look for who is holding it, people usually scan backend_xmin, but if you look only at that you will not find it.

 pid  | application_name |        state        | backend_xid | backend_xmin
------+------------------+---------------------+-------------+--------------
  941 | nightly-batch    | idle in transaction |         932 |
  947 | api-order        | active              |         933 |          932
  949 | api-cart         | active              |         934 |          932
 1050 | psql             | active              |             |          932

The one holding the cutoff is 941, but the backend_xmin of 941 is empty. That is because it holds the horizon with its own transaction id, backend_xid 932. Conversely, 947, 949, and 1050, which carry 932 in backend_xmin, merely reflected in their own snapshots the fact that 941 is still alive. Even if you terminate them, the horizon does not move.

There is only one way to find it — the oldest backend_xid.

select pid, application_name, backend_xid, now() - xact_start as age
  from pg_stat_activity
 where backend_xid is not null
 order by age(backend_xid) desc limit 1;

And 941 is the very session you already saw in the earlier lock chain. There are two symptoms but one cause. That the cause of a table not shrinking may not be inside that table — this is what this course is trying to teach.

What it looks like in the field

First, the last line of a bulk load script is ANALYZE. Autoanalyze does run eventually, but nobody knows when, and those few minutes are the outage time. The cheapest thing is for the person who loaded the data to add one line right there.

Second, remember that the cause may be outside the table. When you get a report that "only this table keeps growing," you start digging into that table's indexes or load pattern, but in this incident the table is not at fault. Once n_dead_tup is large and VACUUM answers not yet removable, from then on you have to look not at the table but at the list of transactions.

Third, n_dead_tup is a statistic, not a measurement. It is a value updated by the statistics collector, so it may differ from the real figure. If you want to be sure, it is better to read the output of VACUUM (VERBOSE). That output includes the cutoff too, so it tells you "why it could not clean up" in one go.

What you will do in the next lab

You receive a database showing three symptoms at the same time — a lock chain, a collapsed execution plan, and a bloated table — extract the evidence for each as numbers, and finally tie it together into a single diagnostic report. The grader pulls the numbers you wrote down again from the live database and checks them, so how you found them is up to you and you pass when the diagnosis is correct.