Decide how to persist the per-database fetch split (plan_fetch/text_fetch), which is N:1 against collection_log #2860

Activity

1. erikdarlingdata

   added 2 commits that reference this issue on Sep 3, 2026

   Address review: fix the #2859 link target, state the Lite scope call

   ...

   29533cc

   Persist the server-scoped phase split to collection_log (Fixes #2859) (…

   ...

   0a7f224
2. erikdarlingdata commented on Sep 4, 2026

   

   erikdarlingdata

   on Sep 4, 2026

   OwnerAuthor

   More actions

   Measured first, as the issue asked. The deciding criterion splits, and the answer is a fourth shape.

   Premise re-verified at origin/dev (8d2a52a), then the distribution measured off the existing log lines. Staying open — this is a decision, and the point of the below is to make it decidable.

   1. Premise still holds

   claim	status at 8d2a52a
   the fetch split is emitted per DATABASE	yes — DarlingCollectorRunner.cs:1390 / :1399, inside onItemComplete, gated on batchCount > 0 and PerItemPlanFetchMs > 0
   it is emit-only	yes — LogInformation, and all ten sub-phase members (PerItemPlan/Text × ProbeMs/TargetMs/WriteMs/Chunks/IdsAttempted/ProbeIds) resolve to exactly three places: the reset block at :1235-1240, their stamp sites inside the two fetch methods, and the one log site. Zero references from InsertCollectionLogSql or any read
   collection_log is one row per run	yes — LogCollectionAsync still takes no database parameter
   the fan-out row's duration_ms is the sum	yes — bound from (int)(sqlMs + storageMs), and sqlMs += driverResult.SqlMs (:1450) is the driver's cross-item total
   schema version	still 109

   One thing has not changed that the issue text implies: [#2855]'s per-database connect:/open:/drain: split is not on dev — its PR is still open, so PerDatabase*Ms does not exist here yet. The decision below still governs it.

   2. The deciding measurement

   Source: the service's own app log on the larger store's monitoring host, 42 SQL Server members, 2026-09-03 00:00 → 2026-09-04 14:12 UTC (38.2 h), build 3.6.0. Runs bracketed by the server-level => N rows (sql:…, pg:…) line that closes each enumerated run, which is interleaving-safe (bodies run four-wide); 0 runs left unclosed.

   Scope caveat, stated up front. 11,193 plan_fetch and 11,099 text_fetch sub-split lines exist in the window, but only ~7,580 of the plan-fetch ones (67.7%) carry the current 11-field format. [#2823] added the N probed) term on 2026-09-03 08:48 UTC, so lines emitted by the pre-[#2823] build were excluded by the parser. Row-volume figures below use the raw 11,193 / 11,099 counts (format-independent). Distribution figures use the parsed subset — which is the current code's format, i.e. the relevant one.

   query_store, 2,769 runs that emitted a plan-fetch split:

   databases fetching in one run	1	2	3–4	5–8
   runs	865	331	1,249	324
   share	31.2%	12.0%	45.1%	11.7%

   Mean 2.7, max 7. So it is genuinely N:1, with N > 1 on 68.8% of runs. Notably mean_databases_fetching and mean_databases_PRODUCTIVE are both 2.70 — for query_store every productive database also fetches, so the fan-out's productive width is the fetch split's width.

   And the cost is spread, not dominated. The slowest database holds a median 58.8% of its run's plan_fetch ms (p25 45.9%, min 19.6%); restricted to the 2+ runs, median 51.0%.

   By the criterion this issue states — "if the fetch cost is spread evenly across many databases, option 1 is not enough" — that reads as a verdict against option 1. But the criterion carries a hidden assumption, and the measurement breaks it.

   3. The question option 1 exists for is still answered ~90% of the time

   The question is which of probe: / target: / write: owns the time. So compare the whole run's winner (argmax of the summed phases — the ground truth) against what the slowest database alone would have said:

   	plan_fetch	text_fetch
   runs	2,769	2,769
   slowest db gives the same winner	92.8%	96.2%
   same, weighted by fetch ms	92.5%	98.1%
   same, among runs with 2+ fetching dbs	89.5%	94.5%

   Evenness of spread and wrongness of verdict do not move together. Databases inside one run are phase-correlated — same store, same target, same two statements — so the slowest one usually gives the right verdict while holding only half the milliseconds. The issue's criterion conflates "option 1 loses information" (true, it loses ~half the ms) with "option 1 gives the wrong answer" (false ~90% of the time).

   4. But option 1's residual error points the single worst way

   The 199 plan-fetch disagreements are not symmetric:

   truth	slowest db says	runs
   probe	target	170
   target	probe	26
   probe	write	3

   Option 1's failure mode is blaming SQL Server when the cost is actually the store probe, at ~6.5 : 1 odds. That is the exact misreading [#2811] was filed to end, and the exact question [#2806] is still open on. A rollup that is right 90% of the time and whose 10% error systematically indicts the target is a poor instrument for the target-versus-store question — which is the only question anyone has actually asked of this split.

   5. What the phases actually are — first fleet aggregate

   	total	probe	target	write	other
   plan_fetch	18,266,444 ms	55.4%	41.1%	3.5%	0.1%
   text_fetch	13,859,273 ms	80.6%	18.2%	1.1%	0.1%

   Two things worth putting on the record:

   • write: is 3.5% / 1.1%. The illustrative line in [query_store: plan_fetch and text_fetch are whole methods spanning two databases, timed as one number #2811]/[Split the query_store fetch phases into store, target and residual halves #2812] (write:188000ms inside a 189,562 ms parent) is not the production shape. The store probe is the largest single term and the target is second.
   • Derived rates: probe 0.608 ms per probed reference (plan) and 0.684 (text) — which independently reproduces the ~0.61 ms/reference already documented on PerItemPlanProbeIds, so the parse is calibrated against a known value. target 31.65 ms per attempted id (plan, 236,947 ids) and 11.93 (text, 211,764 ids).

   That last figure bears directly on [#2806]. Its controlled A/B measured ~650 ms for 400 ids ≈ 1.6 ms/id on hot, recently-executed plans. Production, on the cold plans the collector actually fetches, is 31.65 ms/id — about 20×. So the target half is neither a rounding error (41.1% of plan_fetch; 7,500,016 ms in 38 h) nor the whole story. [#2806]'s "measure target: on cold plans, then decide" now has its number, from log lines that already existed rather than a new experiment.

   6. Does the [#2472] / V80 reasoning transfer? The cost estimate does not.

   V80 declined collector_item_timings because it would keep the distribution "at ~10% of collection_log's row volume forever". Re-derived for this case, the number is very different, because the fetch split only fires when a fetch actually runs — 22.2% of query_store runs — and only for ~2.7 databases inside those:

   shape	rows/day/server	as % of collection_log
   one row per (run, database), both splits on it	167	1.4%
   plan and text as separate rows	334	2.8%
   V80's declined estimate, for comparison	~3,200	(~10% of the volume it measured then)

   Denominator: ~11,955 collection_log rows/day/server, derived from get_collector_cost run counts over 2 days ÷ 42 members. Two caveats against over-reading the percentages: collection_log's own volume has fallen a long way since [#2472] measured ~31,200 rows/day/server, so the ratio flatters this case twice over — the absolute 167–334 is the honest figure, 10–19× fewer rows than the shape V80 priced. And it scales with databases-per-member, not with fleet collector count.

   Has V80's rollup proved sufficient in practice? Untested rather than demonstrated. It is surfaced only on get_collection_health, as a fanout block on the latest run per collector — not on get_collection_log, and not aggregated over a window. Nothing since V80 has asked it for more, but nothing has asked it a trend question either. Its numbers do corroborate this measurement independently: a spot read on one multi-tenant member shows query_store items: 3, dominance: 2.05, i.e. the slowest item at 68% of the run — the same "spread, not dominated" shape.

   7. Recommendation — a fourth option: persist the sums, as columns

   Not the slowest database's split, and not the distribution.

   plan_fetch_probe_ms, plan_fetch_target_ms, plan_fetch_write_ms and their three text twins, each the sum across the fan-out, NULL when no fetch ran.

   Why this and not the three on the table:

   1. It answers the question exactly rather than at 90% with a biased 10%. The sums are the ground truth §3 measured against. There is no proxy and therefore no §4 bias toward indicting the target.
   2. The N:1 problem dissolves, because the two questions are already separated across two mechanisms. Which database is answered today by V80's slowest_item / dominance — 1:1, persisted, surfaced — and the fetch is the dominant term inside a query_store item, so V80 already fingers the right database. Which phase is what the fetch split is for, and a sum answers it. The issue's own framing lists "the sum" as one of the three things to decide among, but then never gives it an option; that is the gap.
   3. Sums compose against this row by construction. sqlMs += driverResult.SqlMs already makes sql_duration_ms the cross-item total, so these are strict sub-terms of a column that is already a sum. Nothing new has to be decided about cardinality.
   4. Zero new rows, ~98% NULL on a server_id-segmented compressed hypertable — V80 / V108 / V109's own trade, and the read pattern is already cut: CollectionLogSql on dev appends V108/V109 the same way.
   5. Keep [Persist the server-scoped phase split to collection_log so it can be aggregated without an SSM session #2859]'s rule: do not store other:. It is a residual; readers subtract. Same for the chunk/id/probed counters — they are a different unit (a count, not a duration) and per-id cost is derivable only if you also want the counts persisted; I would leave them out of the first rung and add them if a question actually needs them, rather than shipping 13 columns.

   What it cannot answer, plainly: whether one database inside a run is pathological while its siblings are fine. §3 sizes that blind spot at 10.5% of multi-database runs (where the slowest database's phase mix differs from the run's). If that becomes the live question, the increment is three more columns for the slowest database's mix — an addition on top, not a different shape.

   8. Does it generalise to [#2855]'s Azure split? No — and it should not be forced to. Tested, not assumed.

   Three findings, and they cut against reusing any single shape:

   • The row-volume profile is opposite. [Fixes #2855 #2893] states explicitly that its line is not gated on batch.Count > 0 — "the connect is paid on a quiet database exactly as on a busy one". So its emissions are one per database per cycle, ungated. That is precisely the ~one-row-per-item-per-cycle shape V80 priced at ~10% and declined. The fetch split's cheapness (§6) comes entirely from its gating and does not transfer.
   • The names collide. A persisted per-database open_ms / drain_ms would sit next to V108's sql_open_ms / sql_drain_ms, which mean the server-scoped open and drain. [Fixes #2855 #2893] already had to invent the PerDatabase* prefix to avoid exactly this collision in the log; persisting it re-opens the same hazard in a column list, where it is worse because the reader has no doc comment in front of them.
   • It is not yet a live question on this store. Every member here is RDS, so the Azure per-database branch is never taken. The branch is live for the per-database PostgreSQL collectors on the other host — which I did not measure, and until someone does, its persisted cost would be an unpriced guess.

   So the honest answer to "does jsonb win because it generalises?" is: jsonb is the only shape that generalises, and generalising is not obviously worth buying here. It would hold {probe, target, write} and {connect, open, drain} in one column with no naming collision and no second rung — but it costs the cheap aggregation that is the entire reason to persist any of this ([#2859] point 1), and it buys a distribution that §6/§7 show nothing currently needs. If the decision is that [#2855] and [#2860] must land as one thing, then option 3 is the right answer to that question — but it is a bigger question than this issue, and I would not let the tail wag it.

   9. If a schema change is taken

   It is a real rung, and the numbering has a live hazard: do not pre-reserve 110. dev is at 109; [#2731] (the force-plan bot write path) is still open carrying rung 107, which dev already used, so it must renumber at its own merge. Take max(dev) + 1 when this merges, not a number reserved now — a reserved gap that merges out of order is the failure mode the ladder-density pin exists for.

   The rung would involve: new Migration(N, …) + VNSql (nullable, no DEFAULT, no backfill — V80/V108's reasoning); StorageVersion.SchemaVersion; the CREATE OR REPLACE VIEW collect.v_collection_log re-issue (a view freezes its SELECT * list at create — V14's lesson, restated by V80 and V108); InsertCollectionLogSql + the writer's parameter block; CollectionLogSql + CollectionLogEntry so it is actually reachable; the three literal pin forms; and the viewer schema probe's newest-first arm. Lite writes collection_log too, and its INSERT names columns explicitly — so its writer needs checking rather than assuming, per V80's own note.

   10. One side finding, which wants its own issue

   While attributing the parsed lines: _planFetchCarryover and _textFetchCarryover are keyed (ServerId, Database), not (ServerId, Database, Collector) (DarlingCollectorRunner.cs:258-261, :2248, :2650), and the fetch statement is always QueryStoreCollector.Instance.BuildPlanFetchByIdsQuery (:2462) regardless of which enumerated collector is running. So query_store's deferred plan-fetch debt is paid by whichever CapturePlanXml collector next visits that database.

   The measurement shows it happening, and the signature is conclusive from the data alone — PerItemPlanProbeIds is set only when references.Count > 0, so probed = 0 with ids > 0 can only mean carried debt:

   collector	plan_fetch target: ms	ids attempted	probed
   plan_correction	302,076 (92.7% of its fetch)	7,041	0
   query_store_health	34,046 (94%)	1,299	0
   index_object_stats	9,817 (96.7%)	218	0

   That is ~346 s of Query Store plan-fetch time in 38 h billed to three collectors that never referenced a plan. It matters here because it is a third answer to "what to record": the collector that paid is not the collector that owed. Filing separately rather than half-answering it in this thread.

   11. What remains unmeasured

   • The store could not be queried directly. The read-only psql-on-the-box path was refused by my session's permission classifier partway through, as were later SSM sends. So the collection_log volume denominator is derived from get_collector_cost run counts rather than counted, and the hypertable's on-disk size is not priced. The distribution figures are unaffected — they were taken before the block.
   • text_fetch and plan_fetch were treated as independent in the row-volume table; whether they share a row is a design choice, not a measurement.
   • Only one host was measured. The per-database PostgreSQL path — [The Azure per-database branch emits no phase split at all #2855]'s other consumer — was not, so §8's third bullet is reasoning, not data.
   • 38 hours, one build generation. The phase mix moved sharply this week ([Bound the server-scoped watermark read on the partitioning column #2796], [query_store probe phase is connection acquisition, not SQL: probe query is 0.4-37ms, probe phase is 673-6663ms #2819], [Split-timing lines log target ids as the probe denominator, hiding probe cost's real driver #2823] all landed in it), so the 55/41/3 plan-fetch split is current-build behaviour and should be re-read after anything else touches the probe.

   What would flip the recommendation: a question that needs per-database phase granularity (then option 2 or 3), or a decision that [#2855] must be persisted in the same rung (then option 3). Absent either, sums-as-columns answers the only question this split has ever been asked, and answers it exactly.
3. erikdarlingdata commented on Sep 4, 2026

   

   erikdarlingdata

   on Sep 4, 2026

   OwnerAuthor

   More actions

   Pointer for §10 above, which said "filing separately" without a number: that is #2902 (filed independently on the same finding). The full mechanism, the file:line evidence, the read-side consequence and the three options are in #2902 (comment).

   It bears on the decision in this thread rather than just sitting beside it. The carryover is keyed (ServerId, Database) with no collector, so a fetch split persisted against the running collector records whoever PAID the debt, not whoever OWED it — and today ~346 s / 38 h of Query Store fetch time is paid by plan_correction, query_store_health and index_object_stats.

   Which way that cuts depends on which option #2902 takes:

   • Narrow the key, or gate the fetch on the running definition → paid == owed by construction, and §7's sums-as-columns recommendation here stands unchanged.
   • Keep the sharing and fix the accounting → these rows need the owing collector as well, and the rollup shape changes with it.

   So #2902 should land first, or at least be decided first. Persisting the split at option-1/3 semantics and then taking option 2 means a stored series that silently changes meaning mid-history, which is worse than either.
4. erikdarlingdata commented on Sep 4, 2026

   

   erikdarlingdata

   on Sep 4, 2026

   OwnerAuthor

   More actions

   Closing out the ordering caveat above: #2902 has landed (#2906, merged to dev as 679b7340), and it took the narrow-the-key option. So the PAID-vs-OWED question this thread inherited is settled in the simple direction — paid == owed by construction, and §7's recommendation to persist the sums as columns stands unchanged. Nothing here is blocked on it any more.

   Verified on dev: four fetch-state dictionaries now key (ServerId, Database, Collector) through one FetchStateKey builder (DarlingCollectorRunner.cs:247, :260, :263, :275, :304), while _consecutiveQueryStoreItemFailures correctly stays 2-tuple at :224 because its call sites are name-guarded.

   One thing #2906 hands to this issue rather than taking away: the carryover has no eviction — ids leave only by landing, by proving target-side-gone on an uncut pass, or with the process. Narrowing the key drops drain opportunities ~52%, which makes an existing capacity question visible rather than creating one. The ids attempted vs probe ids pair per query_store run is the only instrument that would see the backlog grow, and today it exists solely in the log line. That is an additional argument for persisting them here.
5. erikdarlingdata

   added 4 commits that reference this issue on Sep 4, 2026

   Split the V110 live test out and move the two pins it broke (#2860)

   ...

   1835bec

   Add the missing [#2849] CHANGELOG link reference

   ...

   a50276f

   Group get_collection_log's phase fields into nullable blocks (#2860)

   ...

   758ad8e

   Merge pull request #2914 from erikdarlingdata/feat/2860-persist-fetch…

   ...

   b1d8315
6. erikdarlingdata commented on Sep 4, 2026

   

   erikdarlingdata

   on Sep 4, 2026

   OwnerAuthor

   More actions

   Fixed by #2914, merged to dev as V110 collection-log-fetch-phase-sums.

   Ten nullable integer columns on collect.collection_log plus the v_collection_log refresh: plan_fetch_probe_ms / _target_ms / _write_ms / _ids_attempted / _probe_ids and the five text_fetch_* twins. Naming derived from V108 rather than invented — V108 wrote sql_open_ms / sql_drain_ms, i.e. parent's log-line term, then phase, then unit; counters drop _ms because they are counts, matching V109's drain_rows_read.

   The run-level sums answer the question the alternatives traded off

   Which database is already answered exactly by V80's fanout_item_count / slowest_item / slowest_item_ms; which phase is answered exactly by a sum. So the N:1 problem dissolves rather than being priced. Sums also compose against a row whose duration_ms and sql_duration_ms are already sums, and this adds zero rows — the split fires on only 22.2% of query_store runs, and these are columns on a row that already exists.

   Stated blind spot, and it is in the doc comment: the ~10.5% of multi-database runs where one database's phase mix differs from the run's aggregate. A slowest-database rollup would instead have carried a ~6.5 : 1 bias toward indicting the target when the cost was actually the store probe, which is the specific misreading this instrumentation family exists to end.

   §7's recommendation is reversed, and here is the justification

   This issue's §7 argued for leaving the id/probe counters out. Its own stated condition was "add them if a question actually needs them" — and #2902 supplied one, twice: the fetch carryover has no eviction (no count cap, no byte cap, no age-out), narrowing its key dropped drain opportunities ~52%, and ids attempted vs probe ids per run is the only instrument that would see a backlog growing silently. They also turn durations into rates: target ÷ ids_attempted gives the 31.65 ms/id cold vs ~1.6 ms/id hot figure that reframed #2806, and probe ÷ probe_ids reproduces the ~0.61 ms/reference already documented in source. chunks was left out as a batching artifact. Ten columns, not the thirteen §7 feared.

   The read side was already broken — for two rungs

   Following V108/V109's route revealed that V108 and V109 both stopped halfway: their eight columns are selected into the record and then dropped by get_collection_log's JSON projection. Nothing downstream could ever see them. All eighteen are now emitted and the family is pinned, so a future rung cannot repeat it.

   Emitting them flat cost too much, and that was measured rather than assumed: a 200-row response went 41,221 → 138,481 characters (3.36×), roughly 97 KB of it literal null. They are therefore grouped into four nullable blocks — sql_phases, drain, plan_fetch, text_fetch — bringing the same window to 59,644 against 136,764, 56% removed. The nesting is the mutual exclusivity that was previously only a comment. sweep_peer_max_ms stays flat deliberately, because V109 needs it on every row as a denominator.

   Migration verified on three populations, not two

   path	result
   fresh create (empty → applier)	stamped 110, 301 ms
   upgrade 109 → 110, against real pre-rung code	34 ms
   upgrade 79 → 110, 31 rungs behind	81 ms

   All three land byte-identical schemas — 2,387 columns across collect + config, diff clean. Idempotent: applied a second and third time on each with no error, MAX(version) unchanged, exactly one ladder row for 110. collection_log was a compression-enabled hypertable in the fixture, so the catalog-only claim was tested against the real shape. A full round trip through the shipped code — accumulator → LogCollectionAsync → LogRetentionRunAsync → GetCollectionLogAsync → JSON — passes 35/35 on all three stores, with row counts asserted rather than call returns, because both writers swallow exceptions and a bind mismatch would otherwise fail silently.

   The CREATE TABLE path is deliberately untouched, and that is a finding rather than an omission. V2 has never been widened; V80, V108 and V109 all arrive only via their own rungs, and editing V2 would be actively wrong — a store already stamped at 2 skips it forever. Pinned, with a positive control so the DoesNotContain sweep cannot pass by matching nothing.

   Decimal precision: not applicable, reasoned rather than skipped. Whole milliseconds and whole counts, matching sql_duration_ms. Rates are divided by the reader in floating point; baking a scale in would fix it for every future consumer.

   No Lite twin, correctly — Lite never sets CapturePlanXml or FetchQueryTextSeparately, so neither fetch ever runs there.

   Pinned red-first, fourteen ways

   Fourteen mutations, fourteen distinct assertions, including several that a coarser pin would have missed: the view refresh forgotten (fails on v_collection_log specifically, with the columns present on the table), a member dropped from the TEXT block only (a whole-file Contains would have passed), the accumulator's += turned to =, the failure arm attributing a value, and sweep_peer_max_ms no longer flat.

   Most instructive near-miss: #2864's peer-mark pin has a negative half that was anchored on result.Drain. Inserting these columns would have made that anchor un-matchable — silently passing while guarding nothing. It has been re-anchored on what the defect actually looks like, so a future insertion cannot silence it. Related trap in the new pin's own first draft: a DoesNotContain("batchCount > 0") failed against its own explanatory comment, fixed by pinning if (batchCount > 0) — prose versus code.

   Not verified

   No live fleet run — every figure here is a parse of log lines that already existed, and no row with these columns populated has yet been written by the service. The 79→110 upgrade is genuinely old but carries no data, so a large existing store is untested. The local rig ran PG 17.11 / TimescaleDB 2.29.2 against CI's PG 18.4 / TimescaleDB 2.28.1. Windows suites ran in CI only.

   Not generalised to #2855

   Deliberately. #2893's per-database line is not gated on batch.Count > 0, so its emissions are one per database per cycle — the ungated row shape V80 declined — and persisted open_ms / drain_ms there would collide with V108's server-scoped sql_open_ms / sql_drain_ms. jsonb remains the only shape that would generalise, and that is a separate decision nobody has asked for.
7. erikdarlingdata

   closed this as completedon Sep 4, 2026
8. pull

   added 4 commits that reference this issue on Sep 10, 2026

   Split the Azure per-database branch into connect/open/drain (Fixes er…

   ...

   a0cd424

   Key the plan and text fetch carryover by collector, not database alone (

   ...

   6c9eb97

   Persist the per-database fetch phase split as sums on collection_log (e…

   ...

   0ccabb8

   Remove three duplicate CHANGELOG issue link-reference definitions

   ...

   65e6a90