Split the query_store fetch phases into store, target and residual halves

[erikdarlingdata]

Fixes #2811

What

plan_fetch:Nms and text_fetch:Nms each time a whole method, not a query. FetchAndStorePlansAsync opens a store connection, round-trips the store to learn what it already holds, issues at most two statements against the monitored server, and writes the results back — three of those four steps are Postgres. FetchAndStoreQueryTextAsync is identical in shape.

Both now stamp probe: / target: / write: separately, plus chunk and id counts, on their own log line.

The measurement this settles

On omega-01, plan_fetch was 189,562 ms — 85% of a 224-second run — and was read as SQL Server query time for a day. Two measurements of that target statement disagree by two orders of magnitude and both are real:

measurement	workload	result
sp_QuickieStore on OMEGA	cold plans missing from the store (what the collector actually fetches)	~60,213 ms duration / ~57,073 ms CPU per execution
controlled A/B	hot, recently-executed plans	~650 ms for 400 ids

#2791 was tuned on the assumption the target statement dominated, measured 0.508 s in isolation, and moved production nothing. That is consistent with the target half being a rounding error but does not prove it — and the blended number cannot say. This is the #2312 argument one seam further down.

Log format

Existing line, byte-identical (tooling outside this repo parses plan_fetch:(\d+)ms):

[omega-01] query_store [OMEGA] => 4069 rows (sql:224043ms = wm:1032ms + open:5351ms + drain:12067ms + plan_fetch:189562ms + text_fetch:16031ms, pg:4883ms)

New, additive, emitted only when the corresponding fetch actually ran:

[omega-01] query_store [OMEGA] plan_fetch:189562ms = probe:120ms + target:1240ms + write:188000ms + other:202ms (2 chunk(s), 512 ids)
[omega-01] query_store [OMEGA] text_fetch:16031ms = probe:90ms + target:14500ms + write:1400ms + other:41ms (1 chunk(s), 300 ids)

other: is a computed residual, not a fourth stopwatch, so the parts sum to the parent by construction rather than approximately. A large other: is itself a finding: the cost would be in the collector's own bookkeeping, in neither database.

Design notes

• Own line, not nested. "Don't break the external parser" outranks "one line to grep".
• Cleared on the same rule as the parents — before the operation, so a faulting item cannot print the previous database's split as its own. A stale sub-split is worse than a stale total because it looks precise.
• Stamped in finally, not after the block. A timed-out target statement and a cancelled store write are exactly the events this needs to describe; stamping only on success would report target:0ms for them — "the target was free" is the misreading the whole change exists to end.
• Id/chunk counts make per-id cost computable, which is the only honest way to compare a cold production pass against a hot-plan benchmark. Comparing the totals is how a 0.508 s figure came to be believed about a 189 s phase.

Verification

Darling.Tests is net10.0-windows and cannot run on macOS, so both harnesses ran against the real built assemblies.

1. Arithmetic (against the shipped PerformanceMonitor.Collectors.dll) — 19/19 PASS, including the identity probe + target + write + other == parent, the zero-clamp on stopwatch skew, and a pair proving the same 189,562 ms parent now yields opposite diagnoses (store-bound vs target-bound).

2. IL witness — loads the shipped PerformanceMonitor.Darling.Service.dll and resolves call tokens through the metadata tables to confirm all ten setters are present in the compiled async state machines. Deliberately not a string scan: the last binary witness in this repo returned "the fix never shipped" on both the box and the artifact because it decoded UTF-16 from offset 0 and only saw even byte offsets, while its positive controls passed inside the broken scan.

3. Red-first. Reverting DarlingCollectorRunner.cs to origin/dev and rebuilding:

FAIL FetchAndStorePlansAsync calls set_PerItemPlanProbeMs      (x10, all setters)
PASS negative control: bogus setter is NOT reported present
PASS positive control: pre-existing TouchAndProbePlansAsync call is seen
10 IL FAILURE(S)

My first positive control was Stopwatch.StartNew, which failed on the reverted build too — because the stopwatches are my code, so it proved nothing about the scanner. Replaced with a call that exists on origin/dev, so on the reverted build both controls pass while all ten setter checks fail. Restored → ALL IL CHECKS PASS.

Scope

Instrumentation only. No query change, no hint change (#2806 stays open), no retention change (#2809). Not deployed.

🤖 Generated with Claude Code

https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy

[claude]

Review

Went through this as an instrumentation-only change (no query/hint/retention behavior change) and didn't find correctness, security, or Lite/Darling parity issues.

What I checked:

• Arithmetic identity — PlanFetchOtherMs/TextFetchOtherMs are computed residuals (Math.Max(0, parent - probe - target - write)), so probe + target + write + other == parent holds by construction. Matches the pinned tests in StatementSplitTimingTests.cs.
• Reset discipline — all 10 new CollectorContext fields are cleared at the same site and same point (before the item's read) as the existing PerItemOpenMs/PerItemPlanFetchMs/PerItemTextFetchMs reset, so a faulting item can't leak the previous item's sub-split.
• finally-based stamping — probe/target/write are each stamped in finally blocks (or, for probe, before the "nothing owed" early return), so a timeout or cancelled write reports the time it actually burned instead of 0ms. Verified this holds across both the early-return paths (references.Count == 0, missing.Count == 0) and the chunk loop's per-chunk try/finally.
• Parent/child consistency under failure — if FetchAndStorePlansAsync/FetchAndStoreQueryTextAsync throws inside the target or write phase, the internal catch (Exception ex) when (ex is not OperationCanceledException) swallows it and the sub-phase fields stay at their partial values, while the caller still stamps PerItemPlanFetchMs/PerItemTextFetchMs from its own wrapping stopwatch after the await returns — so the parent total and whatever sub-phases got set stay coherent, and the parent/sub-phase logging gate (> 0) still lines up correctly.
• Log format — confirmed the existing plan_fetch:Nms + text_fetch:Nms line's format string is byte-identical to dev (diffed it directly); the new sub-split rides its own line, gated on the same > 0 check as its parent, so collectors that never separate-fetch print nothing new.
• Lite parity — FetchAndStorePlansAsync/FetchAndStoreQueryTextAsync/QueryStoreFetchProbe have no Lite equivalent (grepped Lite/); this fetch-from-central-Postgres-store shape is Darling-only by architecture, so there's no counterpart to drift out of sync. CollectorContext is shared, but the new fields default to zero and Lite never touches them (test FetchPhases_DefaultToZero... documents this contract already).
• Security/perf — no new SQL text construction, no new user input paths (this only wraps existing queries with stopwatches), no new I/O. No missing-index DMV usage either way, so nothing to flag there.

One minor naming note, not a bug: context.PerItemPlanIdsAttempted (and its text twin) is incremented unconditionally in the chunk's finally, while the local attempted list used for the target-side-gone cleanup only grows after ExecuteReaderAsync succeeds. So a chunk whose statement fails before returning a reader counts toward PerItemPlanIdsAttempted but not toward attempted. That matches the doc comment ("ids the fetch attempted this pass," i.e., tried, not necessarily succeeded) and is clearly intentional given the finally-not-after-block reasoning documented right above it — just flagging the two same-ish-named counters carry different semantics in case it trips up a future reader.

No inline comments to add.