Repository navigation
Query Store compose rollup: a failing hour backs off to once a day, with a longer timeout after a timeout (#5867) - #5871
Conversation
… a longer timeout after a timeout, then once a day (#5867) A build that throws is now recorded per hour in collect.query_store_compose_stamp_failures (V186, renumbered at merge if taken). The next tick retries it, under a 240 s statement timeout after a statement timeout; after 3 failures in a row, or a timeout under the longer timeout, the plan skips it until its daily attempt, and the WARN is one line a day. A success clears the record. Hours that failed before run last in the tick. get_store_metrics lists the hours (query_store_compose), and the Compose Rollup Hours Stuck self-alert fires while any hour is in daily backoff. Checkpoint: the viewer-probe ordinal pins of the rung tests still expect V185 as the top rung (see the PR body).
… record moves to V187 (#5867)
…tarts its clock between the open and the read (#5867)
…red with the alerting census as exempt (#5867)
| /// <summary>The store schema version of the rung that creates <see cref="FailuresTable"/> (V186, #5867). The number is the next | ||
| /// free rung when this was written; it is renumbered at merge if another rung took it first.</summary> | ||
| public const int FailuresRungVersion = 186; |
There was a problem hiding this comment.
The renumber to V187 missed this constant — it still names V186, which is a different rung.
S1's note says "This branch's query-store-compose-failures is now V187 (V187Sql), and StorageVersion.SchemaVersion is 187", and the tree agrees at PgMigrations.cs:1631 (new Migration(187, "query-store-compose-failures", V187Sql)) and StorageVersion.cs:20. But this constant — whose own doc comment predicts exactly this ("it is renumbered at merge if another rung took it first") — still reads 186, and 186 is now #5829's collection-log-hourly rung, which does not create collect.query_store_compose_stamp_failures.
Nothing reads it today (grep -rn FailuresRungVersion finds only the declaration and the <see cref> on ReadFailuresAsync), so there is no runtime defect in this PR. That is also what makes it durable: it is a public const on a public static class stating the wrong rung, with no pin to fail, so the first consumer that gates on it — "is this store at the failures rung?" — gets true on a V186 store where the table is absent. The ReadFailuresAsync doc that cites it ("Empty on a store below FailuresRungVersion") is wrong by one rung for the same reason.
Two more V186 labels in the same file were missed by the renumber, including one in the shipped SQL text that lands in the store:
:318—/// V186 (#5867): the failure record of the hours whose build threw.:324—/* V186 (#5867): one row per Query Store compose hour whose last build failed: ... */insideFailuresCreateSql- and
Darling.Tests/QueryStoreComposeStampLiveTests.cs:410—/* Four since V186 (#5867) added the failure record. */
| /// <summary>The store schema version of the rung that creates <see cref="FailuresTable"/> (V186, #5867). The number is the next | |
| /// free rung when this was written; it is renumbered at merge if another rung took it first.</summary> | |
| public const int FailuresRungVersion = 186; | |
| /// <summary>The store schema version of the rung that creates <see cref="FailuresTable"/> (V187, #5867). The number is the next | |
| /// free rung when this was written; it is renumbered at merge if another rung took it first.</summary> | |
| public const int FailuresRungVersion = 187; |
| /* The client waits 30 s past the server's timeout, so the server's cancel (57014, which the failure record keys on) arrives first. */ | ||
| var commandTimeout = Math.Max(CommandTimeoutSeconds, statementTimeoutSeconds + 30); |
There was a problem hiding this comment.
The 270 s client timeout reaches one of the build's eight commands; the other seven keep 90 s, so on an extended attempt the CLIENT cancels first — the opposite of what this comment promises.
commandTimeout is computed here (270 s for a 240 s attempt) and then used at exactly one site, :946 (BuildHourInsertSql). Every other command in BuildHourAsync still carries CommandTimeout = CommandTimeoutSeconds, which is BuildStatementTimeoutSeconds + 30 = 90, a compile-time constant that does not move with statementTimeoutSeconds:
:905StatementTimeoutSql(...):910HourLockSql:916OpenWriterSql:929ReadPairsSql:940DeleteHourSql:953SourceRowsSql:959UpsertBuiltSql:968UpsertHourSql:975ClearFailureSql
SET LOCAL statement_timeout is per transaction, so the server grants every one of those statements 240 s while the client waits 90. The comment's invariant — "the client waits 30 s past the server's timeout, so the server's cancel (57014, which the failure record keys on) arrives first" — holds only for the insert.
Failure scenario: the hour this feature exists for (the field's 8-day-old 2026-10-07 15:00) gets its extended attempt. BuildHourInsertSql runs 170 s inside its 270 s budget, then SourceRowsSql — a count over the same wide-table rows the insert just aggregated, on the same churned legacy partition S1 measured at 99 GB / 41 M rows with collection_time correlation −0.30 — takes past 90 s. Npgsql's command timeout fires, sends a cancel, and the server raises 57014. RecordFailureAsync is then called with timeoutSeconds: 240, so RecordFailureSql's EXCLUDED.last_sqlstate = '57014' AND EXCLUDED.last_timeout_seconds >= $7 is true and the hour backs off to once a day at once — on an attempt that never actually got its 240 s. The body's "(d) What store A should do after this lands … it runs last, after the warm builds, under 240 s, and builds (about 80 s cold). The backlog then clears at 4 to 5 hours per tick" is predicated on the 240 s reaching the whole build.
Simplest fix is to hand commandTimeout to every command in the method rather than to the insert alone — the normal path is unaffected, because at statementTimeoutSeconds = 60 commandTimeout is already 90.
| composeFailures = null; | ||
| } | ||
|
|
||
| var (composePage, composeTruncated) = McpHelpers.BoundPage(composeFailures ?? Array.Empty<QueryStoreComposeStamp.HourFailure>(), limit); |
There was a problem hiding this comment.
limit now bounds four lists, but the tool description still says three and never names query_store_compose — and the sibling pin that would have caught it was moved instead.
This is the fourth McpHelpers.BoundPage(..., limit) in the tool, and StoreMetricsSummaryFirstTests.cs:342 was updated to Assert.Equal(4, …) with the comment "Four since #5867 added the Query Store compose failure list". Two tests above it, StoreMetricsSummaryFirstTests.cs:311 still asserts the description's own count:
Assert.Matches(@"SUMMARY FIRST: by default[^.]*three ranked lists, each bounded by limit[^.]*truncated", description);
and the description it reads is unchanged, so the two pins in one file now contradict each other about how many lists limit governs — and both pass, which is the problem. Stale in three places:
:40— "the store-level blocks plus three ranked lists bounded by limit":77— "SUMMARY: store blocks + 3 ranked lists bounded by limit":82— "and three ranked lists, each bounded by limit with its match count and truncated: objects …, fastest_growing … and background_jobs …"
An agent reading :82 is told the three lists limit bounds, by name. It hits query_store_compose.truncated: true on a store with more failing hours than limit, finds the block in neither the enumeration nor the description at all, and has nothing to tell it that raising limit is the lever — ViewNote's "raise limit (now N) for more" sentence is attached to objects only. This is also the one block in the payload with no description: inventory, retention, job_history and checkpointer each get a paragraph.
McpPageContractTests.PgPagedToolsThroughTheHelper (:945) does not roster get_store_metrics, so no page-contract sweep reaches this fourth page either — the trap's own words, "A roster-based census does not see the file it does not roster". Worth adding a sentence to :82 naming the block, its keys and that limit bounds hours[] with hours_returned/truncated, and moving the :311 regex to four.
Two smaller things in the same hunk:
- The checkout count in the neighbouring comment is now stale.
:161-165goes out of its way to say "That is a third pooled checkout per call, which is cheap but is not free, and saying so is the point — a comment that overstates what the code does is worse than none." This block is a fourth, plus ato_regclassprobe round trip insideReadFailuresAsync. - The
catchat:181discardsexwithout a log line, whileloggeris in scope right above (:169passeslogger: nulldeliberately). The payload does saystate = "Unreadable", so this is not a silent swallow from the caller's side, but nothing on the service side records why the read failed.
| ( | ||
| SELECT u.hour, u.stale, u.blocked, row_number() OVER (PARTITION BY u.stale, u.blocked ORDER BY u.hour DESC) AS rn | ||
| SELECT u.hour, u.stale, u.blocked, coalesce(f.failures, 0) AS failures, | ||
| coalesce(f.last_sqlstate = '57014', false) AS extended, |
There was a problem hiding this comment.
Non-blocking, but it is the shape trap #3684 names — "Two copies of one definition pinned EQUAL to each other fail only after BOTH have drifted. Alias, do not copy."
'57014' is now written as a bare SQL literal three times — here, and twice in RecordFailureSql (:599 in the INSERT arm, :608 in the DO UPDATE arm) — beside StatementTimeoutSqlState = "57014" at :122, with nothing holding them equal. What makes it stand out is that RecordFailureSql already parameterises the other three knobs in the very same CASE: $6 is FailuresBeforeBackoff, $7 is ExtendedBuildStatementTimeoutSeconds, $8 is BackoffInterval. The fourth constant in that expression is the only one hardcoded, so a future edit to StatementTimeoutSqlState moves the C# reader (LogFailure's extendedNext test at :1055) and leaves both the plan's extended flag and the backoff decision keyed on the old code.
57014 is fixed by PostgreSQL, so drift is unlikely in practice — the cost is that the SQL no longer says why that string matters. A $9::text bound from the constant (or string interpolation over it, as FailuresTable is interpolated at :1019) would make the three agree by construction.
| await built.ExecuteNonQueryAsync(cancellationToken); | ||
| } | ||
|
|
||
| await using (var failures = new NpgsqlCommand(GcFailuresSql, connection, transaction) { CommandTimeout = CommandTimeoutSeconds }) |
There was a problem hiding this comment.
Non-blocking: the method's summary is now one table short. :839 still reads "Removes the hours below FloorHour from all three tables in ONE transaction and returns how many hours went. Step one deletes the hours and the validity rows (small tables) and returns the hours; step two removes each returned hour's rollup rows by the index."
With this block there are four, and the new delete is neither step one nor step two as the summary describes them — it runs on the floor directly, not over the expired list, which is right (an hour can hold a failure record without ever having reached the hours table), but it is not what the prose says. The behaviour itself is correct and unconditional: GcAsync never early-returns on an empty expired, so the sweep happens even on a tick that expired nothing.
What I checked and found cleanRecording these so the verdict's findings are not mistaken for the whole read. Each of these is a place the mechanism could plausibly have been wrong and is not.
One consequence the PR body does not state, which I do not think is a defect: an hour in backoff now runs last, and The read-failure direction of the self-alert is the safe one. Both alert traps near this diff come out clean. The re-fire trap (an alert re-firing on every cooldown expiry against one unchanged observation) does not reach it: Parity. Line endings. The swallowed-read census arithmetic adds up. Evaluator exempt 19 → 20 (the new wrapper catch), |
There was a problem hiding this comment.
Verdict: CHANGES REQUESTED
Mechanism sound (see top-level note). Three defects, each inline: the V187 renumber left a public const on 186; the extended timeout reaches 1 of the build's 10 commands; get_store_metrics's description counts one fewer bounded list than the tool emits.
Claims
- VERIFIED — V187 registered,
SchemaVersion187 —PgMigrations.cs:1631,StorageVersion.cs:20; no ladder gap. - VERIFIED — probe keeps 161, adds 162; V187 arm above V186 —
ViewerDataService.cs:1249,:1486. - VERIFIED — N = 3; extended 240 s (4 x 60) —
QueryStoreComposeStamp.cs:105,:119. - VERIFIED —
next_attempt_at = last_failed_at + 1 day, plan skips until due —:608,:580-581. - VERIFIED — a timeout under 240 s backs off at once — second disjunct
:608. - VERIFIED — a backed-off timeout hour's daily attempt also gets 240 s —
:575independent of backoff,:1102. - VERIFIED — success clears the row in the build's transaction —
:975. - VERIFIED — cleanup removes rows below the floor —
:868, unconditional onexpired. - VERIFIED — same hours, stable sort, failed hours last —
:713;ChooseBuilds_RunsTheHoursThatFailedBefore_AfterTheOthers_AndChoosesTheSameHours. - VERIFIED —
query_store_composeon every response withstate/failing_hours/hours_in_backoff/boundedhours[]—DarlingMcpStoreMetricsTools.cs:380-411. - VERIFIED — Raw Purge idiom; AlertFamily + triage pairs —
DarlingSelfAlertEvaluator.cs:7205mirrors:7023;AlertFamily.cs:159;DarlingTriageEndpoint.cs:146. - VERIFIED — no Lite twin —
grep -rn get_store_metrics --include=*.cs Lite/ Lite.Tests/empty. - VERIFIED — read extracted into
s_workerAlertMembers; 20 / 15 / 41 —AlertReadFailureSurfaceTests.cs:967,:929,:984,:1284;s_exemptions+2. - VERIFIED —
DropV187SentinelAsyncin 10 rewinds;MigrateAsync16 → 17 at all eight sites —RungRewindArtifacts.cs:181. - UNVERIFIED — the
EXPLAIN (ANALYZE, BUFFERS)table (2,347 vs 107 ms, 21.9x, 16 MB spill) — rig only. - UNVERIFIED — "2.6 s a normal hour / 9 M rows in 60 s / 240 s covers ~90x" — field arithmetic the tree does not carry.
- UNVERIFIED — "3 live tests, passing" — all
Assert.SkipWhen(string.IsNullOrEmpty(BaseConnectionString), …); they skip withoutDARLING_TEST_PG. - UNVERIFIED — gate figures (4181/0/0, 1134/0/0) and the 1843/1, 494/0 runs — need rig + build; the body says the 289+29 batch has no verdict.
- UNVERIFIED — store A catalog (99 GB legacy partition, 41.1 M rows, correlation -0.30 vs 0.998) — live read. Code half checks out: V171 attached without a copy; the
first_execution_timefloor has no upper bound. - REFUTED — "the migration renumbered to V187 … fixed", as a complete renumber —
QueryStoreComposeStamp.cs:96still readsFailuresRungVersion = 186, and 186 is #5829'scollection-log-hourlyrung, which creates no failures table. Two more V186 labels survive, one in the shipped SQL (:318,:324), plusQueryStoreComposeStampLiveTests.cs:410. - REFUTED — "with the client command timeout at 270 s" —
:902computes 270 and uses it only at:946; the other nine commands (:905,:910,:916,:929,:940,:953,:959,:968,:975) keep 90.SET LOCAL statement_timeoutis per transaction, so the server grants all ten 240 s while the client waits 90.
Riskiest lines
Darling/PerformanceMonitor.Darling.Storage/QueryStoreComposeStamp.cs:580-581— this filter is the backoff: wrong one way a stuck hour never retries, the other way the 240 s build runs every tick (the bug being fixed). Pinned byABuildThatFailsForAnotherReason_IsRetriedEachTickThreeTimes_ThenOnceADay_IsReadable_AndASuccessClearsIt— live-only, so CI covers it not at all.…:608— decides "next tick" vs "a day" off two disjuncts and a NULL-capable comparison, and is the sole producer ofbacked_off(read by the WARN, the tick counter and the self-alert). Pinned by the two live backoff tests — live-only.…:902with:946— the extended timeout's client half, on 1 command of 10. UNPINNED: no test makes 270 and 90 diverge.
Traps near this diff
- "Two copies of one definition pinned EQUAL … Alias, do not copy" (#3684) — applies —
'57014'literal at:575,:599,:608besideStatementTimeoutSqlState:122, unpinned, while the sameCASEparameterises the other three knobs. Inline, non-blocking. - "A roster-based census does not see the file it does not roster" (#3699) — applies —
McpPageContractTests:945rosters eight PG tools, notget_store_metrics; the new page is watched only by a source-text count. - "Ruling (#5833) … never answer a trap with a test that reads source text" — applies — extends probe-ordinal,
BoundPage-count, reflection and plan-text pins. Mitigated, but it is why defect 3 went unnoticed. - "Truncation inferred from a full page … the flag is
fetched.Count > limit" — does not apply —ReadFailuresSqlhas noLIMIT;McpHelpers.cs:662compares the whole population. - "A count taken off the page and named as the population's" (#3679) — does not apply — counts come off the unbounded read (
:383-384); the page's ishours_returned. - "
limit/top/hours_backrefused, never clamped" (#3699) — does not apply —ValidateTop(limit)at:99refuses before any read. - "An alert … re-fires on every cooldown expiry against the same rows" (#3628) — does not apply —
DecideStateAlert(:8949) "never repeats per cooldown"; its only caller is the hourly tick (DarlingWorker.cs:12820). - "Presence-shaped conditions sit behind
AlertPersistenceGateat K consecutive collections" (#3692) — does not apply —InBackoffis set only afterFailuresBeforeBackoffconsecutive failures. - "An empty analysis window is 'unavailable', not an all-clear" (#3553) — does not apply —
DarlingWorker.cs:12848returns on a failed read rather than passing[]into the resolve branch. - "
… ELSE 0 ENDspells 'unknowable' as 0" (#3707) — does not apply —ELSE interval '0'is a retry interval meaning "due now"; a NULL SQLSTATE takes the same ELSE. - "A percent whose denominator is the PAGE" (#3613) — does not apply — no share or percent in the new payload.
- "Lite and Darling ship in parity …" (#3594) — does not apply — no counterpart surface in Lite; shared
AlertFamily.cs:159present. - "
.gitattributessaystext=auto eol=crlf" — does not apply —file(1)reports CRLF on all four changed source files; every hunk is line-scoped. - "A test that reads the clock twice measures the CI scheduler" (#3676) — does not apply — the live tests move the store clock by
UPDATE … - interval '1 day'.
Divergence (blind read vs PR body)
1. The renumber is reported finished and is not. 16 test files plus StorageVersion, PgMigrations and ViewerDataService moved; FailuresRungVersion, the one place in the storage layer that names the rung, did not — and the body's own "Not done" keeps the renumber live, so the next pass walks the same sites and finds this one still unlisted.
2. The 270 s client timeout is presented as a property of the attempt; it is a property of one statement. The store-A prediction rests on it ("it runs last … under 240 s, and builds (about 80 s cold). The backlog then clears at 4 to 5 hours per tick"). On the churned legacy partition the body itself characterises, SourceRowsSql's count over those rows is the plausible second slow statement, capped at 90 s client-side — after which the hour records a 57014 at timeoutSeconds = 240 and backs off to once a day on an attempt that never had its 240 s.
3. The diff adds a fourth bounded list and moves the pin that counts them, not the prose. "BoundPage count 3 -> 4" is listed under "Pins moved because their rule still holds"; StoreMetricsSummaryFirstTests.cs:311, asserting the description still says "three ranked lists, each bounded by limit", was not. Both pass while disagreeing, and the description names for an agent which three lists limit bounds, omitting the one this PR added.
Smaller, neither a finding: "re-fires on the state cooldown" vs DecideStateAlert's own "It never repeats per cooldown" (inherited Raw Purge wording); and "one pooled checkout an hour" undercounts — get_store_metrics gained a fourth atop the "third pooled checkout" its comment at :161-165 names.
Reviewer checklist
- Run the three new live tests with
DARLING_TEST_PGset — they skip silently without it and are the only cover for the plan filter and both backoff disjuncts. - Build:
FailuresRungVersionis unread, so a wrong value compiles; confirm the renumber missed nothing that is read. - On store A, watch the 2026-10-07 15:00 hour's first extended attempt and see which statement the 240 s covered — whether
SourceRowsSqlorDeleteHourSqlis cut at 90 s client-side first. - Call
get_store_metricswith more failing hours thanlimit: confirmtruncatedflips at the boundary andhours_in_backoffcounts the population. - Let
Compose Rollup Hours Stuckfire and resolve live; check the history row's colour is the WARNING tier it fired at (#3635). - Finish the pre-push gate's 289-Darling/29-Lite class batch, stopped at the 60-minute wall with no verdict.
… finish the V187 renumber, one client timeout for the whole attempt (#5867)
There was a problem hiding this comment.
Verdict: LGTM
Claims
- VERIFIED —
next_attempt_at→retry_atrename is complete across the DDL,PlanSql,RecordFailureSql,ReadFailuresSql, theget_store_metricspayload field and the live test, while the C# record propertyNextAttemptAtis unchanged — confirmed by readingQueryStoreComposeStamp.csand greppingnext_attempt_atrepo-wide: the only remaining hits areExternalAlertStore's unrelatedtimestamptzcolumn. - VERIFIED —
FailuresRungVersionis now 187 and every V186 label tied to the compose-failures table was updated —grep -n "V186"inQueryStoreComposeStamp.csand the compose-stamp test files returns zero hits; the two remainingV186mentions inQueryStoreComposeStampTests.cscorrectly refer to #5810's unrelatedcollection-log-hourlyrung, matchingPgMigrations.cs:1617-1618. - VERIFIED —
BuildHourAsync's ten commands now share one clientCommandTimeoutvia the new localNewCommand, with acommandCreatedtest seam — confirmed by readingQueryStoreComposeStamp.cs:894-990, and the newEveryCommandOfABuildAttempt_CarriesTheAttemptsClientTimeout_ExtendedOrNotlive test exercises exactly this (QueryStoreComposeStampFailureLiveTests.cs:224-260). - VERIFIED — the
'57014'literals inPlanSql($4) andRecordFailureSql($9) are now bound fromStatementTimeoutSqlStateby their two callers, andget_store_metrics's description/test now say "four ranked lists" namingquery_store_compose.hours— confirmed in the diff andStoreMetricsSummaryFirstTests.cs. - UNVERIFIED — "Proven on the old shape...
Assert.Single() Failure: The collection contained 2 items; it passes on the fix" — a live-rig test-run result, not reproducible from a read-only tree. - UNVERIFIED — "Gate (
bash .github/scripts/pre-push.sh): GATE GREEN" and the full by-hand class-run tallies — live test execution output, not checkable statically.
Riskiest lines
Darling/PerformanceMonitor.Darling.Storage/QueryStoreComposeStamp.cs:909-914— theNewCommandlocal function that now unifies every command's client timeout to the attempt's (270s/90s) — pinned byEveryCommandOfABuildAttempt_CarriesTheAttemptsClientTimeout_ExtendedOrNot.Darling/PerformanceMonitor.Darling.Storage/QueryStoreComposeStamp.cs:575,737—PlanSql's$4::textparameterization of the SQLSTATE literal, with the C# call adding the 4th parameter in order — pinned by the existingQueryStoreComposeStampFailureLiveTestsbackoff/extended-timeout tests, which exercisePlanAsyncend to end.Darling/Darling.Tests/QueryStoreComposeStampTests.cs:35-42— new pin assertingFailuresRungVersionmatches the actual migration whose SQL isFailuresCreateSql— pinned by itself (TheFailuresRungVersion_IsTheVersionOfTheMigrationThatCreatesTheFailureTable), checked againstPgMigrations.Scripts(runtime data), not source text.
Traps near this diff
- "Ruling (#5833): tests are load-bearing... never answer a trap with a test that reads source text or asserts how code is spelled" — does not apply: both new tests (the rung-version pin and the command-timeout live test) assert against runtime values (
PgMigrations.Scripts,NpgsqlCommand.CommandTimeout), not source text. - "Two copies of one definition pinned EQUAL to each other fail only after BOTH have drifted (#3684)" — does not apply: the new rung-version pin compares
FailuresRungVersionagainst the single source of truth (PgMigrations.Scripts), not a second hand-maintained copy. - "Lite and Darling ship in parity... a fix to one SKU's reader, tool, alert or description without the counterpart's is a finding" — does not apply:
QueryStoreComposeStamp.cs:57documents "No Lite twin: Lite has no PostgreSQL store," and no Lite MCP tool exposesget_store_metrics.
Divergence (blind read vs PR body)
The body says "the three V186 labels (two in the DDL comment, one in QueryStoreComposeStampLiveTests) say V187," but the diff actually changes four textual V186 occurrences in QueryStoreComposeStamp.cs alone (the FailuresRungVersion doc comment, the FailuresCreateSql XML doc, and the inline SQL comment inside the DDL literal) plus the one in the test file. Cosmetic undercount in the narrative only — the renumber itself is complete and correctly verified by grep.
Reviewer checklist
- Run the gate (
bash .github/scripts/pre-push.sh) and the newEveryCommandOfABuildAttempt_CarriesTheAttemptsClientTimeout_ExtendedOrNot/TheFailuresRungVersion_IsTheVersionOfTheMigrationThatCreatesTheFailureTabletests against a live Postgres+TimescaleDB rig to confirm the claimedGATE GREENand the reverted-shape failure repro.
Claude posting for Erik Darling. Round-1 findings were answered at 6c38cab, where the bot's round 2 is LGTM; own run 38790331695 is green.
…llup-retry-backoff
… alert resolution rung test; fix the xUnit2000 argument order
…ber this PR's rung to V190
Claude posting for Erik Darling.
Fixes #5867.
Status: the successor lane S1 finished the checkpoint: dev merged, the migration renumbered to V187, the rung-test fallout and the census fixed, and the gate run. See "S1" below. The "Not done" list further down is the first lane's and is resolved in S1.
Why
When an hour's build threw,
RunTickAsynclogged a WARN and planned the same hour again on the next tick. It ran the same build under the same 60 sstatement_timeoutand kept nothing that an operator could read. On the 42-server store, the 8-day-old hour 2026-10-07 15:00 failed every tick with57014.Note: the
57014in the field line comes from the build's ownSET LOCAL statement_timeout = '60s'(BuildStatementTimeoutSeconds), not from the store's setting.What changes
1. Why the build cannot finish (rig, EXPLAIN ANALYZE)
Rig: 204 hours of wide rows. A normal hour has 12 stamps x 4 servers x 210 rows = 10,080 rows, which is the field's 400 K-row hour scaled by 1/40. One planted hour, 2026-10-07 15:00, has 20 times that: 201,600 rows. The rig has the #4605 BRIN index on
collection_time, as a field store has. I ranEXPLAIN (ANALYZE, BUFFERS)on the build statement (custom plan):The plan is right, and the build is simply big. Time grows linearly with rows: 20x the rows took 21.9x the time. Age costs nothing while the BRIN index exists. The sort spills, and an in-memory sort (
work_mem64 MB) saves 23% (2,099 ms to 1,600 ms). At field scale, though, the sort needs about 187 bytes a row, so 1.5 GB for an 8 M-row hour. No boundedwork_memavoids the spill, so the plan is unchanged.Field arithmetic: a normal hour builds in 2.6 s (400 K rows at 6.5 us a row), so 60 s holds about 9 M rows, roughly 23 normal hours. Check the BRIN on the field store. With the BRIN index dropped, the build of an old hour becomes a Seq Scan that reads every row from the hour up to now. On the rig that was 2.2 M rows read, against 290 K for a recent hour. The cause is the build's
first_execution_time >= H - 26 hfloor, which has no upper bound. On a store withoutix_query_store_interval_wide_collection_time_brin(or with its ranges unsummarized), an 8-day-old hour reads 9 days of rows. That fits "8 days old, times out, newer hours build". Adding an upper bound would change which rows the rollup holds, against the compiler's wide read, so it is a design call and not in this PR.2. Retry policy (V187 after S1's merge; the number is assigned at merge)
collect.query_store_compose_stamp_failures: one row per hour, holdingfailures,last_sqlstate,last_reason,last_timeout_seconds,first_failed_at,last_failed_atandretry_at(store clock). It is written after the failed build rolls back. The build that commits deletes it in its own transaction, and the cleanup removes rows below the floor.FailuresBeforeBackoff). What a retry fixes (a deadlock, a lock or serialization failure, a dropped connection) clears within a tick or two. At an hourly tick, three failures in a row are three hours of the same error.57014, the next attempt runs under 240 s (ExtendedBuildStatementTimeoutSeconds, 4 x 60 s), with the client command timeout at 270 s. 240 s covers an hour of up to about 90 times the normal size and stays well under the 10-minuteMaxTickDuration. If the build also times out under 240 s, it backs off at once, because retrying next tick would run the same build under the same timeout. In backoff, a timeout hour's daily attempt also gets 240 s.retry_at = last_failed_at + 1 day, and the plan leaves out an hour until it is due. The WARN then comes once a day and names the count, the next attempt and the reason. A success resets the count by deleting the row.3. Visibility
get_store_metricsgets a newquery_store_composeblock on every response:state(Observed or Unreadable),failing_hours,hours_in_backoff, and a boundedhours[]list. Each entry has the hour, failures, in_backoff, last_sqlstate, last_reason, last_timeout_seconds, first_failed_at, last_failed_at and retry_at.4. Tick budget
ChooseBuildsstill chooses the same hours, then sorts them with a stable sort so hours with a prior failure run last. A build that may run to 240 s cannot spend the tick before the other hours get their turn.Test plan
Rig: PostgreSQL with TimescaleDB, UTC, own port;
DARLING_TEST_PGset. The rig is stopped.QueryStoreComposeStampFailureLiveTests(3 live tests, passing):query_canceled(57014) failure is retried under 240 s, where the planted check passes. The hour builds and its record is cleared.ChooseBuilds_RunsTheHoursThatFailedBefore_AfterTheOthers_AndChoosesTheSameHours(unit).ComposeHoursStuck_FiresForAnHourInBackoff_NotForOneStillRetried_AndResolvesWhenNoneIsLeft(self-alert, the existing harness).*QueryStoreComposeStamp*,*ComposeQueryStoreStamp*,*DarlingSelfAlertTests*,*SelfAlertFailedSendCensus*,*NotificationRoutingTests*,*AlertReadFailureSurface*,*StateSelfAlert*,*ServiceVersionRung*,*LegacyPinCandidateRung*,*ViewerSchemaVersionGate*,*StoreMetrics*and*McpPayloadContractCensus*:Total: 745, Failed: 8. After the fixes below, a rerun of the failed methods plus the new tests gaveTotal: 17, Failed: 2. The commit then fixed one of those two (see "Not done").bash .github/scripts/pre-push.sh): not run.Pins moved because their rule still holds:
clockCTE);BoundPagecount 3 -> 4;StatementTimeoutSqlread through reflection as a method.Not done (handoff)
hasComposeStampFailures). Every rung test that asserts the probe's last ordinal orparameters.Lengthfails until it moves one up. Seen failing:ServiceVersionRungTests,QueryStoreWatermarksRungTests,QueryStoreComposeStampTests.TheProbe_HasThisRungsSentinelAndMapsItsArmToV173andLegacyPinCandidateRungTests.git grep -l 'reader.GetBoolean({ProbeOrdinal' -- Darling/Darling.Testslists about 55 files, as in Plan regression reads stop re-reading three open days of Query Store intervals, and on-demand calls reuse the candidates for one analysis cadence (#5812) #5817's V185 bump. Also needed:RungRewindArtifacts.DropV186SentinelAsync(drop the failures table) and its callers in the rewinding rung tests, plusViewerSchemaVersionGateTests. The four other V186 branches (get_collection_health computes its p95 without a serial per-collector sort (#5810) #5829, Generic webhook: {{investigation_json}} carries the alert's investigation request (#5821) #5853, Darling: an opt-in setting to send alert resolutions to Slack, Teams, email and webhooks #5825, MCP long-poll: an agent waits for an investigation request to open for its routes (#5822) #5856) need the same renumbering at merge.AlertReadFailureSurfaceTests.EverySwallowedAlertingRead_IsCountedOrExplicitlyExemptfails withExpected: 19, Actual: 20. Another count in that class, probably the exemption or catch census, needs moving (or one of the two new exemptions dropped). Not investigated.TheBuildOrder_IsStaleHoursFirst...reflection fix is in the commit but was not rerun.To double-check: the Warning text "is retried next tick under a 240 s statement timeout"; and that the worker's new read after each tick (one pooled checkout an hour) is acceptable.
Commit: ebe0846.
S1 (successor lane: merge, V187, rung fallout, census, BRIN finding)
Merge.
9cb97ba20and791044d14mergeorigin/dev(a merge, not a rebase). Two files conflicted:PgMigrations.cs: get_collection_health computes its p95 without a serial per-collector sort (#5810) #5829'scollection-log-hourlystays V186. This branch'squery-store-compose-failuresis now V187 (V187Sql), andStorageVersion.SchemaVersionis 187. Generic webhook: {{investigation_json}} carries the alert's investigation request (#5821) #5853 and Alert resolutions go to the channels that got the fire, opt-in per channel (#5825) #5855 also carry V187 on their branches. The ladder allows no gaps, so each PR takes the next free number when it merges, and whichever lands later gets renumbered.ViewerDataService.cs: the probe keeps get_collection_health computes its p95 without a serial per-collector sort (#5810) #5829'scollection_log_hourlysentinel at ordinal 161 and adds this branch'squery_store_compose_stamp_failuresat 162 (GetBoolean(162)).MapProbedSchemaVersiontakes both parameters (hasCollectionLogHourly, thenhasComposeStampFailures). The V187 arm returns 187 above the V186 arm.Rung-test fallout (
b3ac77a50,31e42344e). Moved the way #5829 moved its files: the probe's last ordinal +1,parameters[^n]andatThisRung/behindshifted by one, the cascade clones also clear V187,Scripts[^n]+1, and the version lists end in 187. Changed files: AwsPerServerRole, ExternalAlert, Investigation, LegacyPinCandidate, PlanRegressionDaily, PlanRegressionRowcount, QueryStoreComposeStamp, QueryStoreWatermarks, ReadCaller, ReadLatencyCapacity, RunnableQueueSettings, ServiceVersion and QueryStoreIntervalPartition (MigrateAsyncapplies 17 rungs, not 16).RungRewindArtifacts.DropV187SentinelAsyncdrops the new table, and every rewind that callsDropV186SentinelAsyncnow calls it first (10 files). InCollectionLogHourlyLiveTests, the after-full-migrate checks readStorageVersion.SchemaVersioninstead of 186. Each of these pins still checks that the probe ends at the ladder's top, so each one moved; none was deleted.AlertReadFailureSurfaceTests(19 vs 20) (e5fef9a6f,5dc7ca302). This test's rule is "every catch block in the alerting scope is either counted or exempt with a stated reason", not a spelling census. The 20 is real:DarlingSelfAlertEvaluator.csgained one exempt wrapper catch (Compose-rollup-hours-stuck). The first lane also left the worker's failure-record read inline inBuildQueryStoreComposeStampAsync, which the census does not scan, so its exemption entry matched nothing. The fix registers the read the way the others are registered:DarlingWorker.EvaluateComposeHoursStuckAsync, listed ins_workerAlertMembers;WorkerExemptSitesis 15, and the total exempt count is 41.The read stays exempt, not counted. A failed read sends no report, so the standing alert is held. I tried counting it as #5654's read is counted. That adds a 15th fleet-scoped read, and the inventory test then requires a new entry in
AlertReadFailureCounter.FleetScopedReads, whose text goes into theget_collection_healthMCP description of both Darling and Lite. This brief excludes Lite changes, so the read stays exempt. The log line is now a Warning ("...the standing alert is held this tick").The first lane's unrun fix.
QueryStoreComposeStampTests(includingTheBuildOrder_IsStaleHoursFirst...) passes in the runs below.Item 5: the BRIN on the legacy partition (store A).
57014the next attempt runs underExtendedBuildStatementTimeoutSeconds= 4 x 60 = 240 s, with a 270 s client timeout. A cold read of about 80 s fits.ChooseBuildsreturnschosen.OrderBy(b => b.Failures > 0), a stable sort, so hours that failed before run last and the warm builds go first. The tick starts a build only while it has used less thanMaxTickDuration(10 min). The last 240 s build can therefore run to about 14 minutes, which is inside the hourly cadence. I made no change.collection_timecorrelation is -0.30 on the legacy partition and 0.998 on daily partition p20261014 (0 deletes). The code fits that reading:first_execution_time" (DarlingRetention.cs). New rows filled the freed space all over the heap.query_store_interval_wide_legacyand attached it, with no copy.collection_timerange still matches about 1.95 M blocks (about 15 GB, about 15% of the partition), while on p20261014 the same predicate costs a few thousand blocks.collection_time.collection_timein place. On conflict it runsDO UPDATE SET collection_time = EXCLUDED.collection_time, ...when the newer(collection_time, execution_count)is greater (QueryStoreIntervalWide.cs). With fillfactor 50 that is a HOT update in the same page, so it widens ranges on the daily partitions too. Each row is refreshed only while its runtime-stats interval is open, though, which movescollection_timeby about one interval. The daily partition's 0.998 correlation shows this does not matter in practice. No code change for it here.first_execution_timebtree, and it needs an upper bound onfirst_execution_time. The build cannot add one without proving it drops no row (the rollup must hold what the unbounded wide read holds). On a churned heap, that window's rows are also spread across the heap. So I made no statement change and have no EXPLAIN pair to show.Results (rig: PostgreSQL + TimescaleDB, UTC, port 55871,
DARLING_TEST_PGset; stopped at the end):*Rung*,*SchemaProbe*,*StorageVersion*,*SchemaVersion*,*SelfAlert*,*StoreMetrics*and*ComposeStamp*class (includingQueryStoreComposeStampFailureLiveTestsandQueryStoreComposeStampLiveTests), plus all 61 other classes that nameMapProbedSchemaVersion,StoreSchemaProbeSql,QueryStoreComposeStamporSchemaVersion:Total: 1843, Failed: 1. The one failure wasOversizedPlanBacklogPins.V121.... My scripted edit had left LF line endings in the working copy ofPgMigrations.cs(the committed blobs are normalized either way); after restoring CRLF it passed.QueryStoreIntervalPartitionRungTests,AlertReadFailureSurfaceTests,OversizedPlanBacklogPins,QueryStoreComposeStampFailureLiveTests):Total: 80, Failed: 0.AlertReadFailureSurfaceTests,QueryStoreComposeStampFailureLiveTestsand*SelfAlert*:Total: 494, Failed: 0.bash .github/scripts/pre-push.sh, with Pre-push gate: run selected classes by full name, RED on zero tests, STOP on a whole-suite selection (#5868) #5870's full-name fix merged): GuardDarling.Tests Total: 4181, Errors: 0, Failed: 0andLite.Tests Total: 1134, Errors: 0, Failed: 0.classes: darling 289, lite 29. Its class batch (289 Darling classes, 29 Lite) was still running at 17:55Z, the 60-minute wall. I stopped the rig then, so that batch has no verdict here, and CI decides it. The hand runs above cover the brief's class list.Not done / for the coordinator.
FleetScopedReadstext change that reaches Lite's MCP description. That needs its own small change.Round 1 answers
Merge:
origin/devmerged first (a5ed963, no conflicts), then the work below in 6c38cab. Rig: PostgreSQL + TimescaleDB, UTC, port 5871,DARLING_TEST_PGset, stopped at the end.CI failure (
StoreSqlClockDisciplineTests.NoStoreSqlComparesANaiveTimestampToABareClock). V187 added a naive column namednext_attempt_at, so the name entered the naive-timestamp vocabulary and the scan flaggedExternalAlertStore.ClaimSql's correctp.next_attempt_at <= now()(atimestamptzcolumn). Renamed this PR's column (V187 is unreleased) toretry_at: the DDL, the plan filter, the record and read SQL, theget_store_metricspayload field (it spelled the column name, sohours[].next_attempt_atis nowhours[].retry_at; no other payload field changed), the note text and the live test. The C# record propertyNextAttemptAtis unchanged. No waiver was added.StoreSqlClockDisciplineTests:Total: 3, Errors: 0, Failed: 0.(a) V187 renumber.
FailuresRungVersionis now 187, and the three V186 labels (two in the DDL comment, one inQueryStoreComposeStampLiveTests) say V187.TheFailuresRungVersion_IsTheVersionOfTheMigrationThatCreatesTheFailureTable(inQueryStoreComposeStampTests) finds the migration whose SQL is the failure-table DDL and asserts its version equals the constant. It compares values and does not read source text.(b) Client timeout.
BuildHourAsyncnow makes every command through one localNewCommand, which applies the attempt's client timeout (270 s extended, 90 s normal) to all ten commands, including theSET LOCAL statement_timeoutone. New optional parametercommandCreatedlets a test see each command.EveryCommandOfABuildAttempt_CarriesTheAttemptsClientTimeout_ExtendedOrNot(live) builds one hour normally and one under the extended timeout and asserts each attempt's commands carry a single timeout, the two differ, and the extended one is at least 240 s. Proven on the old shape: with the commands reverted to 90 s except the insert it fails (Assert.Single() Failure: The collection contained 2 items); it passes on the fix.(c)
get_store_metricsdescription. It now says four ranked lists and names the fourth,query_store_compose.hours(hours whose build failed, newest first); the short description says 4 and the type's summary says four.StoreMetricsSummaryFirstTestsmatches "four ranked lists".(d) The
'57014'literals inPlanSql($4::text) andRecordFailureSql($9::text) are now bound fromStatementTimeoutSqlStateby their two callers. The comment inGetStoreMetricsnow says the retention-hold read is the third pooled checkout and the compose read is the fourth.Build:
dotnet build Darling/Darling.Tests/Darling.Tests.csproj -c Debug: Build succeeded (storage, service and viewer build as dependencies).Gate (
bash .github/scripts/pre-push.sh):GATE GREEN.[guard-darling] Darling.Tests Total: 4181, Errors: 0, Failed: 0, Skipped: 0[guard-lite] Lite.Tests Total: 1134, Errors: 0, Failed: 0, Skipped: 0classes: darling 261, lite 24 (selected names: darling 276, lite 24; symbols: 251 candidates ...);[classes-darling-1] Total: 4698, Failed: 0, Skipped: 454,[classes-lite-1] Total: 606, Failed: 0.By hand, full class names, with the rig (all
Failed: 0, none skipped):StoreSqlClockDisciplineTests3;QueryStoreComposeStampLiveTests7;QueryStoreComposeStampTests21 (includes the rung test);QueryStoreComposeStampFailureLiveTests4 (the three failure-path tests plus the new timeout test, all RUN, Skipped: 0);StoreMetricsSummaryFirstTests10;McpPageContractTests45;AlertReadFailureSurfaceTests27; and every rung or rewind class naming V187:AwsPerServerRoleRungTests9,CaggGroupIndexDropLiveTests5,CollectionLogHourlyLiveTests6,ExternalAlertRungTests4,InvestigationRequestStoreLiveTests12,InvestigationRungTests4,LegacyPinCandidateRungTests5,NotificationRouteScopeRungTests7,PlanRegressionDailyRungTests18,PlanRegressionRowcountRungTests6,QueryStoreIntervalPartitionRungTests11,QueryStoreWatermarksRungTests4,ReadCallerRungTests5,ReadLatencyCapacityRungTests7,RunnableQueueSettingsRungTests4,ServiceVersionRungTests4. The runner prints no per-test[PASS]lines here, so the evidence for the live tests isSkipped: 0in a run withDARLING_TEST_PGset.Not done. Nothing from the brief. The earlier S1 "Not done" items above still stand.
Renumbered to V189
#5855 landed V187 (alert-resolution-delivery) and #5853 landed V188 (investigation-alert-facts) on dev first, so this PR's migration
query-store-compose-failuresmoved from V187 to V189. Everything above that says V187 for this PR's rung now reads V189. Merge head3cd0200cb(dev merged twice; the second merge brought only README and docs changes).PgMigrations.cs(Migration(189, ...),V189Sql, doc comment),StorageVersion.SchemaVersion = 189,QueryStoreComposeStamp.FailuresRungVersion = 189(and the V189 label in the DDL comment).ViewerDataService.cs: dev's V187 and V188 probe sentinels kept at ordinals 162 and 163; this PR's compose sentinel is now ordinal 164 (hasComposeStampFailures, last parameter) and its arm returns 189 above dev's 188 and 187 arms.RungRewindArtifacts:DropV189SentinelAsync(this PR's); dev's V187 and V188 helpers are untouched. Every live rewind drops V189 first, then dev's V188 and V187 (new:AlertResolutionSettingsRungTestsalso needed it; it was failing on the first run with expected 186, actual 189).^noffsets with dense-range and by-name checks, dev's version was taken as is, and this PR's own count, offset and trailingDoesNotContainassertions were dropped (they only spelled the ladder's length; the by-name checks in the same tests cover the rule). Where dev's tests set sentinels absent by name,hasComposeStampFailureswas added to that list. Comment ladders list V189 (Query Store compose rollup retries a timed-out hour verbatim every tick and never builds it #5867), V188 (Generic webhook {{investigation_json}} token carries the investigation request to a POST runner #5821), V187 (Darling: an opt-in setting to send alert resolutions to Slack, Teams, email and webhooks #5825) in order.TheFailuresRungVersion_IsTheVersionOfTheMigrationThatCreatesTheFailureTable(argument order), soDarling.Testsbuilds with 0 warnings.V187/187in the diff against dev is dev's own rung from Alert resolutions go to the channels that got the fire, opt-in per channel (#5825) #5855 (V187Sql, its sentinel, its drop helper, its comments).Verification (rig on port 55871, stopped at the end):
0 Warning(s).GATE GREEN. Guard:[guard-darling] Total: 4181, Errors: 0, Failed: 0, Skipped: 0and[guard-lite] Total: 1144, Errors: 0, Failed: 0, Skipped: 0.classes: darling 262, lite 24; then[classes-darling-1] Total: 4711, Failed: 0, Skipped: 30and[classes-lite-1] Total: 606, Failed: 0.*Rung*classTotal: 452, Failed: 0(after the one fix above);*QueryStoreComposeStamp*(unit, live, failure-live),StoreMetricsSummaryFirstTests,InvestigationRequestStoreLiveTests,CaggGroupIndexDropLiveTests,CollectionLogHourlyLiveTests,PgClusterObjectCensusTests,McpPayloadContractCensusTests, every*Census*and*Ratchet*class together:Total: 588, Failed: 0, Skipped: 0.SECTION: Fixed
ENTRY: - The Query Store compose rollup stops retrying a failing hour every tick ([#5871]) - A build that fails is now retried next tick (under a 240 s timeout after a statement timeout), then once a day after 3 failures in a row. get_store_metrics lists such hours, and a Compose Rollup Hours Stuck self-alert fires while any hour waits a day between attempts.