Skip to content

DMV blocking snapshots no longer merge two separate waits of one pair (#5743) - #5766

Merged
erikdarlingdata merged 77 commits into
devfrom
fix/5743-dmv-wait-split
Oct 13, 2026
Merged

erikdarlingdata merged 77 commits into
devfrom
fix/5743-dmv-wait-split

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Oct 13, 2026 •

Copy link
Copy Markdown
Owner

Claude posting for Erik Darling.

Closes #5743.

#5705 merged to dev as 3f3b9c1. The seat merged dev into this branch (fd2c23d, built with git merge-tree --merge-base f1f1f59b4 because #5705 was squashed), so the diff is now the #5743 change only: BlockingWaits.cs and two test files (110509f, plus the seat's doc fix 5fc9549).

Summary

Blocking counts group the rows of one (blocked, blocker) pair into waits by derived start (event_time - wait_time_ms). That is safe for blocked-process reports (a reported wait already lasted >= 5 s) but not for DMV snapshot rows, which catch a wait of any length. Wait A seen at T with wait 1,500 ms and a new wait B that starts 200 ms later and is seen at T + 10 s with wait 9,800 ms have derived starts 1.7 s apart, so they counted as one wait.

Design

One rule for every source, no source-specific branch. A blocked session waits on one thing at a time, so a new wait of a pair cannot start before the previous wait was last seen alive, and a row's event_time is a moment its wait was observed alive. A row now starts a new wait when EITHER its derived start is more than WaitStartToleranceMs (2000) after the previous row's start (unchanged) OR its derived start is more than the new WaitStartJitterMs after the LATEST event_time of all preceding rows of the same pair (same start order).

  • C# Collapse<T>: a running max of Time over all preceding rows of the pair, not just the current group.
  • WaitsCteSql (PostgreSQL and DuckDB): the OR in {name}_gapped, MAX(<epoch ms of m.event_time>) OVER (PARTITION BY ... ORDER BY m.wait_start_ms NULLS LAST, m.event_time NULLS LAST ROWS BETWEEN UNBOUNDED PRECEDING AND 1 PRECEDING). A NULL max (no preceding row) puts no constraint. No output column was added; the order and tie-breaks are the same as C#.
  • Blocked-process reports: every report of one wait derives a start at least 5 s before any earlier report's event time, and waits with different starts are already split by the first condition, so the new condition never changes a report count (tests below).

Why WaitStartJitterMs = 150 ms

  • DMV snapshot rows get event_time from the collector, not from the query. DmvBlockingSnapshotCollector.WritePayload writes context.CollectionTime, and both runners stamp that at the start of the run (CollectionTimeClock.NextStrictlyAfter(..., DateTime.UtcNow) in RemoteCollectorService.DefinitionRunner and DarlingCollectorRunner), before the store connection and the SQL Server connection open and before the query reads wait_duration_ms. The derived start is therefore the true start minus that run's lead time (tens of ms on a pooled connection) and varies from run to run. The stamp is not in the same query, so the jitter is larger than a same-query stamp's.
  • PostgreSQL and DuckDB keep microseconds, so the store adds none (no whole-second store is read by this code).
  • 150 ms covers that spread and is below the 200 ms re-block gap in the issue's example; a value of 200 or more would merge that case again. I could not measure lead times against a monitored server (not allowed), so the value rests on the code reading above and on that ceiling.
  • Limit, stated in the constant's doc: a continuing wait splits by mistake only when its next row's lead time is longer than its first row's by more than the first row's wait time plus 150 ms. The collector keeps only waits of at least 500 ms (page latches; 1 s, 2 s and 5 s for the other wait types it reads, DmvBlockingSnapshotCollector ~195), so that takes a run-to-run lead difference above 650 ms. (Seat, 5fc9549: the doc no longer claims an unmeasured "tens of milliseconds" lead time and cites this floor instead.)

Tests

Extended Darling/Darling.Tests/BlockingWaitCountTests.cs (PostgreSQL) and Lite.Tests/BlockingWaitDuckDbTests.cs (DuckDB). Both run the C# rule and the SQL over the same rows and compare rows and per-pair wait counts.

  • Case 21: the issue's example, 2 waits (was 1), in Collapse, PostgreSQL SQL and DuckDB SQL (plus Lite's real overview reader over seeded dmv_blocking_snapshots rows).
  • Case 22: a continuing DMV wait first seen at wait 300 ms, again 10 s later at wait 10,300 (start jitter +40 ms): 1 wait.
  • Cases 23-25: first seen at wait 10 ms, next start +50 ms: 1; exactly +150 ms: 1 (strict comparison); +151 ms: 2.
  • Case 26: three rows of one continuing wait with start jitter up to 120 ms and out of event order: 1.
  • Case 27: the running max covers ALL preceding rows, not only the previous one (a previous-row-only form would split here): 1.
  • Blocked-process reports: two waits 6 s apart = 2 and one 11-report wait = 1, in C# and on PostgreSQL (with wait_reports 1, 2 and 11 unchanged); on DuckDB the overview card, the analysis fact and C# agree on 3.

Runs (rig: throwaway PostgreSQL from pg-runtime.zip, UTC, pg_stat_statements preloaded; stopped and deleted):

  • Build Darling.Tests and Lite.Tests: 0 errors, 0 warnings.
  • BlockingWaitCountTests 19/19 (16 before). BlockingWaitDuckDbTests 14/14.
  • Darling.Tests classes *Blocking*, *DailySummary*, *FleetReadsAreBounded*, *Census*, *Ratchet*: 1019 passed, 0 failed. Stage=Guard: 1624 passed, 0 failed.
  • Lite.Tests classes *Blocking*, *DailySummary*, *Census*, *Ratchet*: 312 passed. Stage=Guard: 502 passed.
  • Final re-run after restoring the red-plants: Darling *BlockingWait* + *DailySummary* 101 passed, Lite *Blocking* + *DailySummary* 245 passed.

Red-plant (each restored afterwards):

  • C# OR removed (|| (false && ...)): DmvSnapshots_AWaitCannotStartBeforeThePreviousWasLastSeen and PostgresSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows fail (2 of 19).
  • SQL OR removed (OR FALSE AND ...): PostgresSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows fails (1 of 19); DuckDB: DuckDbSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows and DmvSnapshots_OfTwoShortWaits_LessThanTwoSecondsApart_AreTwoWaits fail (2 of 14).
  • Not run on this laptop: the rest of the Darling and Lite suites outside the classes above (CI runs them).

For the coordinator to check

  • Lite's analysis BLOCKING_EVENTS fact reads blocked-process reports only, so the DMV end-to-end test in Lite goes through the overview card, not the fact.
  • The 150 ms value is a code-reading estimate with a hard ceiling from the issue's example, not a measurement.

