The problem
PerItemPlanFetchMs — the number that prints as plan_fetch:Nms — times the entire FetchAndStorePlansAsync call, which does four distinct things across two different databases:
1. await _postgres.OpenConnectionAsync(...) <- STORE (Postgres)
2. await QueryStoreFetchProbe.TouchAndProbePlansAsync(...) <- STORE round trip
3. foreach chunk in attempt.Chunk(PlanFetchIdsPerStatement):
4. BuildPlanFetchByIdsQuery -> ExecuteReaderAsync + read loop <- TARGET (SQL Server)
5. await QueryStorePlanWriter.WriteAsync(...) <- STORE write
Three of those four steps are Postgres. PerItemTextFetchMs / FetchAndStoreQueryTextAsync has the identical shape.
Why it matters — the contradiction this exists to settle
On omega-01, 2026-09-02 23:44:31Z:
query_store [OMEGA] => 4069 rows (sql:224043ms = wm:1032ms + open:5351ms + drain:12067ms
+ plan_fetch:189562ms + text_fetch:16031ms, pg:4883ms)
plan_fetch is 85% of that run, and it was read as SQL Server query time for a full day. Two measurements of the target statement exist and they disagree by two orders of magnitude:
sp_QuickieStore on OMEGA shows the plan-fetch statement at ~60,213 ms duration / ~57,073 ms CPU per execution — real SQL Server CPU, on the collector's actual workload of cold plans missing from the store.- A controlled A/B measured the same statement at ~650 ms for 400 ids — but on hot, recently-executed plans.
Both numbers are real; they are different workloads. Nobody knows which dominates the 189-second phase, and the blended number cannot say. #2791 was tuned on the assumption it was the target statement, measured 0.508s in isolation, and moved production nothing — which is consistent with the target half being a rounding error, but does not prove it.
This is exactly the argument #2312 already settled one seam higher up, for the same reason: a blended sql: could not say which statement, so the next fix would have been a guess.
What this adds
Sub-phase timings inside both fetch methods, on their own log line so nothing parsing the existing line breaks:
[<server>] query_store [<db>] plan_fetch:189562ms = probe:120ms + target:1240ms + write:188000ms + other:202ms (2 chunk(s), 512 ids)
[<server>] query_store [<db>] text_fetch:16031ms = probe:90ms + target:14500ms + write:1400ms + other:41ms (1 chunk(s), 300 ids)
probe: — store connection open + touch/probe round triptarget: — the SQL Server statements only, summed across chunkswrite: — the store writeother: — the residual, computed rather than measured, so the parts sum to the parent by construction- chunk and id counts, because per-id cost is the only honest way to compare a cold production pass against a benchmark over hot plans
other: being large would itself be a finding: it would mean the cost is in the collector's own bookkeeping rather than in either database.
Scope
Instrumentation only. No query changes, no hint changes (the #2791 hint question stays open in #2806), no retention changes (#2809).
The problem
PerItemPlanFetchMs— the number that prints asplan_fetch:Nms— times the entireFetchAndStorePlansAsynccall, which does four distinct things across two different databases:Three of those four steps are Postgres.
PerItemTextFetchMs/FetchAndStoreQueryTextAsynchas the identical shape.Why it matters — the contradiction this exists to settle
On
omega-01, 2026-09-02 23:44:31Z:plan_fetchis 85% of that run, and it was read as SQL Server query time for a full day. Two measurements of the target statement exist and they disagree by two orders of magnitude:sp_QuickieStoreon OMEGA shows the plan-fetch statement at ~60,213 ms duration / ~57,073 ms CPU per execution — real SQL Server CPU, on the collector's actual workload of cold plans missing from the store.Both numbers are real; they are different workloads. Nobody knows which dominates the 189-second phase, and the blended number cannot say. #2791 was tuned on the assumption it was the target statement, measured 0.508s in isolation, and moved production nothing — which is consistent with the target half being a rounding error, but does not prove it.
This is exactly the argument #2312 already settled one seam higher up, for the same reason: a blended
sql:could not say which statement, so the next fix would have been a guess.What this adds
Sub-phase timings inside both fetch methods, on their own log line so nothing parsing the existing line breaks:
probe:— store connection open + touch/probe round triptarget:— the SQL Server statements only, summed across chunkswrite:— the store writeother:— the residual, computed rather than measured, so the parts sum to the parent by constructionother:being large would itself be a finding: it would mean the cost is in the collector's own bookkeeping rather than in either database.Scope
Instrumentation only. No query changes, no hint changes (the #2791 hint question stays open in #2806), no retention changes (#2809).