Attribute the store probe inside query_store's sql_duration_ms instead of re-basing the column (#3192)

[erikdarlingdata]

Closes #3192.

collection_log.sql_duration_ms is documented and consumed as the time a collector spent querying the monitored server, and on the collectors that fetch plan XML or statement text it is mostly not that. The enumerated driver's per-item stopwatch (EnumeratedCollectorDriver.RunAsync) wraps the watermark refresh and the whole readItem closure, and for query_store that closure calls the deferred plan and text fetches — each of which round-trips the store to learn what content is already held before writing back what came off the target. One measured production run: sql_duration_ms 124,972 ms, of which plan probe_ms 54,016 and text probe_ms 53,318 — 107,334 ms, 86%, was store time — against a plan-plus-text target_ms of 6,494. Fleet-wide the store probe is the largest single term in both fetches, 55.4% of plan_fetch and 80.6% of text_fetch, which V110 already measured and recorded.

Two of #3192's framings did not survive checking, and neither moves the conclusion. query_store is not the most expensive collector by total on the store I could read: live 7-day get_collector_cost puts procedure_stats at 486,660,678 ms against query_store's 452,742,197 - query_store leads on avg_sql_ms (6,744) and max_sql_ms (344,436), and procedure_stats is server-scoped so none of its figure is store time. And the ~45.8 M ms/day does not reproduce there either: 452,742,197 / 7 = 64.7 M ms/day.

So the product's own "is the target slow or is the store slow" split points the wrong way on its heaviest enumerated collector, and the projection comment that states the split's purpose sits directly above the two columns that invert it.

The decision, and what the alternative costs

