procedure_stats is 9.2x slower on use1 than use2 for identical row counts, and is 69% of use1's collection body

[erikdarlingdata]

procedure_stats takes 9.2x longer on use1 than use2 for identical row counts

Split out of #2841, where it turned out to be the dominant term. Measured from collect.collection_log on
both stores, window >= 2026-09-03 14:00 UTC — after the t3.xlarge -> m7i.2xlarge resize, so both boxes
are unthrottled 8 vCPU / 31 GB for the whole window. 42 servers each.

	use1	use2	ratio
duration_ms p50	4,900	535	9.2x
duration_ms p90	7,161	1,019	7.0x
sql_duration_ms p50	4,635	473	9.8x
duckdb_duration_ms p50	224	58	3.9x
median rows_collected	150	150	1.0x
n	2,481	4,200

It is not workload volume, and it is not a few bad targets

Same row count. Median rows_collected is 150 on both boxes, and the top-12 slowest use1 servers all
return exactly 150. So it is ~33 ms per row on use1 against ~3.5 ms on use2 for the same output.

Uniform across the fleet. Per-server p50 on use1: median 4,952 ms, p90 6,154 ms, worst
7,532 ms, across all 42 servers. No outliers carrying it — every server is slow.

Target-side. sql_duration_ms is 95% of duration_ms on use1 (4,635 of 4,900), so it is the query
against the monitored server, not the store write.

Why it matters beyond this collector

At p50 4,900 ms it is 69% of use1's entire 1-minute collection body (7,061 ms summed across the 19
collectors on that tier). Excluding it, use1's body is 2,161 ms against use2's 1,665 ms — 1.3x apart rather
than 3.2x. It is the single reason the two boxes' bodies differ, and therefore the largest lever on #2841's
cadence floor.

Candidate causes — none verified

The obvious environmental difference is that Query Store is live on use1's targets and dead on use2's
since the #2296 split (2026-08-17). Whether procedure_stats touches anything Query-Store-adjacent, or
whether use1's targets simply carry larger plan caches as a consequence, is unestablished. Other candidates:
per-row plan or text lookups that scale with cache size, or a genuine difference in the monitored workloads
that rows_collected does not capture.

The decisive diagnostic is the collector's actual execution plan captured on a use1 target and a use2
target with the same shipped query text — not a retyped copy. That splits "the query is doing more work
because the target has more to look at" from "the query has a plan problem on one fleet".

Constraint on the fix

Rescheduling it off the 1-minute tier is not freely available: PR #2843 (0ebbc7db) added a pin
asserting no detached collector sits on the 1-minute tier, because a detached run skips when its previous
run is still in flight — so detaching a 1-minute collector converts starvation into guaranteed misses.
Changing its default frequency instead is a CollectorScheduleDefaults change, which is duplicated into
Lite's ScheduleManager.s_presets and needs the parity treatment (and Lite.Tests does not run in PR CI).

Note on configuration

config.config_collector_schedules is empty on both stores — zero rows. Neither box has per-server
schedule overrides, so both run the shared CollectorScheduleDefaults cadences directly. Any comparison
between the two boxes is therefore comparing identical schedules, and any fix to the default frequency
lands on both.

[erikdarlingdata]

Not a defect in the query: 3.5x is fleet shape, and the rest is not target-side

Measured on the boxes, shipped query text extracted from ProcedureStatsCollector.StandardQueryText
(C# verbatim un-escaped, /*EXCLUSION_FILTER*/ and both plan placeholders erased — which is the
literal shipped string here, see below), run from each monitoring box against a real target with
System.Data.SqlClient, 6 reps, first discarded.

	use1 multi-01	use2 dummy	ratio
shipped query, isolated	247 ms (min 174, max 292)	70 ms (min 67, max 91)	3.5x
rows returned	150 (at the TOP cap)	42
collector sql_duration_ms p50	4,644 ms	485 ms	9.6x
isolated -> observed gap	18.8x	6.9x

The query is 3.5x apart, not 9.2x. And it earns that 3.5x against a candidate set that is
22.8x larger — measured on the targets themselves, rows with last_execution_time in the last
10 minutes, which is the denominator TOP (150) hides:

candidate source	use1	use2	ratio
sys.dm_exec_procedure_stats	815	35	23x
sys.dm_exec_trigger_stats	137	1	137x
sys.dm_exec_function_stats	51	8	6x
total candidates	1,003	44	22.8x
sys.dm_exec_cached_plans	38,002	18,477	2.1x

