S3 revisited: `statement_timeout` does half-migrate, and autovacuum is why
- Upgrade
- 26.0.0 → 26.7.1
- Scale
- 2,000,003 users · CREDENTIAL 2,000,002 rows / 105,296 pages
- Database
- PostgreSQL 16, single node, container
- Topology
- single container
- Host
- Hetzner CCX33 (fsn1) — 8 vCPU dedicated, 30 GB RAM, local NVMe
- Condition
- statement_timeout mid-flight
Summary
S3 measured correctly and concluded wrongly.
Its measurement stands: no statement in this migration takes meaningful time to execute. We re-measured the statement that matters and got 0.177 ms.
Its conclusion does not. S3 reasoned that because the longest statement was
2.142 ms, no statement_timeout value could land between "too short to start"
and "long enough to finish". That inference assumes a statement's duration is its
execution time. In Postgres it is not: a statement's duration includes the time
it spends waiting for its lock, and statement_timeout is charged for that
wait.
At 2,000,003 users, statement_timeout values of 500 ms, 200 ms and 50 ms all
leave the database half-migrated — DATABASECHANGELOG at 157 of 211,
migration_model still 26.0.0, and the server refusing to start. 1 s and 10 s
complete. The band S3 called empty is (500 ms, 1 s].
Environment
| Field | Value |
|---|---|
| Keycloak from → to | 26.0.0 → 26.7.1 |
| Distribution / start mode | quay.io/keycloak/keycloak official image, start w/ external DB |
| Database | PostgreSQL 16, single node, container |
| Postgres tuning | stock except where a leg names the variable. deadlock_timeout 1s (stock), autovacuum on (stock), statement_timeout set per leg on the keycloak role |
| Adverse scenario | S3 |
| Dataset scale | 2,000,003 users · CREDENTIAL 2,000,002 rows / 105,296 pages |
| Seeding method | seed-sql, restored from baseline-26.0.0-sqlseed-2m |
| Topology | single container |
| Host | Hetzner CCX33 (fsn1) — 8 vCPU dedicated, 30 GB RAM, local NVMe |
| JVM heap | -Xms1g -Xmx4g |
| Instrumentation | log_min_duration_statement=0, log_lock_waits=on on the diagnostic legs |
Breakage observed
A statement_timeout below one second half-migrates the database
- Symptom:
canceling statement due to statement timeouton changeset 26.2.0-26106; server exits;DATABASECHANGELOG157/211,migration_model26.0.0. - Evidence: the sweep above; Postgres log quoted in full.
- Cause: confirmed — autovacuum holds a conflicting lock on
CREDENTIALand Postgres waitsdeadlock_timeoutbefore evicting it; the wait is charged tostatement_timeout. - Fix or workaround: any one of — raise
statement_timeoutabovedeadlock_timeoutfor the migration role; lowerdeadlock_timeout; or make sure autovacuum is not mid-scan of the large tables when the window opens (VACUUMthem beforehand, or setautovacuum_enabled=falsefor the window). - Would this hit a customer? A
statement_timeouton the database role is ordinary hardening, and this is the fourth route the lab has found to a half-applied changelog. It is likeliest immediately after a restore or bulk load — which is the state of every staging rehearsal, and of a production database that has just been restored for a DR test.
Verification
| Claim | Primary source | Checked |
|---|---|---|
| 500 ms / 200 ms / 50 ms half-migrate at 2M | three runs, DATABASECHANGELOG and migration_model queried | ☑ |
| 1 s and 10 s complete | two runs, 211 rows, model 26.7.1 | ☑ |
| The failing statement is 26.2.0-26106, not the index build | Liquibase exception quoted | ☑ |
| That statement executes in well under a millisecond | F1 0.177 ms, F2 0.156 ms, F3 0.210 ms, from Postgres' log | ☑ |
| The duration is a lock wait, not execution | still waiting for AccessExclusiveLock / acquired … after 100.161 ms | ☑ |
The blocker is an autovacuum worker on CREDENTIAL | canceling autovacuum task … automatic vacuum of table "keycloak.public.credential" | ☑ |
The wait length is deadlock_timeout | E2 — 100 ms setting produced a 100.485 ms statement | ☑ |
| Turning autovacuum off makes 500 ms survivable | F3 — READY | ☑ |
| S3's own measurement was of an uncontended run | inferred from F1 reproducing 2.142 ms's order of magnitude; the original run cannot be re-inspected | ☐ |
| The autovacuum worker predicts the outcome | ten repetitions, 10/10 agreement, 7 failures | ☑ |
| Failure rate immediately after a restore | 70% (7/10) at statement_timeout=500ms | ☑ |
| Whether other version pairs have an equivalent DDL on a large table | not tested | ☐ |
Whether lock_timeout behaves differently from statement_timeout here | not tested | ☐ |