Repository navigation
query_stats renders and ships the same ~200 plans every minute: 47x more plan XML than is distinct, and the reason its slow runs are slow #5158
Description
Claude posting for Erik Darling.
query_stats renders and ships the same plans every minute: about 47 times more plan XML than there is distinct plan XML. On a large store that's 54 GB of plans rendered per hour on the monitored servers, 29 GB of it sent over the network, and it is what makes the slow query_stats runs slow.
Measured (one production store, 43 SQL Server targets, the last hour, read-only)
-
Fleet:
- plan XML rendered: 53.75 GB (sum of
query_plan_xml_bytes), from 479,000 rows; - shipped: 28.83 GB (the rows under the 512 KB cap);
- rendered on the server and then discarded: 22,752 rows over the cap;
- distinct plans, each counted once per server and plan hash: 1.14 GB.
- plan XML rendered: 53.75 GB (sum of
-
Per server: 1.4–1.8 GB of plans per hour each, from about 55 runs of 200 rows. Only 160–200 distinct plans per hour per server, so 40–59× redundancy.
-
The busiest-tail server:
- 11.9 MB shipped per run, against 2.4 plans per run not seen in the previous run;
- its slowest runs were 78–85 s, of which 72–78 s was
sql_drain_ms; - across the fleet, the slowest
query_statsruns this hour were 90–96% drain.
-
What the slow runs look like (measured earlier on another server whose
query_statsp95 rose from 2.8 to 11 s over four days):- the same 200 rows and about 14 MB of plans in slow and normal runs alike;
- the stream rate fell from about 18 MB/s to 0.17–0.30 MB/s in the slow runs.
So a run's time is roughly bytes ÷ the server's stream rate, and the bytes are almost all repeats.
Why
QueryStatsCollector splices PlanSelectFragment/PlanApplyFragment into the main query whenever CapturePlanXml is on (Darling). So every run calls sys.dm_exec_text_query_plan for each of its ~200 surviving rows, whether or not the store already holds that plan. #2862 put procedure_stats on a plan-capture cadence and deliberately left query_stats alone. #2164 gave query_store a skip for already-shipped plans. query_stats has neither.
Costs
- On the monitored server:
dm_exec_text_query_planrenders on the server's CPU, and the server streams the result. - On the server's other collectors: collectors on one server run in sequence, so a long
query_statsdrain holds that server's every-minute collectors (CPU, perfmon, waits). This hour the busiest-tail server had gaps of 160–246 s on them whilequery_statsran 80–90 s. - On the store: it receives and de-duplicates about 47× more than it keeps.
Fix
Fetch plan XML only for plans the store doesn't already hold, as query_store does (#2164):
- The main query returns the stats rows with each row's plan identity and no plan XML.
- A store probe finds which of them are already captured.
- A second target query renders only the missing ones.
Readers already handle rows whose plan is NULL and fall back to the latest row that has one (the #1767 guard that #2862 relies on).
- Expected payload: a few plans per run instead of ~200, with the drain falling to match.
- Already learned elsewhere: the probe must be cheap, because query_store probe: ~99% of probe: phase is client-side, not the database (measurement) #2831 found a
query_storeprobe phase that was ~99% client-side.
A cadence gate like #2862's is the smaller fallback. It cuts the volume by the interval, but still re-renders every plan on each captured cycle.
Acceptance
On the same store after the fix:
- plan XML rendered per hour falls to near the distinct-plan volume;
query_statsp95 and the slowest runs'sql_drain_msfall;- the every-minute collectors' gaps on the busiest-tail servers close.
Measure all three with the same read-only queries, same hour of day.
Activity
query_stats can fetch plan XML in a second target query for only the …
procedure_stats deferred fetch: drop KnownPlanBytes (the host sets Qu…
procedure_stats: the deferred plan fetch, collector half, inert (#5158)…
Resolve procedure_stats' plan fetch mode once per run and prune with …
Document procedureStatsDeferredPlanFetch as restart-only, the cap as …
Pin that shadow stores every procedure_stats column exactly as off do…
Keep the plan-fetch stamp seam between the two fetch methods the sour…
The store accepts a known plan digest for a row and keeps that plan a…
query_stats fetches plan XML only for plans this host hasn't stored, …
Diagnostics bundle: project procedureStatsDeferredPlanFetch into conf…
Live plan-fetch tests drop their scratch database when setup fails
procedure_stats: wire the deferred plan fetch, with a shadow mode tha…
Shadow plan reuse: one false-hit callback, one test helper, and the f…
Plan reuse shadow mode counts a false hit only when the plan's shape …
erikdarlingdata commentedon Oct 6, 2026
Claude posting for Erik Darling.
The query_stats half (#5173, #5174, #5209), measured on the largest production store after the nightly that first carries #5209: query_stats now reads 0.97 GB/h from its 43 targets, against 23.8 GB/h before. That's 96% less. Run time fell too: p95 2,096 → 596 ms, p50 925 → 254 ms. There are no new gaps.
How it was measured:
collection_log, forquery_statson 43 SQL Server targets.queryStatsDeferredPlanFetchis at its default (on).drain_bytes_read), GB/hplans_rendered_bytes), GB/hBy hour:
Not covered:
plans_rendered*note, so that row has no before value.erikdarlingdata commentedon Oct 7, 2026
Claude posting for Erik Darling.
24 h follow-up on the query_stats half (deferred plan fetch, build 515), one production store, 43 servers. Install windows and the cold hours are excluded.
The reduction held over the longer window. Rendered volume stayed under 1 GB/h in the 515 window, and p95 stayed near the 596 ms measured earlier. One hour after a restart, the 517 window shows 1.23 GB rendered and p95 824 ms. I believe that is a post-restart effect, but I have not measured it. The 27 gaps over 5 minutes in the 517 window fall in a window that contains one service restart (for the procedure_stats
onswitch below), which takes about two minutes to reach collection; that they are that restart is inferred, not yet checked per gap.The query_stats half is done. The procedure_stats half moved from shadow to
onon this store today, after its gate passed: over about 2 warm hours, 1,329 shadow runs on 43 servers, 0 shape false hits and 35 over-cap false hits. Its before and after comes after a day onon.erikdarlingdata commentedon Oct 8, 2026
Claude posting for Erik Darling.
The procedure_stats half, measured on the large SQL Server measurement store (43 servers), read-only. One side ran in
shadowand the other inon. Both windows cover the same hours of the day, 11 h 40 min each. Restarts are left out.shadow: 2026-10-06 13:20 to 2026-10-07 01:00 UTC, nightly 515.on: 2026-10-07 13:20 to 2026-10-08 01:00 UTC, nightly 517. The store switched toonat 12:38 UTC.shadowondrain_bytes_read), GB/hshadowwindow. Each read 44 to 46 MB in theonwindow. Their p95 went from 1.6 to 2.5 s down to 0.8 to 1.6 s.plans_rendered_bytestotals. Only 7,523 of the 30,093shadowruns wrote that note, so the two sides do not compare.shadowruns had no shape false hits.Limits:
onside is half a day.ProcedureStatsCollector, including theonpath. Nightly 517 does not have Procedure stats keep every procedure that did work, with plans for at most 150 (#5449) #5463, so these numbers do not cover it yet.shadowyet.The default stays
off. The query_stats half needs no setting and is done.procedure_stats fetches plans only for plans the host has not stored,…
erikdarlingdata commentedon Oct 9, 2026
Claude posting for Erik Darling.
The procedure_stats half, re-measured in
onwith #5463 and #5502 in the build: 0 failed runs and 0 gaps over 5 minutes, but bytes read from targets went up 5×. That's 0.772 GB/h, against 0.153 GB/h before #5463. Against the earliershadowwindow (8.29 GB/h) it is 91% down, not 98%. The store is the large SQL Server measurement store (43 servers), and the read was read-only.The two sides, both
onand both on the same hours of day (10 h 5 min each), with restarts left out:onondrain_bytes_read), GB/hThe 20:00 to 01:00 hours alone (5 h, 534 on the after side):
ononshadowwindow (8.29 GB/h) ran on nightly 515 without Procedure stats keep every procedure that did work, with plans for at most 150 (#5449) #5463. Noshadowwindow with Procedure stats keep every procedure that did work, with plans for at most 150 (#5449) #5463 exists, so 91% is against a baseline without Procedure stats keep every procedure that did work, with plans for at most 150 (#5449) #5463.runs_with_note= runs).erikdarlingdata commentedon Oct 9, 2026
Claude posting for Erik Darling.
Closing as completed, at Erik's call: 91% down against the
shadowbaseline is good enough for 3.10. The figures are in the comment above. We can revisit after the full release if the bytes need another look.Release 3.10.0 (#5645)