22.8x the input for 3.5x the time is sub-linear — the query handles the load well. use1's targets
are multi-tenant shards executing far more distinct modules per 10-minute window than use2's
single-tenant ones. That part is fleet shape, not a defect.

Two candidate optimizations, both disproved by measurement

Same target, 5 reps each, BINARY_CHECKSUM over the projected columns to compare rowsets:

A  proc branch, CROSS APPLY dm_exec_plan_attributes   med= 79 ms  rows=794  xor=-1368691569
B  proc branch, join on s.database_id                 med= 93 ms  rows=794  xor=-1368808758
C  trigger branch, with CROSS APPLY dm_exec_sql_text  med= 33 ms  rows=137  xor=-517272213
D  trigger branch, without the sql_text apply         med= 42 ms  rows=137  xor=-517272213

• B is slower than A and returns different data. Same row count, different checksum:
  dm_exec_plan_attributes' dbid and sys.dm_exec_procedure_stats.database_id disagree on at
  least one row. Swapping to the DMV column — which looks redundant, and which the Azure variant
  already uses — would have silently changed database attribution. Do not make this change.
• D is slower than C. Removing the dm_exec_sql_text apply from the trigger branch does not
  help either, despite it sitting inside the branch below the TOP (the shape query_stats and procedure_stats render plan XML BELOW the TOP: 2,434 TVF executions for 200 kept rows - validated 6x fix from field investigation #1959 fixed for the
  plan apply). Rowsets identical.
• OBJECT_SCHEMA_NAME/OBJECT_NAME cost 2 ms (37 -> 39 ms with vs without). Not the cause.

Two corrections to this issue

1. rows_collected is not 150 on both. Over 60 minutes, collection_log: use1 p50 150 with
   max 150 — it is pegged at the TOP (150) cap, so at least half its runs are truncated. use2 p50
   is 85, max 150. use1 n=1,217 runs, use2 n=2,128, 42 servers each.
2. CapturePlanXml is OFF on both boxes, so the dm_exec_text_query_plan apply is not even
   spliced. SELECT count(query_plan_xml) FROM collect.procedure_stats over the last 30 minutes
   returns 0 of 93,080 rows on use1 and 0 of 91,881 on use2. Plan rendering is not involved,
   and the duckdb_duration_ms difference noted in the issue is not plan payload.

The unexplained 18.8x is not target-side, and cannot currently be attributed

The isolated query is 247 ms; the collector records 4,644 ms for the same query against the same
target from the same box. Sampled during the measurement window the box was at 4% CPU, with the
collector still logging sql:4,024ms..sql:5,242ms on contemporaneous runs — so it is not CPU
contention on the monitoring box.

sql_duration_ms is composed of wm: (a store-side watermark read) + open: (target execute) +
drain:. procedure_stats emits no such split — DarlingCollectorRunner logs the breakdown
only when PerItemOpenMs > 0, which is the per-database enumerated path, so a server-scoped
collector logs the blended sql:Nms only. Zero procedure_stats lines in today's app log carry a
wm: split. The instrumentation that would attribute this does not exist for the collector that
needs it most. Filed separately.

This matches the shape found for TouchAndProbePlansAsync in #2831/#2819 — ~36 ms in a quiet
harness against ~1,451 ms in production, ~99% of it not in the database.

What this means for #2841

procedure_stats' query is 247 ms of its ~4,900 ms observed cost. Optimizing or rescheduling it
on the strength of query time cannot deliver the cadence #2841 is after — even eliminating the query
entirely would recover about 5% of the collector's measured duration. The lever is whatever accounts
for the other 95%, which is shared with the probe finding rather than specific to this collector.

Recommendation: close as fleet shape + a shared unattributed overhead, not a ProcedureStatsCollector
defect. No code change proposed; both candidate changes measured worse and one was unsafe.

[erikdarlingdata]

The 18.8x gap is plan XML, and the premise that ruled it out was a measurement artifact

The follow-up comment closed with "the unexplained 18.8x is not target-side, and cannot currently be
attributed", having ruled out plan rendering on the grounds that CapturePlanXml is OFF on both boxes.

Plan capture is ON, on both boxes. The probe that said otherwise cannot answer that question.

Why count(query_plan_xml) = 0 proves nothing

#1767 diverts this exact column into a hash-keyed dimension. PayloadDimensions.All carries