Option 1 — re-base the column (subtract the store terms from sql_duration_ms, or exclude the fetches from the driver's slice) was declined, because the past cannot be brought along and the surface where the harm is largest cannot be corrected either way:

• CollectorRunResult.SqlMs also feeds collect.collector_cost, whose nine columns are metric_time, server_id, database_name, collector_name, run_count, total_sql_ms, max_sql_ms, total_storage_ms, total_rows. No phase split, and it is not a continuous aggregate — CollectorCostAccumulator sums the blended figure in memory and flushes an hourly row, so there is nothing to subtract from those rows and no source table to re-derive them from. Re-basing leaves 90 days meaning one thing and every row after meaning another, with nothing in the series able to reconcile them, and it makes those 90 days no more correct than they are now.
• That series feeds the Collector Cost Regression self-alert, whose baseline window is 14 days and whose factor is 2.0. An 86% drop at the deploy would resolve any live regression as a false recovery, and for a fortnight afterwards a genuine target-side regression would be measured against a baseline inflated by pre-change rows. That failure direction is silence.
• Routing the probe into store_duration_ms instead of deleting it is worse, not better. That column is the binary COPY of the collected rows and nothing else, and it is the measurement ServiceCommandDeadlines derives the 10 s COPY deadline from ("the worst of 200 runs was 1.53 s"). Absorbing a 54 s probe would take that maximum to ~54 s, and the next person re-deriving the deadline from it would widen a deadline the sweep watchdog depends on.

Option 2 — move the documentation is what ships, extended so the number carries its own correction rather than only a caveat: sql_store_ms, derived on DarlingDataReader.CollectionLogEntry from the V110 columns already on the row (plan_fetch.probe_ms + write_ms + text_fetch.probe_ms + write_ms), emitted flat beside sql_duration_ms by get_collection_log, and rendered as its own column in the web grid. Derived rather than stored, the SqlOtherMs / #2859 rule — which also makes it retroactive to every row written since V110 instead of only to rows written after this change. No persisted column changes meaning; nothing vanishes; a 124,972 ms run still sums to 124,972 ms.

What the recommendation costs, stated rather than implied:

1. get_collector_cost still reports a blended total_sql_ms / max_sql_ms, because its series carries no phase split. All it can do is refuse to call the figure target-side and point at the per-run tool, and that is all it now does. This is the bound on what any option could achieve there, not a shortcut taken here.
2. sql_store_ms is a FLOOR on the store share, not the whole of it. The per-item watermark refresh is also inside the same stopwatch and is also a store read — plus a store write on the catch-up/adaptive path — and the enumerated branch never raises V108's measured flag, so watermark_ms is NULL on precisely the rows sql_store_ms is non-null on and that component is recorded nowhere. sql_duration_ms - sql_store_ms is therefore an upper bound on target time. The caveat is on the property, on both tool descriptions and in the web grid's comment, and the premise it rests on is pinned.
3. A fetch that ran and cost under a millisecond is indistinguishable from no fetch — inherited from V110's PerItem*FetchMs > 0 gate rather than resolved here, and asserted so the inheritance is deliberate.

Also corrected, having asserted a target-side reading they cannot support

• get_collector_cost's description and both response notes (the single-collector trend had no caveat at all, and it is the shape a regression investigation lands on), from one StoreProbeCaveat constant rather than two copies.
• get_collection_log's description.
• The web grid's collection_log column header, which read "On Server" — the false claim rendered as two words. It is "SQL" now, matching what the WPF viewer's grid has always called it, with "Store (in SQL)" beside it.
• The Collector Cost Regression alert body, which said flatly "This is the MONITORING TOOL's cost on the target".
• EnumeratedCollectorDriver's readItem / EnumeratedRunResult.SqlMs contract, CollectorRunResult.SqlMs (which had no <param> doc at all) and CollectorCostAccumulator's "sql_ms is a DURATION on the target".

Found in passing, in the doc block being corrected

The driver's per-item budget doc said the budget is null for "every collector but query_store" — in three places, one of them at the runner's own call site. Four definitions declare a budget (CollectorCatalog.HasWallClockBudget's own doc calls them "the four budgeted heavies") and two of those also enumerate, so plan_correction reaches perItemBudget non-null as well. Corrected and pinned by deriving the claim from CollectorCatalog.All rather than restating a name, which is the same argument that helper's doc makes for existing.

Scope, checked rather than assumed

Only the enumerated path folds store work into its SQL slice. The server-scoped path reads its watermark at DarlingCollectorRunner.cs:894 and starts sqlSlice at :2106; the per-database path declares its slice early but deliberately starts it below the watermark read and the backfill-hole write, with its own comment saying why. V108's claim that the watermark "runs before that stopwatch starts" holds on both, and both are already pinned.

The other four enumerating collectors (plan_correction, query_store_health, index_object_stats, database_scoped_config) do enter both fetch methods inside their slice — the gates are SKU flags, not collector identity — but extract no references and early-return, so their residual store cost there is the borrowed-connection state check. The version of this that mattered has already been fixed: before the fetch carryover key included the collector, #2902 measured ~346 s of Query Store fetch time over 38 h billed to those three collectors' own rows.

Review follow-through

Three gaps were raised on review. Two were real, one was not.

Real, and the same defect one file over. get_collector_cost's description refused the target-side claim while DarlingCollectorCostReader — the reader it calls through — still asserted it in three places ("sql_ms is a DURATION on the target", "Average target-side duration per run", "most-recent day's target-side cost"), and EvaluateCollectorCostAsync's XML doc asserted it in a fourth, directly above the alert text corrected in the first commit. All four fixed, and the sweep is now by phrase across the whole call path rather than per site.

Real, and declined with the reason recorded where an operator would look. Neither WPF grid gets a "Store (in SQL)" breakout. That is not an oversight: CollectionLogRow and both backing queries (RecentCollectionLogSql, CollectionLogByCollectorSql) are documented verbatim copies of Lite's, Lite runs no deferred fetch, and Lite's store has no V110 columns — so the breakout would either fork a deliberately-verbatim type or add permanently-NULL DuckDB columns, which is the outcome the two-store parity rule prevents and the exact ground V110 declined a Lite twin on. Note also that the WPF headers are "SQL (ms)" and "SQL Duration" — they name the phase, not the side, so unlike the web grid's "On Server" there was no false claim there to correct. Both grids now say all of that in a comment beside the column, and the web grid's cross-reference no longer implies the desktop grid has the breakout.

Not real. Review concluded Lite's query_store "has the identical store-probe contamination" because Lite sums the same driverResult.SqlMs from the same shared driver. It does not: the fetches are gated on CollectorContext.CapturePlanXml and FetchQueryTextSeparately, and Lite sets neither — that is what makes Darling the plan-capturing SKU — so no probe and no write-back ever runs there. grep over Lite/ finds no CapturePlanXml/FetchQueryTextSeparately assignment, no FetchAndStore*, and no QueryStoreFetchProbe. What Lite does share is the watermark shape: its query_store reaches the driver's perItemWatermark, a read against its local store inside the slice. So Lite's description gains that precision and explicitly disclaims the probe half, and the pin asserts the disclaimer — a Lite description that claimed store-probe time would advertise a cost that cannot be incurred, and would send someone building V110-equivalent DuckDB columns that could only ever be NULL. That is a check that fails toward the worse label rather than the convenient one.

Verification

Darling.Tests is net10.0-windows; the new file was compiled into a net10.0 xunit.v3 harness with AssemblyName Darling.Tests alongside the repo-wide DocCommentHygieneTests, so the added crefs and <para> blocks are checked by the shipped guard rather than by eye. Baseline: Total 85, Failed 0, Errors 0, Not Run 0.

Which check actually runs this content: build (windows-latest), whose "Run Darling tests" step executes the suite — confirmed success on the first commit with the job at 545 s. Darling whole-tree guards reported success in 15 s on that commit, and that is the design rather than a gap: it is the FALLBACK, gated on needs.build.outputs.darling-tests == 'skipped', so exactly one of the two jobs runs the suite and here it was build. Steps 5-8 of the guards job (Setup .NET / Restore / Build / Run the whole-tree guards) are all skipped on that run. Read the guards job's duration only when build's path filters left the suite unrun.

Every pin red-proofed by mutation, committed first, presence confirmed by --numstat plus a content check, restoration confirmed by content:

	mutation	verdict
baseline	—	GREEN
M1	SqlStoreMs: drop the write-back terms (probe only)	RED
M2	SqlStoreMs: fold in the target halves	RED
M3	SqlStoreMs null guard: && → ||	RED
M4	driver: sqlSlice.Restart() after the watermark, excluding it	RED
M5	runner: raise the V108 measured flag inside the enumerated branch	RED
M5b	record: un-gate ServerPhases so a watermark persists without the flag	RED
M6	projection: stop emitting sql_store_ms	RED
M7	projection: bury sql_store_ms after the fetch blocks	RED
M8	get_collector_cost: restore "target-side query duration"	RED
M9	get_collector_cost: drop the caveat from the trend note	RED
M10	web grid: restore the "On Server" header	RED
M11	option 1 at the cost surface: subtract the probes before Record	RED
M12	driver doc: restore the stale budget claim	RED
M13	runner call site: restore its own copy of that claim	RED
M14	cost reader: restore "DURATION on the target"	RED
M15	cost reader: restore "Average target-side duration per run"	RED
M16	evaluator XML doc: restore "target-side query time"	RED
M17	Lite description: claim the store share it cannot have	RED
M18	Lite runner: enable the plan fetch, giving Lite the real defect	RED
C1	control — reword an unrelated sentence in the same doc block	GREEN
C2	control — reword the WPF grid's new note	GREEN
post-restore baseline	—	GREEN

M14 first reported GREEN, and that is the most useful result in the table. The pin swept for "DURATION on the target" as an exact substring, and restoring the claim put it across a doc-comment line break — so the assertion matched nothing and certified the very claim it was written to forbid. Doc prose is now flattened (/// continuations and whitespace runs collapsed) before every phrase sweep, with a control asserting the flattener itself still finds a phrase this fix deliberately kept, so an empty return cannot make five negatives pass. M14 is RED after that.

Two more are worth naming. M5's first form was ServerPhasesMeasured: true at the enumerated return, which build-failed — the two paths share one return statement and pass a variable, so the pin as first written asserted the absence of a literal no reachable mutation could introduce. It was rebuilt on the shipped gate (CollectorRunResult.ServerPhases) plus the single-assignment count and its position below the driver call, and M5/M5b then reported RED. And the phrase sweep in the budget pin initially failed on this fix's own prose, because a correction has to be able to name what it corrected; it counts the phrase against its quoted form instead. That pair catches a reversion and a new copy, and does not catch deleting the corrected paragraph outright — the catalog-derived assertions are what make the claim itself checkable.

No schema change, no version bump, no migration rung.

CHANGELOG entry text (not committed — one [Unreleased] block, one appender)

• query_store's sql_duration_ms was mostly store time, under a column documented as the monitored server's ([query_store's sql_duration_ms includes store-side probe time, so the target-vs-store split points the wrong way on the most expensive collector #3192]) - the enumerated driver's per-item stopwatch wraps the whole readItem closure, and for query_store that closure round-trips the store to decide what plan XML and statement text are already held before writing back what came off the target. One production run: 124,972 ms of sql_duration_ms of which 107,334 ms - 86% - was the two store probes, against 6,494 ms of plan-plus-text target time; fleet-wide the probe is 55.4% of plan_fetch and 80.6% of text_fetch. So get_collector_cost's tens of millions of ms/day of "target-side query DURATION" (64.7 M ms/day measured over 7 days on one production store, where query_store's sql_duration_ms includes store-side probe time, so the target-vs-store split points the wrong way on the most expensive collector #3192's ~45.8 M does not reproduce - a different store or window; the ratio is the claim, not the absolute), the get_collection_log projection comment stating that a collector slow because the target is slow needs work on that server, and the web grid's "On Server" column header were all pointing at the monitored servers for time spent in the monitoring store - the ~6.5 : 1 anti-target bias V110 declined a rollup shape over, arriving through the parent column instead. The column is NOT re-based, and the reason is that the past cannot follow it: CollectorRunResult.SqlMs also feeds collect.collector_cost, nine columns with no phase split, flushed hourly from an in-memory accumulator rather than aggregated from collection_log - so there is nothing there to subtract, no source to re-derive from, and a re-based column would leave 90 days meaning one thing and every row after meaning another under a self-alert whose baseline window is 14 days, in which a real regression is measured against an inflated baseline. Routing the probe into store_duration_ms is worse rather than kinder: that column is the binary COPY and nothing else, and it is the measurement ServiceCommandDeadlines derives the 10 s COPY deadline from ("worst of 200 runs, 1.53 s"), so absorbing a 54 s probe would widen a deadline the sweep watchdog depends on. Instead sql_store_ms derives the store share from the V110 columns already on the row, so nothing is stored, nothing vanishes, a 124,972 ms run still sums to 124,972 ms, and the attribution applies retroactively to every row since V110. It is a FLOOR, said out loud on the property and on both tool descriptions: the per-item watermark refresh is also a store read inside the same stopwatch, the enumerated branch never raises V108's measured flag so watermark_ms is NULL on exactly these rows, and that component is recorded nowhere - which makes sql_duration_ms - sql_store_ms an upper bound on target time. get_collector_cost can only carry the caveat and point at the per-run tool, and that bound is stated as the limit of what any fix could reach there. Scope checked rather than assumed: the server-scoped and per-database paths both keep every store round trip outside their sql stopwatch, deliberately and already pinned, so the enumerated path is the only one. Found in the same doc block: the driver's budget doc claimed the per-item budget is null for "every collector but query_store" in three places, one at the runner's own call site - four definitions declare one and two of those enumerate, so plan_correction arrives non-null too; corrected and pinned by deriving the count from CollectorCatalog.All. Proven red fourteen ways with a green control and the baseline printed, including the option-1 change applied at the cost surface, and including one pin that had to be rebuilt after its first mutation build-failed - the shared return statement passes a variable, so asserting the absence of a literal there was a check nothing could turn red.

[claude]

Reviewed. This is a large, well-documented, doc-and-derived-value-only change (no schema/migration, no persisted-column meaning change), and the mutation-tested arithmetic in CollectionLogStoreProbeAttributionTests.cs gives good confidence in the SqlStoreMs derivation itself. No T-SQL touched, so the T-SQL style section doesn't apply here.

Three gaps worth a look before merge, all around the PR's own core claim — "the split's purpose... is what the caveat should follow through everywhere it's asserted":

1. Lite carries the identical bug with zero acknowledgment. Lite/Services/RemoteCollectorService.DefinitionRunner.cs:749 sums the same EnumeratedCollectorDriver.RunAsync result (driverResult.SqlMs) into Lite's own sql_duration_ms, through the same shared QueryStoreCollector/EnumeratedCollectorDriver in PerformanceMonitor.Collectors. So Lite's query_store runs have the same store-probe contamination this PR spent 625 lines correcting for Darling — but Lite/Mcp/McpHealthTools.cs's get_collection_log tool still flatly asserts sql_duration_ms is "the part spent querying the monitored server," and Lite's collection_log schema (Lite/Database/Schema.cs) has no V110-equivalent columns to even compute a floor. I get that a full fix needs new Lite schema/columns (real work, arguably its own PR) — but at minimum the tool description is now a proven-false claim and this PR doesn't flag it as a known gap anywhere (CHANGELOG text, code comment, or issue).

2. Left a few of the exact "target-side" assertions this PR is about correcting, uncorrected, in the file the fixed tool depends on. DarlingCollectorCostReader.cs — the internal reader backing the now-fixed get_collector_cost tool and the now-caveated self-alert — still says "sql_ms is a DURATION on the target" (line 26), AvgSqlMs's doc says "Average target-side duration per run" (line 68), and the regression-detection doc says "target-side cost regressed against its own baseline" (line 123). DarlingSelfAlertEvaluator.cs:715's XML doc for EvaluateCollectorCostAsync similarly still says "target-side query time exceeds their own baseline," right above the method whose fired-alert text below it (line 777) was corrected in this same PR.

3. The WPF desktop viewer's Collection Log grid wasn't touched. ViewerServerTab.xaml's CollectionLogGrid (fed by ViewerDataService.CollectionHealth.cs's RecentCollectionLogSql / CollectionLogByCollectorSql) only selects sql_duration_ms and duckdb_duration_ms — no plan_fetch/text_fetch columns, so no way to compute sql_store_ms there at all — and its "SQL (ms)" header carries no caveat. The web grid's new comment claims the renamed header matches "what the WPF viewer's grid has always called it," which is true for the header text, but the WPF grid never got the new "Store (in SQL)" breakout column the web grid did, so an operator using the desktop viewer still sees exactly the misleading picture this PR set out to fix.

None of these are correctness bugs in what was changed — the new SqlStoreMs logic, its two consuming tools, and the self-alert text are all internally consistent and well-tested. They're follow-through gaps: the same false claim this PR hunted down everywhere else survives in a few places it apparently didn't check.

[claude]

Reviewed. This is a documentation/attribution-correctness fix (no schema change, no T-SQL touched, no persisted column added) — sql_store_ms is a derived, never-stored property on CollectionLogEntry that decomposes an existing sql_duration_ms, so it applies retroactively and doesn't disturb collect.collector_cost's 90-day series.

Spot-checked the claims against the current tree rather than taking the PR body at face value:

• SqlStoreMs arithmetic (PlanFetchProbeMs + PlanFetchWriteMs + TextFetchProbeMs + TextFetchWriteMs, null only when both probes are null) is correct and matches the "floor, not the whole" caveat given (watermark refresh time is genuinely unrecovered).
• V105's collect.collector_cost schema really does have no phase-split columns and DarlingWorker.cs:6509 really does hand result.SqlMs to the accumulator unmodified — the "not re-based" decision is real, not just asserted in a comment.
• The "four budgeted collectors, two of which enumerate" correction checks out: query_stats/procedure_stats declare PerItemWallClockBudget but don't implement BuildEnumerationQuery (server-scoped), while plan_correction and query_store both declare the budget and enumerate — so the driver's old "every collector but query_store" comment was in fact stale, and the fix is accurate.
• Lite/Darling parity: correctly not mirrored. Lite/Services/RemoteCollectorService.DefinitionRunner.cs never sets CapturePlanXml/FetchQueryTextSeparately, so the store-probe contamination this PR documents cannot occur on Lite — only the (much smaller) per-item watermark refresh does. The Lite tool description change reflects that precisely rather than copying Darling's caveat wholesale. The WPF viewer intentionally does not get a sql_store_ms breakout column, and the comments explain why (shared row type with Lite, which has no V110 columns) rather than leaving it a silent omission.

No correctness, security, or performance concerns. Nothing to flag inline — this is prose/documentation/attribution correctness backed by a real derived property, and the extensive test file (CollectionLogStoreProbeAttributionTests.cs) pins the arithmetic, the doc-string corrections, and the Lite non-regression directly against source and shipped attribute text.