The first retention drain after an upgrade makes collection fall behind on a large store

Claude posting for Erik Darling.

What happens

A store upgraded with a large retention backlog runs one long drain on its first retention pass (#5572). On a large store, that drain makes collection fall behind while it runs. These are field numbers from one such store, during the hour the drain ran:

The "Collection Falling Behind on Monitor Store" self-alert fired: 97 of 1,252 due collection slots were skipped (7.7%). The alert fires at 5%, with at least 20 slots.
"Collection body has not completed ... skipping relaunch" was logged for 9 servers, then for 5 more about half an hour later.
The Query Store collector's 95th percentile went from 13.1 s to 20.0 s. Its median did not change (about 360 ms).

The drain already paces its WAL (RetentionWalPacer, half of the store's checkpoint rate). That does not bound the reads and index work each batch does, and those compete with the collectors' writes.

Goal

The first drain after an upgrade never trips the self-alert and never skips a relaunch. The drain is allowed to take longer.

The fix

The drain gives way to collection:

Before each batch, it checks whether collection is keeping up, using the same skipped-slot count the self-alert reads. When collection is not keeping up, it waits until it is.
After each batch, it pauses for a time scaled to how long the batch took.
A pass that runs out of its time budget stops. The next pass picks up the rows that are left.

The PR body will carry a before number from the store above. It will also carry an after number from a store with a backlog and its collectors running.

Add the drain A/B load-replay tool (#5592)

Claude posting for Erik Darling.

How often a normal day meets the drain's wait rule

The fix in #5595 makes the retention drain wait before a batch while collection is behind. Collection counts as behind in two cases. A collector slot was skipped in the last 5 minutes, or a server's collection body has run for 30 s or more. If a normal day meets that rule most of the time, the drain crawls even with no backlog. This read measures that on a large store.

A body is one server's sweep of its due collectors. The script sums each server's collector run times per minute as a stand-in for the body time. If a sweep runs its collectors at the same time, the sum reads high, so the script also reports the longest single run.

Please report both result sets. Also report, from the service log for the same 3 days, the number of "skipping relaunch" warnings per day (there is one per episode). The script is read-only and rolled back, and it skips the hours of the first drain after the install.

-- #5592: how often a normal day already meets the drain's "collection is behind" rule. Read-only, rolled back.
-- The rule waits before a batch when a server's collection body has run for 30 s or more (or a slot was skipped
-- in the last 5 minutes). A body is one server's sweep of its due collectors, so the per-server, per-minute sum of
-- collector run times stands in for the body time. The window is the last 3 days, minus the post-install drain.
BEGIN READ ONLY;
SET LOCAL statement_timeout = '120s';
SET LOCAL lock_timeout = '2s';

WITH per_server_minute AS
(
    SELECT
        cl.server_id,
        date_trunc('minute', cl.collection_time) AS minute,
        SUM(cl.duration_ms) AS sum_ms,
        MAX(cl.duration_ms) AS max_ms
    FROM collect.collection_log AS cl
    WHERE cl.collection_time >= (now() AT TIME ZONE 'UTC') - interval '3 days'
    AND   NOT (cl.collection_time >= timestamp '2026-10-08 19:00:00' AND cl.collection_time < timestamp '2026-10-09 00:00:00')
    GROUP BY
        cl.server_id,
        date_trunc('minute', cl.collection_time)
),
fleet_minute AS
(
    SELECT
        psm.minute,
        MAX(psm.sum_ms) AS worst_sum_ms,
        MAX(psm.max_ms) AS worst_max_ms
    FROM per_server_minute AS psm
    GROUP BY
        psm.minute
),
fleet_window AS
(
    SELECT
        date_bin(interval '5 minutes', fm.minute, timestamp '2000-01-01') AS window_start,
        MAX(fm.worst_sum_ms) AS worst_sum_ms
    FROM fleet_minute AS fm
    GROUP BY
        date_bin(interval '5 minutes', fm.minute, timestamp '2000-01-01')
)
SELECT
    (SELECT count(*) FROM fleet_minute) AS minutes,
    (SELECT count(*) FROM fleet_minute AS fm WHERE fm.worst_sum_ms >= 30000) AS minutes_some_server_30s,
    (SELECT count(*) FROM fleet_minute AS fm WHERE fm.worst_max_ms >= 30000) AS minutes_some_collector_30s,
    (SELECT count(*) FROM fleet_window) AS windows_5min,
    (SELECT count(*) FROM fleet_window AS fw WHERE fw.worst_sum_ms >= 30000) AS windows_5min_some_server_30s,
    (
        SELECT percentile_cont(ARRAY[0.5, 0.9, 0.99, 0.999]::double precision[]) WITHIN GROUP (ORDER BY fm.worst_sum_ms)
        FROM fleet_minute AS fm
    ) AS worst_server_sum_ms_p50_p90_p99_p999;

-- The same, per collector: which collectors make up the long minutes.
WITH per_server_minute AS
(
    SELECT
        cl.server_id,
        date_trunc('minute', cl.collection_time) AS minute,
        SUM(cl.duration_ms) AS sum_ms
    FROM collect.collection_log AS cl
    WHERE cl.collection_time >= (now() AT TIME ZONE 'UTC') - interval '3 days'
    AND   NOT (cl.collection_time >= timestamp '2026-10-08 19:00:00' AND cl.collection_time < timestamp '2026-10-09 00:00:00')
    GROUP BY
        cl.server_id,
        date_trunc('minute', cl.collection_time)
)
SELECT
    cl.collector_name,
    count(*) AS runs_in_long_minutes,
    percentile_cont(0.5) WITHIN GROUP (ORDER BY cl.duration_ms) AS p50_ms,
    max(cl.duration_ms) AS max_ms
FROM collect.collection_log AS cl
JOIN per_server_minute AS psm
  ON  psm.server_id = cl.server_id
  AND psm.minute = date_trunc('minute', cl.collection_time)
WHERE psm.sum_ms >= 30000
AND   cl.collection_time >= (now() AT TIME ZONE 'UTC') - interval '3 days'
GROUP BY
    cl.collector_name
ORDER BY
    sum(cl.duration_ms) DESC
LIMIT 10;

ROLLBACK;

Replay tool: the safety check reads the servers the service collects …

Claude posting for Erik Darling.

On the large SQL Server store, a normal day already meets the drain's wait rule in 513 of 843 five-minute windows (61%). In 920 of 4,201 minutes (22%), some server's collector run times add up to 30 s or more.

Setup:

The store: monitoring 43 SQL Server primaries, build 3.10.0-nightly.20261008.534.
The run: the script in issuecomment-6068627610, verbatim, inside BEGIN READ ONLY … ROLLBACK. It ran at 20:49:53Z for about 12 s of query time, and it excludes 2026-10-08 19:00 to 24:00 (the post-install drain).

Section 1

minutes	minutes_some_server_30s	minutes_some_collector_30s	windows_5min	windows_5min_some_server_30s	worst_server_sum_ms p50 / p90 / p99 / p99.9
4,201	920	313	843	513	15,393 / 47,675 / 93,879 / 622,840

Execution: 9,251 ms.

Section 2: collectors in the long minutes

collector_name	runs_in_long_minutes	p50_ms	max_ms
plan_correction	361	11,040	262,723
procedure_stats	1,123	2,074	99,858
query_stats	1,046	2,735	73,654
query_store	380	6,063.5	637,960
data_retention	5	1,063,345	1,794,173
ag_replica_states	1,098	638	22,792
blocked_process_report	1,121	1,570	14,704
ag_database_replica_states	1,081	223	15,419
query_snapshots	1,124	859.5	37,488
system_health_events	314	1,992.5	26,409

Execution: 2,469 ms.

"skipping relaunch" warnings per day, from the service log

Day (UTC)	`skipping relaunch` lines	`Collection is falling behind` lines
2026-10-05	75	3
2026-10-06	73	3
2026-10-07	58	5
2026-10-08, to 20:47Z	73	5

Caveat on Oct 8: it includes the post-install drain hour. At least 14 of its 73 lines fall between 19:20 and 19:48Z.
Caveat on Oct 5: that log file has 9,664 lines, against 41,768 to 64,146 for the other days.

Claude posting for Erik Darling.

Service-log read for the retune. This is the large SQL Server store's service log only, with no store queries.

The range: 2026-10-05 00:00 to 2026-10-08 21:05Z.
What's excluded:
- the post-install drain: skipping relaunch lines from 19:14 to 19:58Z.
- every gate line whose 60-minute window overlaps the drain: lines stamped 19:14 to 20:58Z.
When: read at 21:06Z, outside the store's avoid windows.

1. The hourly fleet-gate lines

These are the fleet collection gate, last 60 minutes: N collector slots ran, M skipped (P%) lines: 96 in all (82 Information, 14 "Collection is falling behind" Warning).

Set	Hours	M p50 / p90 / p99 / max	P p50 / p90 / p99 / max	Hours with M ≥ 20 and P ≥ 5	Hours with M ≥ 20	Hours with P ≥ 5
All lines	96	19 / 139 / 2,378 / 3,249	0.00 / 0.65 / 21.25 / 24.1	7	42	7
Full-hour lines only (N ≥ 5,000)	90	19 / 95 / 2,433 / 3,249	0.00 / 0.20 / 4.39 / 5.9	1	36	1

The 6 short lines (N from 613 to 1,503, against about 54,000 in a full hour):

Time (UTC)	N	M	P
10-05 14:28	916	291	24.1
10-06 12:56	613	164	21.1
10-06 13:10	1,503	285	15.9
10-07 10:20	1,277	247	16.2
10-07 12:44	1,243	114	8.4
10-08 13:41	787	57	6.8

What they are: the 10-08 13:41 line is the first gate line after the 13:37Z install. I did not check the other five against restart times.

Full-hour lines with P ≥ 1:

Time (UTC)	Level	N	M	P
10-05 15:28	W	54,056	1,114	2.0
10-07 13:44	W	52,945	2,332	4.2
10-08 14:41	W	51,561	3,249	5.9

The other 87 full-hour lines are under 1%.

2. `skipping relaunch` Warnings in 5-minute windows

	Count
Lines	265
5-minute windows in the range	1,108
Windows with any	172
Windows with exactly 1	125
Windows with exactly 2	32
Windows with 3 or more	15
Most in one window	14 (10-08 13:40)

The next busiest windows: 10-05 14:25 (7), 10-06 13:05 (7), 10-08 13:45 (7) and 10-07 12:40 (6).
next run is skipped until it ends (Every daily collector runs detached from its server's pass, behind a fleet-wide cap sized to the store's pool (#4938) #4999) lines: 0 in the range.

Retention drain: back off on a share of skipped slots, not on any ski…

Retention drain yield: cap a pass's waits at half its budget, minimum…

A retention pass that stopped on its wall budget makes the next sched…

Pin that the continuation stamp is written under the purge slot's lock (

Claude posting for Erik Darling.

The #5592 A/B on two restored copies, both under the same replayed collector load:

Every drain phase on the large tables met the bar. That includes the unpaced wide-table drain on A (write p95 1.14× its no-drain phase).
Three phases missed the latency bar, one on each run (2.2× to 2.5×): A's and B's first phase in the service's first 4.5 min, and B's second run's query_store_text phase.
I/O wait could not be scored. The tool's sampler never caught a write backend mid-wait.
The main difference between A and B is volume. A cleared the whole backlog in one 70 min pass. B's passes stop at 30 min, and the purge is daily, so the rest waits 24 h.

Setup

The copies: two copies restored from the same snapshot of a store monitoring 43 SQL Server primaries. The snapshot is at schema 165, with a 9-day Query Store backlog.
Hardware: r7i.2xlarge, with gp3 volumes set to the source store's 6,000 IOPS / 250 MB/s. The runs started only after the volume change read completed.
Isolation: outbound network blocked except the management agent. Monitored servers, alerts and notification routes were disabled. No SQL Server was reached.
A: ca2a39952 (dev, unpaced).
B: 4f3282473 (PR The first retention drain gives way to collection, so it no longer makes slots skip (#5592) #5595). Its merge base with dev is ca2a39952, so A and B differ by the The first retention drain after an upgrade makes collection fall behind on a large store #5592 commits only.
Both services started at 23:15:56Z 10-08 and applied V166 to V172.
The load: tools/drain-ab-replay/Invoke-DrainAbReplay.ps1 (the same file on both, from 77a67217f), with -IdleMinutes 60 -HardCapHours 3. That's 32 clients at 3.92 tx/s (905 rows/s, 8 tables, 90.2% of the store's hourly rows).
B's second run (B2):
- Why: B's first pass stopped at its budget, so I ran purge_now on copy B at 01:17:08Z 10-09. A fresh tool run started at 01:11:55Z.
- The load: its rate window had moved onto the copy's idle hours (457 rows/s), so it ran with -RateScale 1.98. That's 4.21 tx/s, about 905 rows/s. The mix is the same 8 tables, with query_store_stats at weight 19 against 26.

The purge passes (service log)

Run	Pass	Wide table	Pass total	WAL during the batches
A	23:16 to 00:25:54	`drained 19463770 row(s) ... in 391 batch(es)`	`91 table(s) purged, 20241730 row(s) deleted ... 4179742ms`	19,529 MB
B	23:16 to 23:46:35	not reached	`Retention purge stopped at its 30-minute time budget in query_plan_dim with 15 table(s) not reached`. 482,440 rows deleted. `Collection was waited for 590 s and the drain paused 204 …`	4,865 MB
B2 (`purge_now`)	01:17 to 01:47:10	`drained 4000000 row(s) ... in 80 batch(es)`, then stopped: `stopped at its 30-minute time budget in collect.query_store_interval_wide_legacy with 12 table(s) not reached`	4,361,382 rows deleted, 31 chunks dropped	6,180 MB

B's first drain start: Retention drain is waiting for collection to catch up (the service started 13 s ago and collection is still settling). B's first retention DELETE came at 23:26Z, 10 min after the start.
No resume after the budget stop: no pass ran at B's next hourly tick (00:16Z). DarlingWorker.cs at 4f3282473 has s_purgeInterval = TimeSpan.FromHours(24) (line 161). TryStartScheduledPurge sets the next run to now plus that. So "the next pass continues from the rows left" means the next daily purge, unless purge_now is used.
The backlog left on B: after B2, about 15.5 M of the about 19.5 M wide rows remain, plus 12 tables. At 4 M rows per pass, that's about 4 more daily passes for the wide table alone (estimate).

Each drain phase of 60 s or more against its own run's no-drain phase

The bar was set before the data: write p95 at most 1.5×, lag p95 at most 1.5×, and I/O wait at most 10 points above no-drain.

Run	Phase	Seconds	Write p95, ms	Ratio	Lag p95, ms	Ratio	Bar
A	no drain	4,066	149.9	1.00	14.9	1.00
A	`query_store_top_daily`	267	364.3	2.43	15.0	1.01	latency over
A	`query_plan_dim` (#2)	1,301	87.0	0.58	14.9	1.00	met
A	`query_store_interval_wide_legacy` (#2)	2,213	170.5	1.14	14.9	1.00	met
B	no drain	4,441	112.4	1.00	14.9	1.00
B	`query_store_top_daily`	254	277.3	2.47	14.9	1.00	latency over
B	`query_store_plan_map`	62	99.9	0.89	14.9	1.00	met
B	`query_plan_dim` (#2)	597	103.7	0.92	15.0	1.01	met
B2	no drain	4,100	76.9	1.00	15.0	1.00
B2	`query_store_text`	110	167.5	2.18	15.0	1.00	latency over
B2	`query_plan_dim` (#2)	790	47.0	0.61	14.9	0.99	met
B2	`query_store_interval_wide_legacy`	665	33.6	0.44	15.0	1.00	met

I/O wait: io_wait_share_pct is empty in every phase of all three runs, with active_samples 0. At about 4 tx/s the once-a-second sampler did not catch a pgbench backend active. So the I/O bar is not scored.
The query_store_top_daily phases on A and B ran from 23:16:21 to 23:20:52, the first 4.5 min after both services started. They overlap the start-up work (migrations, store convergence), and they are the same on both sides.
Write p50 in every phase: 14.6 to 26.0 ms, except B's query_store_text (93.4 ms, 35 s) and A's 2 s analysis_findings phase.
Where the files are: each run's summary.md, phases.csv and latency_by_script.csv are kept locally.

What the replay does not show

The real collectors: the replay writes with INSERTs at a fixed schedule. It does not reproduce the real collectors' reads against the store, the service's skipped slots, or the self-alert. On the live store, the unpaced drain after the 534 install (17.78 M wide rows) came with the "Collection Falling Behind on Monitor Store" self-alert at 7.7% skipped slots (issuecomment-6068831878, issuecomment-6069085734). The replay is not evidence about that.
Teardown: both copies, their volumes and the scratch security group are deleted (describe returns NotFound for each).

Read the purge continuation stamp as the sooner of two absolute times (…

The retention drain gives way to collection, stops at a 30-minute bud…

Fixed on dev by #5595. The retention drain now gives way to collection: it stops at a 30-minute budget and continues within the hour. Claude posting for Erik Darling.

Run the module map repair once a day, not after every purge pass (#6044…

Navigation Menu

Repository navigation

The first retention drain after an upgrade makes collection fall behind on a large store #5592

What happens

Goal

The fix

How often a normal day meets the drain's wait rule

Section 1

Section 2: collectors in the long minutes

"skipping relaunch" warnings per day, from the service log

1. The hourly fleet-gate lines

2. `skipping relaunch` Warnings in 5-minute windows

Setup

The purge passes (service log)

Each drain phase of 60 s or more against its own run's no-drain phase

What the replay does not show

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

The first retention drain after an upgrade makes collection fall behind on a large store #5592

Description

What happens

Goal

The fix

Activity

erikdarlingdata commented on Oct 8, 2026

How often a normal day meets the drain's wait rule

erikdarlingdata commented on Oct 8, 2026

Section 1

Section 2: collectors in the long minutes

"skipping relaunch" warnings per day, from the service log

erikdarlingdata commented on Oct 8, 2026

1. The hourly fleet-gate lines

2. skipping relaunch Warnings in 5-minute windows

erikdarlingdata commented on Oct 9, 2026

Setup

The purge passes (service log)

Each drain phase of 60 s or more against its own run's no-drain phase

What the replay does not show

erikdarlingdata commented on Oct 9, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions

2. `skipping relaunch` Warnings in 5-minute windows