new PayloadDimension("procedure_stats", "query_plan_xml", QueryPlanDimTable, "query_plan_digest"),

and PgCollectorRowWriter swaps the COPY column list to dimension.DigestColumn at that payload
position. So every row written since #1767 puts the digest in query_plan_digest and the plan text in
query_plan_dim — leaving collect.procedure_stats.query_plan_xml NULL by construction, on every row,
whether or not plans are being captured. 0 of 93,080 is the designed outcome, not evidence.

The diversion list is a static readonly array with no config gate, so this is unconditional. #2862's own
reader guard corroborates it: COALESCE(ps.query_plan_xml, qpd.query_plan_xml) ... OR qpd.query_plan_gz IS NOT NULL exists precisely because new rows resolve through the dimension.

Verified live, just now, on both stores via analyze_procedure_plan (which reads stored
procedure_stats plans): both returned "source": "procedure_stats" with a full module-grain plan —
43 statements on a us-east-1 target, 26 on a us-east-2 one. Plans are being captured, stored and
served on both fleets today. capturePlans defaults to true (DarlingConfig.CapturePlans,
darling.sample.json) and neither box overrides it.

So the isolated 247 ms measured a different query

The isolation run erased both plan placeholders on the strength of the OFF premise. With plans on,
BuildQuery splices PlanApplyFragment:

OUTER APPLY sys.dm_exec_text_query_plan(CONVERT(varbinary(64), ranked.plan_handle, 1), 0, -1) AS tqp

0, -1 is whole-module grain. Since use1 is pegged at the TOP (150) cap, that is 150 module plans
rendered per run, per server, per minute. The isolated run rendered none. It measured #2862's variant A.

What sql_duration_ms spans (from the code)

For a server-scoped collector like this one, DarlingCollectorRunner's plain single-query path is:

var sqlSlice = Stopwatch.StartNew();
definition.BuildQuery(context);
openWatch:   await command.ExecuteReaderAsync(itemToken);     -> sql_open_ms
drainWatch:  await definition.ReadAsync(counting, ...);       -> sql_drain_ms
sqlMs += sqlSlice.ElapsedMilliseconds;

So it wraps query build + open + the whole ReadAsync drain + probe-failure and supplemental reads.
The watermark read sits outside it (V108 documents this deliberately). Per-row client work would indeed
land inside it by construction — so that part of the hypothesis is right about the accounting.

But the drain is not client-side, and that was already measured

Drain-dominant does not mean client-side. SQL Server streams, and an OUTER APPLY over a server-side
TVF is evaluated per surviving row as the client pulls, so target-side render lands in drain:, not
open:. #2862 measured the split and then decomposed it — 6 heaviest servers, 3 reps x 3 variants, serial
and 6-way concurrent, 108 executions, 150 rows every time:

sql:4,902ms = open:149ms + drain:4,724ms + other:1ms

A  no OUTER APPLY (no plans at all)            0.2% of drain
B  OUTER APPLY, select DATALENGTH(plan) only  73.8%  (render, ~no bytes shipped)
C  current - select the plan                 +26.0%  (transfer)

Variant B is decisive against the client-side reading: it renders every plan but ships only bigints,
and it costs 73.8% of the drain. There are no rows to consume slowly. #2862 confirms B's
SUM(DATALENGTH(...)) matched C's independently counted transferred bytes to two decimals per server, so
the TVF genuinely materialised each plan. Stable at 73.6/25.5 under 6-way concurrency — explicitly not a
client-contention artifact.

The gap closes arithmetically

Against #2862's split, the no-plan query is open 149 ms + 0.2% of a 4,724 ms drain ~= ~160 ms — the
same order as the isolated 247 ms (different server, window and reps). The plan fragment the isolated
run erased is the remaining ~4,400 ms:

247 ms (isolated, no plans) + ~4,400 ms (render + transfer) ~= 4,644 ms (observed p50)

The 18.8x is not unattributed overhead. It is the plan apply, it is target-side, and ~74% of it is CPU
burned on the monitored server rather than wire or client.

Why use1 and use2 differ for "identical row counts"

rows_collected is identical at the cap; the plan payload behind those rows is not. use1 is pegged at
150 every run (use2 p50 85), its modules are larger (43 statements vs 26 in the two plans sampled here),
and #2862 puts plan sizes at p50 103 KB / p95 1,206 KB / max 8.5 MB. get_collector_cost for
procedure_stats, last two full days:

	use1 avg	use2 avg	ratio	use1 max	use2 max
