Skip to content

Give every fact-collector read an explicit command deadline (Fixes #2810) - #2869

Merged
erikdarlingdata merged 1 commit into
devfrom
fix/2810-plan-regression-timeout
Sep 4, 2026
Merged

erikdarlingdata merged 1 commit into
devfrom
fix/2810-plan-regression-timeout

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

Fixes #2810.

The diagnosis, which is not what the issue expected

The issue concluded "raising the timeout is NOT the fix", and at the time it was right: the query could not finish in 300 s because query_store_stats held 19 days at a 4-day policy. It also said what to do about that — "fix retention first, then re-measure this query before deciding whether it needs any change at all."

Retention was fixed (#2809, ~87 GB reclaimed, 19 chunks down to 5). I re-measured. The answer changed.

Measured on the production store, now

Running the shipped query string (extracted from source, not retyped) against the six busiest servers, two passes:

rows in window pass 1 (cold) pass 2 (warm)
4,561,927 34,721 ms 21,245 ms
4,252,879 28,181 ms 13,706 ms
3,614,035 32,404 ms 10,589 ms
3,563,352 14,406 ms 10,568 ms
3,370,902 10,985 ms 10,790 ms
3,369,166 10,612 ms 10,591 ms

Two servers cross 30 s cold; a third sits at 28.2 s, inside the noise. Every one of them is comfortably under it warm.

That is the entire defect. PgFactCollector sets no CommandTimeout on any of its 31 commands, so all of them inherit Npgsql's undocumented 30 s default. The plan-regression read needs ~35 s cold on the largest servers and ~11-21 s warm, so it fails on the cold/large combination only — which is why it presents as intermittent, and why a hand-run measurement makes it look fine (the second run is warm).

It also explains why two changes that looked like they should have fixed it did not. #2827 made the query 2.4x faster and #2826 made the failure visible; neither touched the ceiling it was failing against. The comment #2827 left behind even records 38.9-40.9s end-to-end at the time — above 30 s then too.

The value, and why the upper bound is the one that matters

60 s. Bounded on both sides, and the second bound is easy to miss:

  • Below — it must clear the 34.7 s measured cold worst case, or the defect reproduces.
  • Above — DarlingWorker.s_analysisTimeout gives the whole analysis pass 120 s, and thirty collect methods share it. A per-command deadline at or near that figure would let one stalled read consume the entire pass and cost the server its other twenty-nine facts. That converts "one fact is missing" into "every fact is missing" — strictly worse than the failure being fixed.

60 s clears the measured worst case by 1.7x and still leaves half the pass for everything else. When a store eventually outgrows it, the read starts warning (#2826) rather than failing silently, which is the signal to look at the scanned window rather than at the ceiling.

Applied to all 31 sites, not just the one that broke

They share one pass budget and had one missing value. Fixing the reported site and leaving thirty identical ones is the enumerated-list mistake this repo has already paid for twice (#2344, PgStatementText, where a broken sibling arm survived a green suite because the test named the arm it was written for). A generous ceiling is inert on a query that returns in milliseconds, so uniformity costs nothing and removes the trap.

Pins, proven red first

Darling.Tests is net10.0-windows, so the assertions were exercised on macOS through a throwaway net10.0 harness against the real built assembly and the real sources.

  • Every command constructed in the collector sets a deadline — structural, so the next one added cannot silently reintroduce the default. Floor of 31, not an equality, so adding a collector is not taxed.
  • The value sits in the band where both bounds hold.

Three counterfactuals, each failing a different assertion — a pin that can only fail one way is not proving what it claims:

counterfactual result
revert one command site missing==0 FAIL, covered>=31 FAIL
restore the 30 s default value>35 FAIL
raise to the full 120 s pass value<=60 FAIL
restored all PASS

Scope

No query change, no schedule change, no retention change, no migration rung. Instrumentation ceiling only.

Out of scope but worth recording: PgBaselineProvider has the same missing-timeout shape, and its io_latency baseline is currently timing out on the use2 box for what is very likely the same reason. The issue counts 160 such sites across 35 files; this PR closes the 31 in PgFactCollector.

🤖 Generated with Claude Code

https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy

)

All 31 commands in PgFactCollector ran with no CommandTimeout, inheriting
Npgsql's undocumented 30s default. Nobody chose 30s.

Measured on the production store after retention was restored (#2809) and
with #2827's dedup rewrite in place, PlanRegressionSql still crosses 30s on
a COLD run - 34.7s and 32.4s on the two largest servers, against 10.6-21.2s
for the same servers warm. It fails on the cold/large combination only,
which is why it looked intermittent and why the two prior changes missed:
touched the ceiling it was failing against.

60s is bounded on both sides. Below: it must clear the 34.7s cold worst
case. Above: the whole analysis pass gets 120s (DarlingWorker.s_analysisTimeout)
and thirty collect methods share it, so a deadline near that figure would let
one stalled read consume the pass and cost the server its other twenty-nine
facts - strictly worse than the failure being fixed.

Applied to all 31 sites, not just the one that exposed it: same pass budget,
same missing value, and pinning one while leaving thirty is the enumerated-list
mistake this repo has paid for twice (#2344, PgStatementText).

Pinned structurally, proven red three ways: reverting one site, restoring the
30s default, and raising it to the full 120s pass each fail a different
assertion.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy
@erikdarlingdata
erikdarlingdata force-pushed the fix/2810-plan-regression-timeout branch from 7fdb883 to d0b295d Compare September 4, 2026 00:52
@claude

claude Bot commented Sep 4, 2026

Copy link
Copy Markdown

Reviewed. This is a clean, well-scoped fix — no blocking issues found.

Correctness

  • Independently recounted the new NpgsqlCommand( construction sites in PgFactCollector.*.cs: 4 (Activity) + 5 (Config) + 5 (QueryPerf) + 8 (Resources) + 5 (Storage) + 4 (Waits) = 31, and all 31 now carry CommandTimeout = FactCommandTimeoutSeconds. The claim in the PR body and changelog checks out exactly.
  • FactCommandTimeoutSeconds = 60 is bounded correctly against the two constraints described: > 35 (measured 34.7s cold worst case) and <= 120/2 (half the shared 120s DarlingWorker.s_analysisTimeout pass budget). The two Assert.True checks in FactCollectorCommandTimeoutTests encode exactly that band.
  • The structural pin (s_commandCtor / s_setsTimeout regex over a 3-line window) correctly excludes PgFactCollector.cs itself (single dot, doesn't match the PgFactCollector.*.cs glob) — harmless either way since that file has zero command-construction sites.
  • This brings PgFactCollector in line with the rest of the Darling storage layer, which already sets an explicit per-command CommandTimeout everywhere (PgMigrations, RollupBackfill, StoreSelfMetrics, PgTableTuning, etc.) — this was the one collector that had been missed.

Lite/Darling parity

  • No drift. Lite/Analysis/DuckDbFactCollector.*.cs has no CommandTimeout equivalent, but that's already-documented, pre-existing behavior — the XML doc on DuckDbFactCollector.ReportCollectionFailure explains DuckDB is local (no network deadline analogous to Npgsql's), so there's no counterpart seam for this PR to touch. Confirmed this isn't something the PR silently skipped.
  • Two-Store Parity in CONTRIBUTING.md is about shared interface/schema seams (IAlertStateStore-style contracts); this change is internal to one collector's implementation and doesn't touch a shared seam.

Test coverage / CI

  • Darling.Tests is net10.0-windows; confirmed .github/workflows/build.yml and nightly.yml actually build/run it on a Windows runner, so this isn't a pin that only ran once on the author's throwaway macOS harness — it'll run in CI going forward.

Scope

  • Correctly left PgBaselineProvider's same-shaped gap out of scope (called out explicitly in the PR body as a follow-up), rather than scope-creeping into a second file.
  • CHANGELOG link refs for [#2809] and [#2810] are added and resolve; [#2827], [#2826], [#2344] referenced in the new bullet already existed.

No T-SQL touched, no security-relevant input handling changed (only a client-side timeout property), no performance regression — if anything this fixes one (missing facts on every cold/large pass).

@erikdarlingdata
erikdarlingdata merged commit df03e50 into dev Sep 4, 2026
6 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/2810-plan-regression-timeout branch September 4, 2026 01:01
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant