Split per-database collection timing into open + drain — the measurement the next QS fix needs (#2164)

[erikdarlingdata]

Why this instead of the fix I said I'd build

I was queued to build #2164's second half (skip re-shipping plan XML the store already holds). Then I measured the first half on a production server and it overturned the premise:

	rows shipped	sql: time
64 MB budget (10 passes)	2,530–8,626	358–480 s
12 MB budget (2 passes)	698, 1,233	383 s, 352 s

5x less text, ~7x fewer rows, and the clock did not move. So the cost is upstream of shipping, which indicts the hash-skip too — it targets CONVERT(nvarchar(max), qsp.query_plan) in the final select, i.e. the same term the budget already proved isn't dominant. Building it would have been a second guess dressed as a fix.

The blocker to knowing more is that our own log blends the batch: ExecuteReaderAsync blocks through the non-rowset SELECT … INTO #pm_qs_slice, so the aggregate and the final select are indistinguishable in sql:.

What this does

Times the open separately from the drain, exploiting the fact that ADO.NET returns the reader only when the first rowset is available:

• open = every preceding non-rowset statement (for query_store, the #pm_qs_slice aggregate) + the final select's time-to-first-row. Nothing client-side shortens this.
• drain = row streaming, which the byte budget and the network path do govern.

The per-database line becomes sql:Xms = open:Yms + drain:Zms. Zero means not measured (Lite doesn't) and suppresses the split rather than printing open:0ms, which would read as "the aggregate was free". Cleared before each open so a faulted read can't log the previous item's split as its own.

What it buys

After one nightly on the dogfood box, the field question becomes answerable instead of arguable: if those 350–480s passes are ~95% open, the fix is narrowing the server-side aggregate (bound its input, narrow the interval span, or run it less often on expensive servers) and no amount of payload trimming matters. If they're mostly drain, the budget knob was right and the link is the problem. Either way the next PR starts from a number.

Testing

StatementSplitTimingTests pins the contract: zero means unmeasured (so an unmeasured host is never read as instant), drain is the remainder and never negative even under clock skew between the two watches, and the query_store read's own signal resets must not clobber the host's measurement — which if broken would make the whole instrumentation silently log zero. Collectors, Service, and test projects build clean.

Groundwork for #2164; no behavior change to collection itself.

[claude]

itemSqlMs (the sql: total this drain calc is derived from) is timed by EnumeratedCollectorDriver.RunAsync's sqlSlice, which starts before perItemWatermark is awaited, not at readItem (see lines 573-591 above). For query_store — the only enumeration collector with a per-item watermark — that callback does a real Postgres round trip (GetLastCollectedTimeForDatabaseAsync), and when the catch-up clamp or adaptive-shrink path fires, it also calls RecordQueryStoreBackfillHoleAsync, which is a read+write against the store (GetCollectorStateAsync + SaveCollectorStateAsync).

None of that time is captured by context.PerItemOpenMs (which only wraps ExecuteReaderAsync inside readItem), but it is included in itemSqlMs. So drain = itemSqlMs - PerItemOpenMs silently folds the watermark-refresh/backfill-hole store I/O into "drain," even though it's neither SQL Server open time nor row-streaming time.

Given the whole point of this instrumentation is to let a reader decide "narrow the server-side aggregate" vs. "the budget/link is the lever" from the split, a database that trips the clamp/adaptive-shrink path on every quiet cycle will look more drain-heavy than it actually is. Worth excluding the watermark callback's time from the sql: slice used here (or timing it separately) so the split stays trustworthy for the diagnosis it exists to support.

[claude]

This test doesn't actually exercise QueryStoreCollector's reset code — it manually sets PerItemTextBudgetExceeded/PerItemTextBytesShipped/PerItemShippedBoundary back to their reset values itself, then asserts PerItemOpenMs is untouched. That only proves CollectorContext doesn't do anything surprising to its own field; it would not catch a regression where QueryStoreCollector.ReadRowsAsync (PerformanceMonitor.Collectors/QueryStoreCollector.cs:1096-1098) itself starts zeroing PerItemOpenMs — which is exactly the silent-zero regression the doc comment above (and this PR's description) says this test guards against.

There's already a FakeCollectorDataReader + established pattern for this in Lite.Tests/QueryStoreCollectorDefinitionTests.cs (ReadItemAsync_ResetsPerItemSignals_AndNormalRowsDoNotTripTheBudget, ~line 870), which pre-sets signals and then calls QueryStoreCollector.Instance.ReadItemAsync(...) for real. Doing the same here (pre-set PerItemOpenMs, call the real ReadItemAsync with a fake reader, assert it survives) would pin the actual contract instead of a hand-mirrored copy of it.

Same concern applies to DrainIsTheRemainder_AndNeverNegative above — it recomputes Math.Max(0, sqlMs - context.PerItemOpenMs) inline rather than calling the runner's actual log-line arithmetic, so a refactor of that line in DarlingCollectorRunner.cs could drift from this test without either one failing.

[claude]

Reviewed. This is diagnostics-only instrumentation (open vs. drain timing) with no behavior change to collection — scope is appropriately small and the reasoning in the PR body is sound. Two left inline:

1. itemSqlMs includes more than readItem (DarlingCollectorRunner.cs:617) — the sql: total the drain calc subtracts PerItemOpenMs from is timed starting before perItemWatermark runs, so for query_store the watermark refresh (and, on the clamp/adaptive-shrink path, an actual store read+write for the backfill hole) silently gets counted as "drain." That's a real precision gap for the exact metric this PR exists to make trustworthy.
2. Two of the three new tests don't call production code (StatementSplitTimingTests.cs) — DrainIsTheRemainder_AndNeverNegative reimplements the runner's arithmetic inline instead of calling it, and OpenMs_IsNotResetByTheQueryStoreRead_... manually mirrors QueryStoreCollector's reset steps instead of invoking ReadItemAsync (there's already a FakeCollectorDataReader pattern for this in Lite.Tests/QueryStoreCollectorDefinitionTests.cs). As written, neither test would catch the regression it's named for.

Other things checked, no issues found:

• Concurrency: EnumeratedCollectorDriver.RunAsync processes items strictly sequentially in a foreach, and context.PerItemOpenMs = 0 is reset as the first statement inside readItem before ExecuteReaderAsync — so a faulted open can't leak the previous item's timing, matching the test's claim and the "cleared BEFORE the open" comment.
• Lite parity: Lite/Services/RemoteCollectorService.DefinitionRunner.cs's readItem lambda (~line 463) is structurally the same shape as Darling's pre-PR lambda and wasn't given the same instrumentation. The PR body calls this out explicitly ("Lite doesn't measure this today") and CollectorContext.PerItemOpenMs defaults to 0 / the log line falls back cleanly when unset, so this isn't a parity bug — just flagging since Lite's own field diagnosis stays unavailable until (if) this gets ported over.
• CollectorContext.PerItemOpenMs is a shared (Lite+Darling) field but additive/backward-compatible; QueryStoreCollector's existing per-item reset block correctly leaves it untouched (verified against QueryStoreCollector.cs:1096-1098).
• CHANGELOG entry matches the code and the [#2164] reference link resolves.

Minor/non-blocking: PerItemOpenMs == 0 is used as both "not measured" and a legitimate (if unlikely) sub-millisecond open, so a genuinely fast open would silently fall back to the old un-split log line. Given real DMV/Query Store queries essentially never round-trip in under 1ms, this is low-risk as-is.

[erikdarlingdata]

Both taken, and the second one's fix is where the first one belonged:

1. Watermark time was landing in drain. Correct, and it matters more than a rounding detail — for query_store the refresh is a monitor-store read, and on the clamp/adaptive path a store write too, so on a catch-up cycle it could be a large chunk of what I'd have read as "streaming". Now its own measured phase: sql:X = wm:A + open:B + drain:C. Not cleared alongside the open reset, since it ran for the same item and clearing it would hand its milliseconds straight back to drain.

2. The tests re-implemented the formula. Fair, and provably so: a test that duplicates the arithmetic could not have caught finding 1, because my copy and the log line's copy were wrong in the same way. The subtraction now lives in CollectorContext.DrainMsFrom with one definition that both the log line and the tests call, and the pins cover watermark exclusion, the zero clamp under stopwatch skew, and that wm + open + drain sums to the total so nothing is silently unattributed. The tautological reset test is gone rather than reworded.

[claude]

Reviewed both commits (initial split + the review-driven watermark fix).

Checked specifically for:

• Race conditions: EnumeratedCollectorDriver.RunAsync iterates items in a plain sequential foreach, so the shared-mutation pattern on CollectorContext (PerItemOpenMs/PerItemWatermarkMs set mid-delegate, read later in onItemComplete) is safe — no concurrent items touch the same context.
• Stale timing leaking across items: if perItemWatermark or readItem throws before reaching its final assignment, the item's batch stays null and the driver continues without calling onItemComplete, so a stale/unset value from a prior item is never logged. The next item always re-measures both phases before its own log line fires.
• The wm + open + drain == sql arithmetic: DrainMsFrom (Math.Max(0, itemSqlMs - PerItemOpenMs - PerItemWatermarkMs)) is correctly the single shipped definition, and both the log line and StatementSplitTimingTests call it rather than re-deriving it — closing the exact gap the PR's own second commit called out (two tests had reimplemented the formula and missed the watermark-inflates-drain bug).
• Lite/Darling parity: this is Darling-only by design — Lite's per-database watermark read is local DuckDB, not a store round trip, so there's no equivalent phase to measure. That's explicitly documented in the CollectorContext.PerItemOpenMs/PerItemWatermarkMs XML docs and the CHANGELOG entry, and OpenMs_DefaultsToZero_SoAnUnmeasuredHostIsNotReadAsInstant pins zero-means-unmeasured so Lite's silence can't be misread as "instant." Not a drift — no action needed there.
• Reset ordering: PerItemOpenMs is cleared immediately before the open (so a faulted open can't carry a stale prior-item split into the log), while PerItemWatermarkMs is deliberately not cleared at that point since it belongs to the same item and clearing it would hand its milliseconds to drain — matches the in-code comment and is covered by the "parts sum to the whole" test.

One very-low-severity note, not blocking: the extended log line only fires when context.PerItemOpenMs > 0 (DarlingCollectorRunner.cs), so a hypothetical item with a real (nonzero) watermark phase but a sub-millisecond open would silently fall back to the plain sql:/pg: line and drop the wm: figure from view. In practice open is a round trip to the monitored SQL Server, so this shouldn't be reachable for query_store today — flagging only in case a future watermark-bearing collector has a cheaper open.

No correctness, security, or performance issues found. The instrumentation is purely additive to logging (no behavior change to collection, as the PR description states), and the test coverage for the clamping/degenerate cases looks solid.