09-03	5,389 ms	567 ms	9.5x	137,455 ms	10,371 ms
09-04	3,582 ms	407 ms	8.8x	128,546 ms	5,099 ms

The p50 ratio reproduces the 9.2x. Note the tail: use1 exceeds the 120 s PerItemWallClockBudget
(128-137 s) while use2 tops out at 5-10 s. A fixed per-row client cost would not produce that asymmetry;
a payload-size-driven render does.

ASYNC_NETWORK_IO: no contrast between the fleets

4-hour window, one target each, from get_wait_stats:

	us-east-1 target	us-east-2 target
ASYNC_NETWORK_IO total	520,419 ms	384,891 ms
waiting tasks	811,347	459,919
avg per wait	0.64 ms	0.84 ms
rank	3rd	3rd

Rank 3 on both, and the per-wait average is higher on the fast fleet. The total tracks waiting-task
count, not a stall. SOS_SCHEDULER_YIELD is 3.5x higher on the us-east-2 target (2,589,938 vs
734,255 ms), so the slow fleet is not the busier one either.

Caveat, stated plainly: these are cumulative instance-wide aggregates over hundreds of thousands of
waiting tasks dominated by application traffic. They cannot attribute anything to the collector's
session in either direction. They are shown only to say that the fleet-level contrast the hypothesis
predicted is absent — not to prove the collector waits little.

Checked: the #2902 fetch-carryover mis-attribution does not contaminate these numbers

#2902 reports that the plan/text fetch carryover is keyed (ServerId, Database) with no collector in the
key, so budget-deferred fetch debt is billed to whichever CapturePlanXml collector next visits that
database. That would inflate per-collector collection_log figures in one direction, so it was worth
ruling out here rather than assuming.

It cannot reach procedure_stats on this fleet. FetchAndStorePlansAsync has exactly one call site,
inside the per-database enumerated path, and the carryover dictionaries are only read there
(carryKey = (server.ServerId, databaseName)). procedure_stats declares

public override bool RunsPerDatabase(CollectorTargetInfo target) => target.IsAzureSqlDb;

and these targets are RDS SQL Server 2022, not Azure SQL DB — so it takes the server-scoped branch,
which never calls the fetch, never consults the carryover, and has no PerItemPlanFetchMs /
PerItemTextFetchMs term in its sql_duration_ms at all. Consistent with #2902's own observation that the
receiving collectors are the per-database ones and procedure_stats is not among them.

Nothing above uses another collector's duration_ms or sql_duration_ms as a baseline either: every
comparison is procedure_stats against itself, across the two fleets or across #2862's A/B/C variants.

What this means

• procedure_stats is 9.2x slower on use1 than use2 for identical row counts, and is 69% of use1's collection body #2847 is answered, and the answer is procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence #2862. Nothing here is a ProcedureStatsCollector defect in
  the sense this issue was opened on; the query is fine and the client drain loop is 28 ordinal accessors
  with no allocation, no store touch and no per-row lookup. The cost is the plan apply, already filed,
  already measured.
• The earlier recommendation to close as "fleet shape + shared unattributed overhead" should not stand:
  the overhead is attributed, it is specific to this collector, and it is actionable.
• procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence #2862 was parked over its tail (the 120 s stall that is not capacity-shaped). That rationale does not
  reach this issue, which is about the median. The median is fully explained by the A/B/C decomposition,
  and cadence-gating does reduce it proportionally. The tail and the median are two findings in one issue.
• The sql_open_ms / sql_drain_ms / drain_rows_read columns (V108/V109) are the right instrument here,
  but the deployed MCP on the us-east-1 box does not return them — get_collection_log came back with
  only duration_ms / sql_duration_ms / store_duration_ms / rows_collected. The box is behind the
  build that exposes the split. Worth a nightly bump before the next pass, so this stops needing a log
  scrape.

No code change proposed. The fix is #2862's, and it is a scope decision rather than a defect fix.

[erikdarlingdata]

Closing: the 9.2× is explained, and the earlier "plan capture is OFF" premise was a measurement artifact

The mechanism is identified, so this closes as answered. The fix is tracked in #2862 — see the note I've left there, because that issue turns out to hold two separable findings and only one of them was parked.

The premise that had ruled plan XML out was false

An earlier comment concluded CapturePlanXml was OFF from count(query_plan_xml) = 0 over 93,080 rows. That column is structurally NULL on every row regardless of capture state, so the count could never have shown otherwise:

