Skip to content

query_store's per-database fan-out costs ~10s per database serially, so a multi-tenant box cannot finish a 60s body #2468

Closed

Description

@erikdarlingdata

The end of the chain that started with six skipped relaunches on shard-A (#2446 → #2459 → #2460). The cause is now established rather than suspected, and this is the issue for the cause itself.

What the collector does

DarlingCollectorRunner returns immediately when the Query Store enumeration yields nothing — that is the 36 ms an empty run costs, measured on single-A across all 1,555 of its runs. Otherwise it runs the 55-column sys.query_store_runtime_stats payload once per database, on one connection, in sequence.

What that costs on a real server

Verified against the fleet:

shard-A    8 user databases
  db-1               630 GB        db-2              583 GB
  db-3             527 GB        db-4   426 GB
  db-5         246 GB        db-6 216 GB
  db-7             174 GB        db-8            21 GB

productive query_store run   ~80,900 ms   ÷ 8 ≈ 10.1 s per database
cadence                       5 minutes
collection body budget       60 seconds

So one productive cycle costs more than the whole body it runs in, and it is scheduled twelve times an hour. single-C works out to ~65,500 ms on the same arithmetic. single-A, whose enumeration yields nothing on every run, logged no skips at all — the discriminator is exactly this.

This is not a slow query. It is eight sequential ones with nothing wrong with any of them individually.

The lever that is visible from source

WatermarkPolicy.ClampCatchup allows a 24-hour catch-up per database. A database whose watermark has gone stale therefore reads up to a full day of runtime stats in a single cycle — which would make individual runs far heavier than steady state, and would show as p95 ≪ max on the columns #2466 just added. That is now a checkable question rather than a hypothesis, and it should be checked before anything is changed: if the ~10 s per database is steady-state cost, the answer is different from if it is catch-up cost.

Shapes worth weighing

Parallelise across databases. The obvious one, and the one to be most careful with — the collection body is what it is because it is serial, and the monitored server is a production instance that did not ask to be asked eight questions at once. Any concurrency here needs a bound and a justification, not just Task.WhenAll.

Give the collector its own cadence per database, or stagger them. Eight databases at 5 minutes does not have to mean eight databases every 5 minutes. Staggering keeps the per-cycle cost bounded without reducing coverage, at the price of a longer effective interval per database.

Let a heavy database opt out or slow down. There is already per-collector schedule override machinery; whether it can express per-database is worth checking before designing something new.

Do nothing, and let #2459's BODY_OVERRUN carry it. Defensible: the condition is now visible, named, and attributed to the right collector. The cost is that a server in this state collects at a multiple of its configured interval and the operator's only remedy is to lengthen the cadence by hand.

Why this matters beyond one server

Every multi-* box in this fleet is by definition many databases on one instance (see the naming convention), so this scales with exactly the servers that are already the largest. The blast radius is not one dogfood box.


Edited: server and database identifiers replaced with role placeholders. This is a public repository and the originals named tenants and customer databases; the measurements, ratios and reasoning are unchanged, because those are what the issue is about.

Activity

  1. erikdarlingdata commented on Aug 21, 2026

    @erikdarlingdata
    OwnerAuthor

    The check first, as asked — and it did not come back

    I could not run it, and I am not going to infer it. Two reasons, both worth recording:

    1. get_collection_health on the use2 monitor host does not serve the new columns. I called it against shard-A; the response carries avg_duration_ms and the sweep_pressure block but no p95_duration_ms / max_duration_ms. Ask each collector what a heavy run costs, not what its runs average (#2460) #2466 computes those on read from collection_log — no new column, no migration rung — so the store needs nothing; the build does. The box is on v3.5.0 (2026-08-19) and Ask each collector what a heavy run costs, not what its runs average (#2460) #2466 merged after it. So this is the older-build case you flagged, not a store problem, and one nightly on that box makes the tool answer.
    2. The store-SQL fallback is blocked in this session — the AWS SSO token is expired and aws sso login is not permitted here, so I have no route to psql on either monitor box.

    So: the exact queries are below. They want running on the use1 monitor host, not use2, for the reason in the next section.

    But the lever the issue names does not exist, and that changes the question

    WatermarkPolicy.ClampCatchup allows a 24-hour catch-up per database, so a stale watermark means one cycle reads up to a full day of runtime stats.

    WatermarkPolicy.MaxCatchup is TimeSpan.FromHours(1). It has been since #2102, which moved it for this exact cost mechanism:

    The horizon was 24h until the use1 migration wedge (#2102) proved a row cap is not a cost cap: the per-database query aggregates and sorts the WHOLE window before TOP or the byte budget can bound anything, so its cost grows with window width. A big database that missed one 60s cycle faced a wider window the next cycle, which cost more and timed out again — a self-sustaining spiral the 24h clamp sat far above and never interrupted.

    The 24-hour figure came from the comments, not the code: twelve comments across seven files still called it "the 24h catch-up clamp". The logs were always right (they interpolate MaxCatchup.TotalHours), so nothing misbehaved and no test went red — there was no instrument in the repo that could see it. #2471 fixes that, and pins the number to one home so a fresher figure cannot go stale the same way.

    Why it matters here: worst-case catch-up is a 60-minute window against a 5-minute steady-state window — 12×, not 288×. On shard-A's actual delivered cadence (~21.6 min between productive runs, derived below) it is under 3×. So catch-up cannot be most of 80,900 ms: even if every productive run were maximally clamped, the steady-state floor would still be ~27 s for one collector inside a 60 s body, and #2466 already puts the peak cycle at 234% of budget. The right fix does not hinge on this measurement the way the issue assumed it did. It is still worth taking, and it is still the thing that tells you which lever to pull.

    What the store does say about shard-A

    get_collection_health, 7-day window:

    query_store   total_runs 1183   errors 0   yields 0   avg_duration_ms 13508
                  note "enumeration yielded 0 items - nothing to collect this cycle"  (986 of 1183 runs)
    

    Backing out the 36 ms empty runs: (1183 × 13508 − 986 × 36) / 197 ≈ 80,936 ms — your figure, independently reproduced from the tool.

    But 986 of those 1183 runs collected nothing, and it is not a defect. get_query_store_health on the same server:

    9 databases, every one of them:
        actual_state    READ_ONLY        desired_state READ_WRITE
        readonly_reason 8  →  "database is a secondary replica"
        interval_length_minutes 60
    

    The enumeration's readonly_reason & 8 = 0 screen (#1558) is doing exactly what it was written to do. Post-#2296, the shard-* fleet is the readable-secondary side, so shard-A's query_store has enumerated zero items since the split and the 80,900 ms runs are the pre-split tail still inside the 7-day window.

    The run-rate split is the tell, and it is #2446 in one line:

    era wall clock productive runs delivered cadence
    pre-split (collecting) ~71 h 197 one per ~21.6 min
    post-split (0 items) ~97 h 986 one per ~5.9 min

    At 36 ms it holds its configured 5 minutes. At 80.9 s it delivers every ~22. That is the skipped relaunches, measured, not the cadence being configured wrong.

    So the live cost is on use1 now, where the primaries are — which is where the queries below want running, and it is also why I cannot check whether interval_length_minutes is 60 there too (no use1 MCP in this session).

    A fifth shape the issue does not list, and I think it is the one

    interval_length_minutes = 60 on every database on that box. Set that against what the payload actually filters on (QueryStoreCollector.BuildPayloadBody):

    FROM sys.query_store_runtime_stats AS qsrs
    WHERE qsrs.runtime_stats_interval_id IN
    (
        SELECT i.runtime_stats_interval_id
        FROM sys.query_store_runtime_stats_interval AS i
        WHERE i.end_time > @cutoff_time
    )
    GROUP BY qsrs.plan_id, qsrs.runtime_stats_interval_id, qsrs.execution_type_desc
    HAVING MAX(qsrs.last_execution_time) > @cutoff_time

    The scan set is whole intervals, not the watermark window. A 5-minute cutoff against 60-minute intervals selects the open interval — so every cycle re-scans and re-aggregates the same hour's accumulating rows, and HAVING narrows the output only after the aggregate has already been paid. Twelve cycles per interval, each paying for the whole interval so far.

    That is #2102's cost mechanism again, except the width is set by the source's interval length, not by the watermark gap. And it makes a falsifiable prediction the second query below tests directly: duration should saw-tooth with minute-of-hour — climbing through each interval, dropping at the boundary — and be largely indifferent to how long the preceding gap was.

    If that holds, the collector's 5-minute cadence is twelve times finer than the grain of the thing it reads, and it needs no new machinery to fix: config.config_collector_schedules already takes a per-server (server_id, 'query_store', frequency_minutes) row. "Lengthen the cadence by hand" stops being the operator's consolation prize and becomes matching the collector to its source.

    The codebase already says this out loud, in a comment about something else. DarlingCollectorRunner.cs:929 explains why quiet databases get no per-database log line:

    Quiet databases (0 rows — the 2-of-3 cycles between Query Store's 900s flushes) stay silent.

    Two of every three cycles find nothing new — and pay the interval aggregate to find that out. The two knobs compound rather than duplicate: the 900 s flush cadence decides when new rows can appear at all (so a 5-minute poll is 3× too fast), and the 60-minute interval length decides how much gets re-aggregated each time one does (so the cost per poll is set by the hour, not by the gap). That is the fifth shape written down as an aside, in a comment about logging.

    I have deliberately not shipped a default change (CollectorScheduleDefaults["query_store"] = new(5, 30)), because that is one line with fleet-wide effect on data resolution for every install, and it should follow the measurement rather than my inference.

    The gap that blocks three of the four shapes

    collection_log gets one row per collector run per server, never per database. DarlingObservability.LogCollectionAsync has no database parameter, and CollectorRunResult.SqlMs/StorageMs are sums across every database, so duration_ms for a query_store row is the whole fan-out blended. Per-database timing exists — onItemComplete receives itemSqlMs and itemStorageMs, and logs them with the phase breakdown — but only as service log lines. Nothing persists it.

    So no read, including #2466's new p95, can answer which database costs what. And that is not a nicety:

    • 8 × 10.1 s and 1 × 62 s + 7 × 2.7 s are the same 80.9 s and want completely different fixes. Parallelism at width 3 fixes the first and does almost nothing for the second.
    • Staggering has to know which database to defer.
    • A per-database schedule override is unusable without it — you would ship a knob and no way to know which database to turn it for.

    Filed separately as the prerequisite it is.

    Reading of the four shapes

    Parallelise — no, not on this evidence. The on-prem/RDS arm deliberately runs the whole fan-out on one target connection (DarlingCollectorRunner.cs:668), including the plan and text fetches, so bounded concurrency here means N connections to a production instance rather than a SemaphoreSlim over an existing one. It also reduces wall clock, not work — the monitored server still performs eight interval aggregates. If the fifth shape is right, that is spending concurrency on production to make largely redundant work finish faster. Revisit only if the measurement shows near-equal per-database costs and the cadence lever is already taken.

    Stagger — no, and this is the one I would have guessed wrong. The watermark is derived per (server_id, database_name) and clamped at one hour. Round-robin over N databases at a 5-minute cadence visits each every 5N minutes: N=8 → 40 min (inside the clamp), N=12 → 60 min, exactly at it, N>12 → the live path manufactures a clamp hole for the backfill worker on every cycle. And a wider per-database window costs more per #2102, so it moves cost rather than removing it. It fails hardest on the many-database boxes that motivate the issue.

    Per-database schedule override — not yet. The key shape does not exist: the unique indexes are (collector_name) WHERE server_id IS NULL and (server_id, collector_name). Adding a database column is a migration rung plus ResolveSchedule plus a control-plane surface — and it would ship without the attribution that makes it usable.

    Do nothing and let BODY_OVERRUN carry it — yes, for now, but not as the end state. It names the condition and attributes it to the right collector, which is more than existed a week ago.

    Recommendation

    1. Land Give the catch-up horizon one home, because the copies of it went stale (refs #2468) #2471 so nobody reasons from the 24-hour figure again.
    2. Run the queries below on use1 — they settle the p95-vs-max question and the interval-grain question in one pass.
    3. If the saw-tooth is there: take the cadence lever with the machinery that already exists, per-server on the multi-* boxes first, and only then decide whether a default change is warranted.
    4. Land the per-database attribution before designing any of the other three, because all three need it.

    The queries

    Read-only, against the Darling store on the use1 monitor host (10.x.x.x), using the DPAPI recipe.

    Q1 — is it steady state or catch-up, fleet-wide? p95 ≈ max says steady state; p95 ≪ max says a catch-up tail.

    SET default_transaction_read_only = on;
    SET statement_timeout = '120s';
    
    SELECT
        r.server_name,
        count(*)                                                                             AS runs,
        count(*) FILTER (WHERE r.productive)                                                 AS productive_runs,
        round(avg(r.duration_ms) FILTER (WHERE r.productive))::bigint                        AS avg_ms,
        percentile_disc(0.50) WITHIN GROUP (ORDER BY r.duration_ms) FILTER (WHERE r.productive) AS p50_ms,
        percentile_disc(0.95) WITHIN GROUP (ORDER BY r.duration_ms) FILTER (WHERE r.productive) AS p95_ms,
        max(r.duration_ms) FILTER (WHERE r.productive)                                       AS max_ms
    FROM
    (
        SELECT
            cl.server_name,
            cl.duration_ms,
            cl.status = 'SUCCESS'
            AND (cl.error_message IS NULL
                 OR cl.error_message NOT LIKE 'enumeration yielded 0 items%') AS productive
        FROM collect.v_collection_log AS cl
        WHERE cl.collector_name = 'query_store'
        AND   cl.collection_time >= (now() AT TIME ZONE 'UTC') - interval '7 days'
    ) AS r
    GROUP BY r.server_name
    HAVING count(*) FILTER (WHERE r.productive) >= 20
    ORDER BY p95_ms DESC NULLS LAST;

    Q2 — which mechanism, on the worst server Q1 names. gap_minutes vs duration_ms is the direct catch-up test (and note every gap past 60 gets the same window, so a flat tail above 60 is itself the answer). minute_of_hour is the interval-grain test: a saw-tooth climbing to :59 and dropping at :00 is the fifth shape.

    SET default_transaction_read_only = on;
    SET statement_timeout = '120s';
    
    SELECT
        cl.collection_time,
        extract(minute FROM cl.collection_time)::int                    AS minute_of_hour,
        cl.duration_ms,
        cl.sql_duration_ms,
        cl.rows_collected,
        round(extract(epoch FROM cl.collection_time
            - lag(cl.collection_time) OVER (ORDER BY cl.collection_time)) / 60.0, 1) AS gap_minutes
    FROM collect.v_collection_log AS cl
    WHERE cl.collector_name = 'query_store'
    AND   cl.server_name = '<paste the worst server_name from Q1>'
    AND   cl.collection_time >= (now() AT TIME ZONE 'UTC') - interval '3 days'
    AND   cl.status = 'SUCCESS'
    AND   (cl.error_message IS NULL
           OR cl.error_message NOT LIKE 'enumeration yielded 0 items%')
    ORDER BY cl.collection_time DESC
    LIMIT 400;

    Q3 — confirm the interval length on the use1 primaries, since I could only measure it on use2:

    SET default_transaction_read_only = on;
    
    SELECT
        qsh.server_name,
        qsh.interval_length_minutes,
        count(*) AS databases
    FROM collect.v_query_store_health AS qsh
    WHERE qsh.capture_time >= (now() AT TIME ZONE 'UTC') - interval '1 day'
    GROUP BY qsh.server_name, qsh.interval_length_minutes
    ORDER BY qsh.server_name;

    (Q3's relation name is the one place I am guessing — the query_store_health collector's read view. If it does not resolve, \dv collect.v_query_store* will name it.)

    Edited: server and database identifiers replaced with role placeholders — this is a public repository. Measurements and reasoning unchanged.

  2. erikdarlingdata commented on Aug 21, 2026

    @erikdarlingdata
    OwnerAuthor

    Addendum — the queries may not be necessary. The nightly at d2a457de (2026-08-21 18:44 UTC) is after #2466 merged (18:21), so the current nightly build already carries p95_duration_ms / max_duration_ms. Since #2466 computes them on read from collection_log — verified: DarlingDataReader.cs:1132-1133, and the migration ladder's top rung is still new Migration(79, "file-growth-alert", …) with StorageVersion.SchemaVersion = 79, exactly what both boxes already run — the store needs nothing and the history is already there. get_collection_health will answer Q1 for every server the moment the box is on that build.

    The box that wants it is prod-sql-use1-monitor-01, not use2: use2's query_store has enumerated zero items since the split, so its p95 would be computed over the pre-split tail and will age out of the 7-day window within days.

    That is a prod upgrade on a monitoring box, so it is your call and I have not touched it. Q2 (the gap_minutes / minute_of_hour correlation) still wants psql either way — it is the query that separates catch-up from interval grain, and no tool serves a per-run series.

  3. added a commit that references this issue on Aug 21, 2026
  4. erikdarlingdata commented on Aug 21, 2026

    @erikdarlingdata
    OwnerAuthor

    Closing as investigated, no fan-out change — and this issue's central lever does not exist.

    The correction

    I wrote that WatermarkPolicy.ClampCatchup allows a 24-hour catch-up per database. It allows one hour, and has since #2102 — for this exact cost mechanism. Verified: WatermarkPolicy.cs says "floors a stale watermark to now - 1h".

    The 24-hour figure lives in twelve comments across seven files that never moved when the constant did. The logs were always right because they interpolate the value, so nothing could see the drift — which is the same "a fact that must be remembered rather than derived" pattern this backlog has produced all day, in documentation rather than code. Worst-case catch-up is 12× a five-minute window, not 288×, and about 3× at shard-A's real delivered cadence. So catch-up cannot be most of 80,900 ms. #2471 gives the number one home and pins it.

    And the measurement I asked for could not be taken

    get_collection_health on the use2 box does not serve #2466's new columns — that box predates the build. The store-SQL fallback was blocked by an expired SSO session. The exact queries are recorded rather than the answer inferred, which is right.

    More importantly, the premise moved underneath the question: shard-A's query_store has enumerated zero items since the #2296 split — all nine databases are readonly_reason = 8 secondaries. So the ~80,900 ms runs are the pre-split tail, not current behaviour, and the live cost of this fan-out is on use1, which is where any measurement wants running. The caveat another agent flagged on #2446 — that the 7-day window straddles the split — turns out to be the case.

    Why none of the four shapes ships

    Stagger is actively wrong here. With a derived per-database watermark and a 1-hour clamp, N=12 databases round-robin hits the clamp exactly, and #2102 established that a wider window costs more — so it fails hardest on precisely the multi-tenant boxes that motivate this issue.

    Parallelism would need N connections to a production instance, not a semaphore over the existing single one, and it reduces wall-clock rather than work.

    Per-database overrides have no key shape, and are blocked by something more basic: collection_log writes one blended row per run, so nothing can currently say which database costs what. 8 × 10 s and 1 × 62 s + 7 × 2.7 s want opposite fixes and are indistinguishable today. That is #2472.

    Do nothing is where this lands, with the condition visible through #2459's BODY_OVERRUN and attributed to the right collector by #2466.

    A fifth shape the issue did not list

    interval_length_minutes = 60 on every database while the payload filters by runtime_stats_interval_id — so each five-minute cycle re-aggregates the same open hour. The codebase already says this in an aside ("the 2-of-3 cycles between Query Store's 900 s flushes"). It needs no new machinery: the existing per-server schedule override expresses it. Deliberately not shipped as a default change, because that is fleet-wide resolution and should follow the measurement rather than precede it.

    Edited: server and database identifiers replaced with role placeholders — this is a public repository. Measurements and reasoning unchanged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions