Repository navigation
Query Store compose rollup retries a timed-out hour verbatim every tick and never builds it #5867
Description
Claude posting for Erik Darling.
What happens
After nightly 553 (3.10.0-nightly.20261015.553, dev ab5b0b7) was installed on a 42-server store at 14:04Z, the hourly Query Store compose tick logs this line every hour, for the same hour each time:
Query Store compose rollup: building hour 2026-10-07 15:00 (stale False) failed and is retried next tick: 57014: canceling statement due to statement timeout
It fired at 14:05:36Z and 15:06:13Z. There were 0 such lines in that store's logs from 10-12 to 10-14, so it is new since the 553 restart. The hour is 8 days old, and stale False means the plan sees it as a missing hour, not a stale one.
Cause (inferred from the code, not yet measured on the store)
RunTickAsync (Darling/PerformanceMonitor.Darling.Storage/QueryStoreComposeStamp.cs:856-900 on dev 456b1a3) plans every missing or stale hour inside retention and builds each one with BuildHourAsync on the tick's connection, under the store's statement timeout. When a build throws, the tick counts it as failed, logs the warning above, and the next tick plans the same hour again and runs the same build. Nothing counts the retries, raises the timeout for a build that has already timed out, splits the hour, or tells the operator anything beyond one WARN per tick. A build that cannot finish inside the statement timeout therefore fails the same way every hour for as long as the hour is inside retention.
Why this hour is missing on this store, and why its build runs past the timeout while the other hours build, is not known yet. The next field read asks for the hour's row count in the source table against a normal hour, the store's statement_timeout, and whether the hour has a stamp row at all.
Effect
- The hour is never composed, so every read of the rollup misses 2026-10-07 15:00 on this store.
- One WARN per tick per such hour, with no end.
- Each tick spends up to the statement timeout on a build that cannot finish, before it moves on.
What should change
- Find why the build of this hour exceeds the statement timeout (the hour's size, the plan), and fix that if it is a plan or an index problem.
- A build that timed out is not retried verbatim every tick. Pick one: back off after a few failures and record the hour as failed with its reason where
get_store_metricsor a self-alert can show it, retrying once a day; or run a single-hour build under its own longer timeout; or build the hour in parts. - A behavior test: a build that throws N times is not planned again on the next tick as if nothing happened, and the failure is visible to the operator.
Activity
erikdarlingdata commentedon Oct 15, 2026
Claude posting for Erik Darling.
Field reading on store A (16:57Z and 17:14Z), from the service log,
query_store_compose_stamp_hours, three count reads in a quiet slot and the catalog views. Reads only.WideHorizonDaysfrom 9 to 10 in nightly 553, so the builder backfills them, 4 to 5 per tick, newest first.query_store_interval_wide_legacy(rows with first_execution_time before 2026-10-11; the daily partitions start at p20261011): 41.1 M live rows, 12.99 M pages, 99 GB, fillfactor 50. Its BRIN (ix_query_store_interval_wide_collection_time_brin_legacy, autosummarize=off, 3.4 MB) returns about 1.95 M blocks for a one-hour range, about 15% of the partition and about 15 GB: about 655,000 lossy heap blocks per worker, about 14 M rows removed on recheck. An empty, purged hour costs the same read. On a daily partition the same predicate costs a few thousand blocks.SET LOCAL statement_timeout = '60s'. The first old hour of the tick reads cold: 80 s. The next ones read warm: about 10 s. So the newest missing hour fails every tick and the other four pass. Ticks since 553: "built 5 hour(s) (stale 0, missing 5), failed 1", 103 to 139 s each. The WARN fired at 14:05, 15:06 and 16:06Z, one line, no stack.Why the legacy BRIN cannot narrow (settled by the catalog, no writes): its ranges were summarized, then widened by churn. The legacy partition took 110 M inserts and 81 M deletes (the hourly purge) on a fillfactor-50 heap, plus 120 M HOT updates, so new rows landed in pages older rows had freed, and a BRIN range's min and max never shrink. Its collection_time correlation is -0.30; the daily partition p20261014 (0 deletes) is at 0.998. Autovacuum ran 103 times on the legacy partition, last at 03:52Z today with 0 inserts since, so "never summarized" is out.
What follows for the fix: the retry after a timeout runs at 240 s, which covers the cold read; failed hours go last so the warm builds run first; no index is added to the legacy partition and it is not rebuilt (it leaves the horizon about 10-21, and the daily partitions do not have the problem because they are dropped whole instead of purged). The PR body says whether the upsert rewrites collection_time in place, which would widen ranges on daily partitions too.
Merge origin/dev into fix/5867: #5829 keeps V186, the compose failure…
Rung tests: V187 is the probe's newest sentinel; DropV187SentinelAsyn…
Compose rollup self-alert: its failure-record read is counted on the …
V187 rung fallout in the partition rung test; the self-alert read res…
Compose rollup self-alert: its worker read is its own member, registe…
Compose rollup retry backoff: rename the failures column to retry_at,…
Query Store compose rollup: a failing hour backs off to once a day, w…
erikdarlingdata commentedon Oct 15, 2026
Claude posting for Erik Darling.
Fixed by #5871 (3011696) on dev.