• PayloadDimensions.All carries an unconditional entry ("procedure_stats", "query_plan_xml", QueryPlanDimTable, "query_plan_digest") — a static readonly array with no config gate.
• PgCollectorRowWriter swaps the COPY column list to dimension.DigestColumn where a diversion exists, so the plan XML is written to the shared plan dimension and query_plan_digest carries the reference. The fact table's own query_plan_xml is never written.
• PayloadDimensions' own doc comment states the consequence directly: procedure_stats "has no query_text column at all — its entire payload share is plan XML."

Confirmed live rather than inferred: analyze_procedure_plan returns "source": "procedure_stats" with full module-grain plans on both stores — 43 statements on a us-east-1 target, 26 on us-east-2. Capture is on everywhere.

What the 9.2× actually is

The isolated benchmark erased the plan fragment. Reproducing the shipped query text required blanking /*EXCLUSION_FILTER*/ and both plan placeholders — so the 247 ms measurement is the query without plan rendering. The arithmetic closes:

247 ms   (query, plan fragment erased)
+ ~4,400 ms   (plan render + transfer)
≈ 4,644 ms   observed sql_duration_ms p50

#1959 moved the OUTER APPLY outside the ranked derived table so plans render once against at most 150 survivors. But us-east-1 sits pegged at that 150 cap, so it renders 150 whole-module plans (0, -1 grain) every run, every minute, every server. us-east-2 returns 42 rows and renders 42 smaller ones.

And it lands in drain: rather than open:, which is why it looked client-side. sql_duration_ms wraps the whole reader drain, not just ExecuteReader — but an OUTER APPLY over a server-side TVF is evaluated per surviving row as the client pulls, so target-side render time accrues during the drain. Drain-dominant does not imply client-side.

The client-side hypothesis is falsified

I had proposed the gap was slow client row consumption. It isn't:

• The drain loop is trivial. ProcedureStatsCollector.ReadAsync is while (await reader.ReadAsync()) building one record from 28 ordinal accessors — no string building, no dictionary lookups, no store touch, no plan handling, no sync-over-async.
• ASYNC_NETWORK_IO shows no fleet contrast. Rank 3 on both fleets, and the per-wait average is higher on the fast one (0.84 ms vs 0.64 ms). The larger total on the slow fleet tracks task count, not stalling — reading the total rather than the per-wait average is what made it look like a signal. SOS_SCHEDULER_YIELD is 3.5× higher on the fast fleet's target, so the slow fleet isn't simply busier either.
• procedure_stats spends 98.1M ms/day rendering plan XML on the monitored servers; capture it on a cadence #2862's variant B is decisive against any client-read explanation: it renders everything and ships almost no bytes, and still costs 73.8%. Transfer adds 26.0%. A client-consumption cost cannot produce that split.

Caveat kept: those wait figures are cumulative instance-wide aggregates over hundreds of thousands of tasks dominated by application traffic. They cannot attribute anything to the collector's session in either direction — they only show that the predicted contrast is absent.

Corrections to the record

• This issue's "identical row counts" framing is true but misleading. rows_collected is 150 on both fleets because both are reporting at the cap — but the plan payload behind those rows is not identical, and that is where the entire 9.2× lives. Identical row counts were treated as evidence the work was identical; they only show the output shape was.
• The earlier recommendation to close this as "fleet shape plus shared unattributed overhead" rested on the false OFF premise. The overhead is attributed, collector-specific and actionable — not shared and not unexplained.
• Plan/text fetch carryover is keyed by database, not collector, so one collector's deferred work is billed to another (~346s in 38h) #2902 was checked, not assumed, and cannot contaminate any figure here. ProcedureStatsCollector.RunsPerDatabase => target.IsAzureSqlDb is false on RDS SQL Server, so this collector takes the server-scoped branch and has no PerItemPlanFetchMs term at all; the carryover is only read from the per-database enumerated path's single call site. Every comparison used is procedure_stats against itself.

Not verified

The A/B/C decomposition and the plan-size distribution are #2862's measurements, relied on rather than re-run — that is the load-bearing external evidence here. Also: the deployed us-east-1 box is behind the V108/V109 build, so get_collection_log returns no sql_open_ms / sql_drain_ms / drain_rows_read; no fresh deployed phase split was obtainable, and a nightly bump would remove that limitation for the next pass.