procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence

Summary

procedure_stats is the most expensive collector on the production use1 store, and essentially all of its cost is rendering and shipping execution-plan XML that the store already holds. The render half of that cost is CPU burned on the monitored production SQL Server, not on the collector box.

This proposes capturing plan XML on one cycle in N instead of on every cycle, behind a store-backed knob.

The cost


daily total (use1)	98.1M ms/day over 17,869 runs
avg / max	5,490 ms / 137,455 ms
vs `query_store`	1.57x — it recently overtook it
phase split	`sql:4,902ms = open:149ms + drain:4,724ms + other:1ms`

So 96% is the read loop.

Where the drain goes

A controlled decomposition — 6 heaviest servers, 3 reps x 3 variants, serial and 6-way concurrent, 108 executions, 150 rows every time:

variant	what it does	share of drain
A: no `OUTER APPLY`	no plans at all	0.2%
B: `OUTER APPLY`, select `DATALENGTH(plan)`	renders, ships a bigint	73.8% (render)
C: current — select the plan	renders and ships	+26.0% (transfer)

Stable at 73.6/25.5 under concurrency, so not a client-contention artifact. Variant A costing 0.2% means the non-plan columns are free and essentially the entire drain is plan cost.

The render was genuinely measured, not optimised away: B's SUM(DATALENGTH(tqp.query_plan)) matched C's independently counted transferred bytes to two decimals on every server (46.35/46.35, 57.73/57.73, ...), so the TVF materialised every plan while shipping only bigints.

Plan sizes (n=831): mean 373 KB, p50 103 KB, p95 1,206 KB, max 8.5 MB. The module DMVs expose no statement offsets, so the collector passes literal 0, -1 and gets the entire module's plan.

Why cadence and not a dedup key

sys.dm_exec_text_query_plan is a server-side TVF, so the 73.8% render is target-side CPU — get_collector_cost.sql_ms is target-side duration. Hashing at the source (HASHBYTES over the plan, fetch only unknown hashes) would remove the 26% transfer and leave the 74% render burning on customer hardware. Skipping the cycle removes both.

A plan_handle-keyed probe is disproven, not merely untried. Over 42 servers and 2.58M rows in 24h:

16,745 distinct (server_id, plan_handle) -> 142,955 distinct (server_id, plan_handle, digest)
8.5 distinct plan XMLs per handle per day; 30.8% of handles produced more than one; the worst produced 457 distinct plans in 468 sightings
adding cached_time to the key changes the count by exactly zero

The module recompiles statements in place as temp-table statistics change (a diff of two XMLs behind one handle showed different StatisticsInfo on different temp tables and EstimateRows moving), so the handle is stable by design while the XML is not.

The #1767 plan dimension already covers procedure_stats (PayloadDimensions.All carries it), but that is storage-side dedup and structurally cannot touch a wire or render cost — 94.5% of the bytes are already redundant (2,575,654 rows carry 142,329 distinct digests) and it changes nothing about what crosses the wire.

It is not only cost

On alpha-01 in one recent hour, procedure_stats and query_stats each hit the 120s PerItemWallClockBudget and recorded ABANDONED with rows_collected = 0 — cycles that stored nothing and advanced no watermark. Peak is what produces those, which is also why the fix has to stagger the fleet rather than putting every server on the same capture cycle.

Proposal

A config_service knob, procedure_stats_plan_cycle_interval, default 4, clamped [1,60], read live.

1 = capture every cycle, byte-identical to today, so the knob is fully reversible.
The phase is derived from server_id, so the fleet spreads across the interval instead of spiking together.
Only procedure_stats is gated. query_stats, query_store, deadlocks and blocked_process_report also capture plans and are deliberately left alone — this is a targeted response to one measured cost, not a fleet-wide policy change.

Predicted at N=4: avg 5,490 -> ~1,490 ms, daily 98.1M -> ~26.7M ms, and 75% less plan-render CPU on every monitored server. Cost is plan-history granularity: ~3.4 min -> ~13.6 min per server.