SECTION: None
ENTRY: none (fixes blocking wait counting added by #5705 in this same unreleased cycle; #5705's buffered entry "Blocking counts one event per wait, not one per blocked-process report" covers it; the buffer is spliced into CHANGELOG.md at the release cut, so dev's [Unreleased] does not show it yet)

…t banner, job history and plan corrections repeats (#5644)
…ow of each DDL; readers drop stored copies (#5644 W6)
… lexical check always, live SET PARSEONLY when DARLING_TEST_SQL is set (#5644 W5)
…keep reused plan-correction names per query (#5644 W1, W21)
…stored rows of that tick by EventSequence (#5644 W6)
…ng filter reaches the linked watermark test
… hours and worst_count (#5644)

W1 made the displayed blocking counts WAITS, but the health band's 5/20 per-hour tiers were measured in blocked-process reports, so a long wait stopped banding by count. The fleet card and the viewer summary keep waits for display and hand the band the report count. /api/fleet refuses hours outside 1..168 and a negative worst_count with the invalid envelope instead of clamping.
…#5743)

A new wait of a pair cannot start before the previous wait was last seen alive: a row also starts a new wait when its derived start is more than WaitStartJitterMs (150) after the latest event time of the pair's preceding rows. One rule in Collapse, and in WaitsCteSql for PostgreSQL and DuckDB. Blocked-process report counts are unchanged.
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review October 13, 2026 15:46
Comment thread PerformanceMonitor.Common/BlockingWaits.cs Outdated
Comment thread PerformanceMonitor.Common/BlockingWaits.cs Outdated
Comment thread PerformanceMonitor.Common/BlockingWaits.cs Outdated
@claude

claude Bot commented Oct 13, 2026

Copy link
Copy Markdown

The changelog justification does not hold up against the tree

The body closes with:

SECTION: None
ENTRY: none (fixes blocking wait counting added by #5705 in this same unreleased cycle; #5705's "Blocking counts one event per wait" entry covers it)

There is no such entry in this checkout. CHANGELOG.md's [Unreleased] section (lines 22-33) holds one Added entry (#5663) and four Fixed entries (#5668, #5665, #5659, #5682) — no blocking-wait entry. Searching the whole tree for the issue numbers that would carry it finds nothing outside code comments:

This checkout contains dev (HEAD is the merge of fd2c23d6 into 3f3b9c1d, and the body names 3f3b9c1d7 as #5705's merge commit), so if #5705 had written that entry it would be here. The entry this PR defers to has not been written yet, which leaves the whole #5644/#5705/#5743 wave with no changelog line at all.

That matters more than a bookkeeping slip, because this PR does change a number operators read. For any server answered by the DMV fallback — AWS RDS, and anywhere the blocked_process_report XE captured nothing — a pair that re-blocks inside the 2 s tolerance now counts as two waits instead of one, on the Lite overview card (Lite/Services/LocalDataService.Overview.cs:134-136), the server-tab badge (LocalDataService.Blocking.cs:604), both daily summaries (LocalDataService.DailySummary.cs:55, DailySummarySql.cs:242), the Darling fleet tile and viewer cards, and the Blocking alert's fired value (AlertContextBuilders.cs:491). A count going up without a released note is the shape that generates "did my blocking get worse?" questions.

Two ways to settle it, either is fine:

  1. Add the [Unreleased] → Fixed entry here, scoped to Blocking waits: DMV snapshot rows can merge two separate waits of the same pair #5743 (what merged as one wait and now does not, and that blocked-process-report counts are unchanged); or
  2. keep ENTRY: none but correct the justification — say the wave's entry is still to be written and under which issue it will land, rather than citing an entry that is not in the tree.

Nothing else in the body needed correcting. The design argument ("a new wait of a pair cannot start before the previous wait was last seen alive"), the two implementations, the 150 ms derivation and every one of cases 21-27 check out against the code — details in the review.

claude[bot]
claude Bot previously requested changes Oct 13, 2026

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Verdict: CHANGES REQUESTED

I derived all seven DMV cases by hand before reading the body. C# (BlockingWaits.cs:110-133) and SQL (:188-200) agree with each other and with DmvExpectedWaits. The new arm is monotone — it only ADDS splits — so nothing that counted before can now undercount. The sole request is the changelog claim (top-level note); the three inline comments are non-blocking.

Claims

  • VERIFIED — the issue's two rows now count as two — :117-118: 1700 <= 2000 passes the old arm, 200 > 150 fires the new one (case 21, BlockingWaitCountTests.cs:401)
  • VERIFIED — "more than WaitStartJitterMs after the LATEST event_time of all preceding rows (same start order)" — :117-118 with the running max at :109,129-132; SQL twin :196 over the same ORDER BY as the LAG at :192-193
  • VERIFIED — "No output column was added; the order and tie-breaks are the same as C#" — :196 adds only an OR arm inside the existing CASE; :201-215 unchanged; starts_wait/wait_no appear in no other file
  • VERIFIED — "A NULL max puts no constraint" — a partition's first row is already caught by WHEN LAG(...) IS NULL (:192) and TRUE OR NULL is TRUE
  • VERIFIED — event_time is the collector's start-of-run stamp — DmvBlockingSnapshotCollector.cs:273; RemoteCollectorService.DefinitionRunner.cs:107 and DarlingCollectorRunner.cs:2149 stamp ahead of the watermark read and the query
  • VERIFIED — both stores keep microseconds — PgSchemaGenerator.cs:47, DuckDbSchemaGenerator.cs:61, CollectionTimeClock.cs:69-75
  • VERIFIED — the 500 ms / 1 s / 2 s / 5 s floors — DmvBlockingSnapshotCollector.cs:195-202; and 200 would indeed re-merge case 21, the comparison being strict
  • VERIFIED — "never changes a report count" for blocked-process reports — holds for any threshold (start(i) - event(j) = jitter(i) - jitter(j) - wait(j), wait(j) positive), pinned both ways by BlockedProcessReports_KeepTheirWaitCounts_AndReportCounts and ...KeepTheirWaitCounts
  • VERIFIED — cases 23-27 — case 27's third row starts 200 ms past the previous row's event, so a LAG-only form splits it (:407); 9850/9849 sit exactly at 150 and 151 ms, every operand an integral ms well under 2^53, so the arithmetic is exact in C# and both stores
  • VERIFIED — "Lite's BLOCKING_EVENTS fact reads reports only" (BlockingWaitDuckDbTests.cs:396); test counts 19 (was 16) and 14 match the [Fact] members; the diff is exactly the three files claimed
  • UNVERIFIED — every build/test and red-plant result — no .NET SDK here, and the PostgreSQL arms are gated on DARLING_TEST_PG
  • UNVERIFIED — that real lead time varies by under 150 ms — the body says so itself; needs a timed run against a live instance
  • REFUTED — "ENTRY: none ... #5705's entry covers it" — no such entry. [Unreleased] (CHANGELOG.md:22-33) holds #5663, #5668, #5665, #5659, #5682 and nothing on blocking; grep "5705\|5644" CHANGELOG.md docs/changelog/*.md is empty, and this checkout already contains dev (3f3b9c1d, the commit the body names as #5705's merge). Two ways to settle it in the top-level note

Riskiest lines

  1. PerformanceMonitor.Common/BlockingWaits.cs:118 — the in-memory arm; a sign error changes every blocking count silently — pinned by DmvSnapshots_AWaitCannotStartBeforeThePreviousWasLastSeen (CI) and BlockedProcessReports_KeepTheirWaitCounts_AndReportCounts
  2. PerformanceMonitor.Common/BlockingWaits.cs:196 — the SQL twin; one string feeds 13 read sites in both SKUs (Lite's card/badge/daily summary, DuckDbFactCollector.Waits.cs:256, PgFactCollector.Waits.cs:277, DailySummarySql.cs:242, DarlingFleetReader.cs:372, DarlingHealthReader.cs:93, three ViewerDataService reads), failing at read time not build time — pinned by DuckDbSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows (CI) and its PostgreSQL twin (live only). No caller is unpinned: each already projects event_time, which :185 required
  3. PerformanceMonitor.Common/BlockingWaits.cs:68 — the 150 ms constant; its boundary is pinned exactly by cases 24/25, its fitness against real lead times is UNPINNED

Traps near this diff

  • "Two copies of one definition pinned EQUAL to each other fail only after BOTH have drifted (#3684). Alias, do not copy." — does not apply — C#/SQL are two forms of one rule by necessity (BlockingWaits.cs:42-44) and are not pinned only to each other: DmvExpectedWaits (BlockingWaitCountTests.cs:411-414, mirrored BlockingWaitDuckDbTests.cs:341-344) is an absolute count, so a both-sides drift still fails
  • "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 — the fix is wholly in shared PerformanceMonitor.Common/BlockingWaits.cs:117-132,196, both test projects covered in the same diff
  • "A pin that encodes the lie ... Ask what a pin would fail ON." — does not apply — case 27 (:407) fails against a previous-row-only form and cases 24/25 straddle the strict comparison by 1 ms
  • "Integer division in a rate column ... suspect until a 1.0 * or a CAST is found." — does not apply — the new comparison is DOUBLE throughout (:177-180) against an integer literal
  • "A test that reads the clock twice measures the CI scheduler. One anchor owns both ends of an interval." — does not apply — the Lite tests derive every stamp from _windowEnd via Ago (BlockingWaitDuckDbTests.cs:29,116); the Darling cases are offsets from static T0
  • "An alert evaluated every ~30 s against an observation that changes once per COLLECTION re-fires on every cooldown expiry ... AlertPersistenceGate at K consecutive collections." — does not apply — the diff changes what the count IS, not its gate; AlertContextBuilders.cs:491 is untouched and consecutive-cycle rows already split on the 2 s tolerance

Divergence (blind read vs PR body)

One: the refuted claim. ENTRY: none rests on a #5705 changelog entry that is not in the tree, so this operator-visible count change has no changelog line anywhere. Everything else matched, including the parts most liable to overstatement — the running max really spans all preceding rows, case 27 really would fail a previous-row-only form, and the no-regression claim really is pinned on both stores.

Two prose-vs-code gaps, non-blocking, posted inline: the WaitStartJitterMs false-split sentence has its lead comparison inverted relative to the start order the rule sorts by (its 650 ms conclusion still holds), and the retained WaitStartToleranceMs doc still cites "a store that keeps only seconds" two lines above the new paragraph saying none is read here.

Reviewer checklist

  • Run both extended classes with DARLING_TEST_PG set — without it the three PostgreSQL arms skip, so CI never exercises the new window on PostgreSQL. I could not build: no .NET SDK here
  • Confirm no other suite's count flipped: the new arm splits same-pair rows spaced between wait_time_ms + 150 and 2000 ms, a band the old rule merged. The fixtures I read look safe (DailySummaryBlockingWaitsLiveTests.PlantAsync, BlockingBandReportUnitLiveTests.PlantAsync and Lite's SeedWaitAsync all write event_time = start + wait; the AzureMaster*ScopeTests space rows a minute apart or per spid) — but that was reading, not running
  • Take one live lead-time reading, cold connection and pooled: the one input to the 150 ms choice the tree cannot supply, and a cold lead above ~650 ms would split a continuing minimum-length wait
  • Decide the changelog question

@erikdarlingdata

Copy link
Copy Markdown
Owner Author

Claude posting for Erik Darling.

On the refuted ENTRY: none claim: the #5705 entry exists, but not in the tree yet. This repo buffers changelog entries from each PR's SECTION/ENTRY lines and splices them into CHANGELOG.md at the release cut, so [Unreleased] on dev does not show #5705's 17 Fixed entries. The buffered one this PR falls under is "Blocking counts one event per wait, not one per blocked-process report" (#5705, dev 3f3b9c1).

#5766 corrects how that same unreleased change splits DMV snapshot rows into waits, so it ships inside that entry and needs no line of its own: no released version ever counted DMV waits the old way. The body's ENTRY line now says "buffered" so the next reader does not look in CHANGELOG.md for it.

The three inline notes are being fixed on this branch (one epoch helper per dialect, the tolerance doc without the whole-seconds clause, and the jitter doc's lead comparison); each thread gets its own reply with the commit.

@erikdarlingdata
erikdarlingdata dismissed claude[bot]’s stale review October 13, 2026 16:39

Claude posting for Erik Darling. Stale: its one request (the ENTRY claim) is answered in comment 6150143924 (the #5705 entry is in the release buffer) and the body is reworded; the three non-blocking notes are fixed in 0839daf.

@claude

claude Bot commented Oct 13, 2026

Copy link
Copy Markdown

Follow-up review of 0839dafda (the only commit in range fd2c23d65..0839dafda).

This commit does exactly what the previous review's three inline notes asked for, and does them correctly:

No behavior changed: the generated SQL string is byte-identical before and after (confirmed by hand, not just by inspection of the ternaries), WaitsCteSql's public signature is untouched, and every one of its ~13 call sites across both SKUs still gets the same text. No new findings.

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Verdict: LGTM

Claims

  • VERIFIED — title: "one epoch helper per dialect" — EpochMsSql(dialect, column) added at BlockingWaits.cs:153-156, called twice at :182-183 in place of the old string.Replace("s.event_time", "m.event_time") derivation; output is byte-identical for both SqlDialect values.
  • VERIFIED — title: "the jitter and tolerance docs say what the code does" — the WaitStartJitterMs doc's lead-comparison sentence (:62-65) was rewritten from a directional ("next row's lead longer than first row's") to a symmetric one ("the row with the longer lead"); re-deriving the split condition from the CTE's actual comparison (current.Start - latestEpochMs > WaitStartJitterMs, expanded via derived_start = true_start - lead) gives lead_prev − lead_j > wait_prev + jitter, i.e. the row with the longer lead is the one whose wait bounds the gap — matches the new sentence exactly; the old one had it backwards.
  • VERIFIED — the WaitStartToleranceMs doc (:48-50) no longer claims "the whole-second rounding of a store that keeps only seconds", consistent with the adjacent WaitStartJitterMs doc's statement that PostgreSQL and DuckDB both keep microseconds.

Riskiest lines

  1. PerformanceMonitor.Common/BlockingWaits.cs:153-156 — EpochMsSql: a dialect-SQL typo here would silently change the epoch math for every caller — pinned by DuckDbSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows (Lite.Tests/BlockingWaitDuckDbTests.cs:347) and PostgresSql_AgreesWithTheCSharpRule_OnDmvSnapshotRows (Darling/Darling.Tests/BlockingWaitCountTests.cs:428, live-only)
  2. PerformanceMonitor.Common/BlockingWaits.cs:182-183 — the two call sites now derive from the shared helper instead of a text-substituted copy; same tests as above confirm the generated SQL still agrees with the C# rule after the refactor
  3. PerformanceMonitor.Common/BlockingWaits.cs:62-65 — the rewritten jitter-doc sentence; doc only, not pinned by any test, but independently re-derived above and confirmed to match the code at :199 — UNPINNED (as prose, by nature)

Traps near this diff

  • "Two copies of one definition pinned EQUAL to each other fail only after BOTH have drifted (#3684). Alias, do not copy." — does not apply as a defect; this commit is the remedy for the shape (replacing a text-substitution copy with one shared helper function) — BlockingWaits.cs:153-156,182-183

Divergence (blind read vs PR body)

None — the title's two claims ("one epoch helper per dialect", "the jitter and tolerance docs say what the code does") match the diff exactly, and both match the three non-blocking items the prior full review (head=fd2c23d65...) raised inline.

Reviewer checklist

  • None beyond the prior full review's checklist (live PostgreSQL run, a cold-connection lead-time reading) — this commit is doc/refactor only and changes no runtime behavior

@erikdarlingdata
erikdarlingdata merged commit 9f133ec into dev Oct 13, 2026
26 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/5743-dmv-wait-split branch October 13, 2026 17: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