Every reader already skips NULL-plan rows and returns the latest row that has a plan (the #1767 guard, AND (COALESCE(ps.query_plan_xml, qpd.query_plan_xml) IS NOT NULL OR qpd.query_plan_gz IS NOT NULL) ORDER BY ps.collection_time DESC LIMIT 1), so a skipped cycle is invisible to consumers rather than rendering as a missing plan. The write path likewise stores NULL rather than an empty string (PgCollectorRowWriter.Value: "A NULL payload stays NULL — there is nothing to dedupe and no dim row to point at").

Capture procedure_stats plan XML on a cadence (Fixes #2862)

Parked — deliberately, with the work substantially complete

Not merging. The measurements above stand, but they justify the wrong fix: everything here reduces the MEDIAN, and the cost that actually loses data is the 120 s wall-clock abandonment.

The tail is a cliff, not a gradient. On one server over 1h44m, procedure_stats ran p50 6,056 / p90 8,009 / p95 9,551 ms and then jumped straight to 120,122 ms with nothing in between. A cadence that takes the median from ~6 s to ~1.5 s does not move a 120 s wall at all.

And it is not collector-specific. query_stats, procedure_stats and query_store each hit >=120 s inside the same few minutes, back to back, while the target sat at ~31% CPU with zero blocking recorded. Three independent collectors stalling together on an idle target is not a per-collector payload problem — which is exactly the premise the render/transfer decomposition rests on. Whatever produces the cliff is upstream of any single collector, and finding it is the thing worth doing.

What is worth keeping from this

A cheaper median is still worth having later, so the branch feature/procstats-plan-cadence (c6e894c8) is left in place — closed as #2863, green on all six checks. Two properties are recorded because they were not obvious and cost real work to establish:

N=1 is byte-identical to the current collector. CollectorContext.CapturePlanXml already erases the plan fragments to a no-plan query (the path Lite runs in production), so the knob is fully reversible with no residual difference.
The fleet stagger must derive from server_id. A bare ordinal % interval puts all 42 servers on the same capture cycle: three cheap cycles, then the whole fleet paying full plan-render cost at once. That is a 4x spike, and since peak is what produces these abandonments, the naive form would be worse than collecting every time. Pinned with its counterfactual red: [10, 10, 11, 11] shipped vs [42, 0, 0, 0] without the offset.

Also still true and independently useful: the render is 73.8% of the drain and happens inside a server-side TVF, so it is CPU on the monitored production server — any future fix that only removes the transfer leaves three quarters of the cost on customer hardware.

This issue holds two separable findings, and only one of them is what got it parked

Raising this because #2847 closed by pointing here, and the reason this issue was parked does not reach the half that #2847 needs.

Finding 1 — the median, and it is fully explained and actionable. #2847's 9.2× cross-fleet gap in procedure_stats resolves entirely to the plan render measured here. The isolated-query benchmark that appeared to contradict it had blanked the plan placeholders, so it measured this issue's variant A. The arithmetic closes: 247 ms without plans + ~4,400 ms render and transfer ≈ the 4,644 ms observed p50. Because us-east-1 sits pegged at the TOP (150) cap, it renders 150 whole-module plans (0, -1 grain) every run, every minute, every server. This is also the largest single term in #2841's cadence floor — procedure_stats is 69% of that fleet's 1-minute body. Cadence-gating the plan capture reduces this proportionally, which is exactly what a per-run render cost responds to.

Finding 2 — the tail, which is why this was parked. The 120 s stall investigated here is not capacity-shaped, and reducing plan-capture cadence does not address it. That conclusion stands and nothing below disputes it.

The two were parked together. Finding 1 does not depend on Finding 2 being solved, and it now blocks two other issues: #2847 closed against it, and #2841's floor is dominated by it. Worth deciding whether the median half can proceed on its own rather than waiting on the tail.

Corroboration from the fleet, independent of this issue's own A/B/C runs: get_collector_cost gives us-east-1 avg 5,389 → 3,582 ms against us-east-2's 567 → 407 ms (9.5×, 8.8×), and us-east-1 max of 128–137 s — over the 120 s PerItemWallClockBudget — against us-east-2's 5–10 s. A fixed per-row client cost would not produce that tail asymmetry; a payload-driven render would.

One caveat on any cadence change, from #2847's own constraints: procedure_stats cannot simply move off the 1-minute tier. PR #2843 pinned that no detached collector sits there, because a detached run skips when its predecessor is still in flight — so detaching a 1-minute collector converts starvation into guaranteed misses. And changing the default frequency is a CollectorScheduleDefaults change, duplicated into Lite's ScheduleManager.s_presets, needing the parity treatment — and Lite.Tests does not run in PR CI, only in the nightly.

Add the missing [#2849] CHANGELOG link reference

Merge pull request #2915 from erikdarlingdata/fix/2862-plan-capture-c…

The median fix landed (PR #2915). The tail finding stays open, and the approved cadence target is not reached by code alone.

procedure_stats now renders plan XML on one cycle in four instead of every cycle. The collector stays on its 1-minute schedule — only the render is gated — which avoids both traps: #2843's pin against detached collectors on the 1-minute tier, and the CollectorScheduleDefaults / Lite s_presets parity treatment that a frequency change would need.

N = 4, and the ceiling is not a taste judgement

Two bounds, and the hard one is external:

Diminishing return. The saving is (N-1)/N, so N=4 captures 75% of what is achievable: 1→4 buys ~31 s of cadence, 4→8 buys only ~5 s more.
A hard ceiling from the collector's own filter. The query bounds candidates with last_execution_time >= DATEADD(MINUTE, -10, …), so N × cadence must stay inside 600 s or a module can enter and leave the candidate set between two captures and never be seen. Computed against the modelled cadence: N=4 → 329 s ✓, N=6 → 473 s ✓, N=8 → 617 s ✗. N is capped near 7 by construction; 4 leaves margin.

Gating state is in-memory, and a restart is harmless — the phase is serverId % interval, not accumulated drift, so a fleet-wide restart re-enters at ordinal 0 and still spreads the fleet [10, 10, 11, 11]. collect.collector_state was considered and rejected: it buys nothing the server-derived phase doesn't and costs a store write per server per cycle on the hot path. No schema change, no migration — the knob is file-only (procedureStatsPlanCycleInterval, clamped [1,60], default 4), following the existing collectSchemaChangeEvents precedent. The trade is that changing it needs a restart rather than taking effect live; the seam is live-ready if that becomes worth promoting.

The gated path omits the apply entirely rather than rendering and discarding — verified by printing both built queries: the gated form has 0 dm_exec_text_query_plan, 0 OUTER APPLY and 0 query_plan, while keeping all four CROSS APPLY and both TOP (150).

The approved headline was not reachable, and here is the corrected arithmetic

The approval assumed procedure_stats was ~50% of the gate-held body. Measured: 44.7% — 4,282 ms of 9,578 ms per sweep, with a variant-A floor of 364 ms it cannot go below. So the achievable reduction is ~41% of R, not 50%:

	C=4	C=5	C=6
N=4 (this PR)	~82 s	~67 s	~57 s ✅
N=∞ (the floor)	~72 s	~59 s	~51 s

So the code fix alone lands ~82 s, not the ~58 s expected, and #2849's pre-approved C=5 fallback lands ~67 s — still over target. Clearing 60 s needs C=6, at ~1.40× collector work against the ~1.87× that C=8-alone would have cost.

What survives, and it is the part worth having: this buys ~30 s of cadence at 0.97× work — N·R/cadence moves 3.735 → 3.635, flat to marginally down. That is derivable rather than hoped for, and it is why "no CPU cost" holds. It also makes the remaining gap materially cheaper to close. max_concurrent_sweeps is unchanged at 4 and is not this PR's to move.

Deliberately not closed

This issue stays open for its tail finding — the 120 s stall that is not capacity-shaped. Nothing here addresses it and the parking on that half stands.
Fast collector tier floors at ~1.5 min even with no slow collectors (survives the #2840 sweep split) #2841 stays open, and it deserves a more precise epitaph than "wrong". Its fixed ~55 s component does not exist — refuted by measurement, not only by the curve-fit argument: us-east-2 moved from its own 919–1,003 runs/server/day to 1,152.7 today with no procedure_stats change, and a fixed term cannot shrink 15–25%. But it is right in spirit: there is a floor above 60 s at C=4, it is ~72 s, and it is multiplicative rather than fixed.
Collection cadence has no fixed component: cadence = N x gate_held_time / max_concurrent_sweeps + tick/2 #2849 stays open and must not be closed as not-needed. The C-bump is still required, at a different value than was pre-approved.

Not measured

The resulting cadence needs a deploy. Every post-change figure above is a model calibrated to one observed point (32,093 sweeps / 24 h → 113.1 s; per-sweep body 9,578 ms, independently matching #2849's 9.77 s), and is not presented as an observation. Collector-host CPU is a queueing derivation, not a measurement — the monitoring surface here watches SQL Servers, not the monitor box. The variant split this rests on is #2862's own, relied upon rather than re-run, so the 3.23% floor inherits its error. No credit was taken for reduced store time, which makes the projection conservative.

One pre-existing asymmetry found next door, not addressed

ViewerDataService.ProcedureStats.cs's bool_or(...) AS has_query_plan is windowed while the plan fetch is not, so on a sub-5-minute manual slice the Download button can read false for a plan the fetch would find. The default window is 24 h, so it is bounded. Pre-existing, and out of scope here.

Closing. The median finding is fixed and shipped; the tail finding does not survive re-reading as a separate open item.

The median half landed as #2915. procedure_stats now renders plan XML on one cycle in four, staggered by serverId % interval so the fleet does not capture in lockstep. The collector stays on its 1-minute schedule — only the render is gated — which avoids both traps: #2843's pin against detached collectors on the 1-minute tier, and the CollectorScheduleDefaults / Lite s_presets parity treatment a frequency change would need. No schema, no migration; the knob is file-only, clamped [1,60], default 4.

N = 4's ceiling turned out to be architectural, not a taste call — worth recording so nobody later "just bumps the cadence": the collector filters candidates on last_execution_time >= DATEADD(MINUTE, -10, …), so N × cadence must stay inside 600 s or a module can enter and leave the candidate set between two captures and never be seen at all. N=4 → 329 s ✓, N=6 → 473 s ✓, N=8 → 617 s ✗. N is capped near 7 by construction.

Measured outcome: procedure_stats was 44.7% of the us-east-1 gate-held body (4,282 ms of 9,578 ms), not the ~50% assumed, with a variant-A floor of 364 ms. So it buys roughly 30 s of cadence at 0.97× collector work — flat to marginally down, which is why "no CPU cost" is derivable rather than hoped for. Modelled cadence 113.1 s → ~82 s at the current concurrency. Not a measurement: that needs a deploy.

On the tail. This issue also recorded procedure_stats and query_stats each hitting the 120 s PerItemWallClockBudget and recording ABANDONED with rows_collected = 0 — cycles that stored nothing and advanced no watermark. That was the half held back.

Re-reading it: this issue attributes those to peak, and says so explicitly — "Peak is what produces those, which is also why the fix has to stagger the fleet rather than putting every server on the same capture cycle." The shipped fix does exactly that staggering. So the tail is not an independent mechanism awaiting investigation; it is the same load story, and the mitigation this issue itself prescribed for it has landed.

(Recording a correction while closing: the tail was being described elsewhere — including by me — as "a 120 s stall that isn't capacity-shaped." That characterisation does not come from this issue, which says the opposite. It was repeated without being checked against the text.)

What would reopen this: ABANDONED zero-row cycles persisting after the gated capture is deployed and measured. That is the honest test, and it needs the deploy — the modelled figures above are calibrated to a single pre-change observation and are not evidence about the post-change fleet.

Navigation Menu

Repository navigation

procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence #2862

Summary

The cost

Where the drain goes

Why cadence and not a dedup key

It is not only cost

Proposal

Parked — deliberately, with the work substantially complete

What is worth keeping from this

This issue holds two separable findings, and only one of them is what got it parked

The median fix landed (PR #2915). The tail finding stays open, and the approved cadence target is not reached by code alone.

N = 4, and the ceiling is not a taste judgement

The approved headline was not reachable, and here is the corrected arithmetic

Deliberately not closed

Not measured

One pre-existing asymmetry found next door, not addressed

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence #2862

Description

Summary

The cost

Where the drain goes

Why cadence and not a dedup key

It is not only cost

Proposal

Activity

erikdarlingdata commented on Sep 3, 2026

Parked — deliberately, with the work substantially complete

What is worth keeping from this

erikdarlingdata commented on Sep 4, 2026

This issue holds two separable findings, and only one of them is what got it parked

erikdarlingdata commented on Sep 4, 2026

The median fix landed (PR #2915). The tail finding stays open, and the approved cadence target is not reached by code alone.

N = 4, and the ceiling is not a taste judgement

The approved headline was not reachable, and here is the corrected arithmetic

Deliberately not closed

Not measured

One pre-existing asymmetry found next door, not addressed

erikdarlingdata commented on Sep 4, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions