Repository navigation
Darling: every server skips one collection pass about 30 minutes after a service restart (first seen in the slot log of nightly 550) #5824
Description
Claude posting for Erik Darling.
Measured on the largest field store (store A, 42 servers) on 2026-10-14, read-only, after the nightly 550 restart at 20:57Z. Nightly 550 is the first build that records a stepped-over collection slot (#5741), so this is the first time the dip is visible in collect.collection_log. The 547 restart on 10-13 shows the same dip in the count of successful runs, so it is not new.
What happens
- After a service restart, the first
data_retentionrun goes long: 1,820 s (20:58 to 21:28), 240,055 rows deleted, about 3.9 GB of WAL. The purge then runs in rounds of about 30 minutes. - About 2 minutes after that first run ends, every server skips one collection pass: 84 SKIPPED rows at 21:30 to 21:39, one or two on all 42 servers, each waiting 78 to 211 s for a fleet collection slot (or "no single cause was measured"). Eleven more at 21:01 to 21:02 are restart catch-up (56 to 67 s waits). From 22:00 nothing is skipped.
- Successful runs per 5 minutes around the dip (two restarts):
| Minutes after restart | 547 (10-13) | 550 (10-14) |
|---|---|---|
| 25 to 30 (normal) | 4,572 | 4,679 |
| 30 to 35 | 2,905 | 2,230 |
| 35 to 40 | 4,226 | 3,744 |
| 40 to 45 (normal again) | 4,574 | 4,644 |
Inferred, not tested: the end of the purge, or the work that follows it (checkpoint, autovacuum on the purged chunks, or compression), slows the store for a few minutes; collectors hold their fleet slots longer, and the next passes skip.
Why it matters
About 16 KB of WAL per deleted row is far more than a plain DELETE should write; it points at deletes against compressed chunks, or at a purge that rewrites more than it removes. One skipped pass per server per restart is small; a purge that writes gigabytes every 30 minutes is the thing to measure.
Ask
- Measure, on the same store, what the retention purge deletes from and how much WAL each table's purge writes per row (the
data_retentionlog rows andpg_stat_walaround one round). If deletes hit compressed chunks, usedrop_chunksfor whole-chunk retention and delete rows only inside the partial chunk. - Check whether the dip follows the purge's later rounds too, not only the first after a restart. If it does, the fix is in the purge; if it does not, the first round's size (the restart backlog) is the cause and a capped first round would do.
- If the purge stays long, make the fleet slot wait not count a store-side stall as a missed slot for every server at once (one purge should not skip 42 passes).
No seat work is assigned yet; this records the measurement.
Activity
erikdarlingdata commentedon Oct 14, 2026
Claude posting for Erik Darling.
Correction, from one row per
data_retentionround on the same store since 10-11 (the SKIPPED column exists only from build 550; the before/after columns are successfulcollection_logruns in the 10 minutes before and after the round ended):What changes
Inferred, not tested: the first scheduled analysis pass runs about 30 minutes after a service start (the analysis cadence), and before #5812 its PLAN_REGRESSION read was the store's most expensive statement, with its slowest runs at the 60 s timeout. A first pass over every server at once would hold the store for a few minutes and make every collector wait for its fleet slot. If that is it, #5812 (PR #5817) removes the cause.
Next check, cheap: on the same store, the start time of the first scheduled analysis pass after the 550 restart, and whether its PLAN_REGRESSION reads ran inside 21:28 to 21:40. After #5817 is installed, the next restart answers it for good.
[-]Darling: the first retention purge after a restart writes gigabytes of WAL, and every server skips one collection pass when it ends[/-][+]Darling: every server skips one collection pass about 30 minutes after a service restart (first seen in the slot log of nightly 550)[/+]erikdarlingdata commentedon Oct 14, 2026
Claude posting for Erik Darling.
The analysis-pass suspect from the last comment does not hold on its own. From the same store's
analysis_findings(2-minute buckets) and the service log:The first pass runs 0 to 150 s after each server connects, not 30 minutes after the start. The second pass sits inside the dip, but every later pass has the same shape and no dip, and the 547 restart on 10-13 shows the same pattern (the dip on the second pass only).
Three things ended together inside the dip window: the first purge round (21:28:27), the daily module_map refresh that starts when a purge round ends (done 21:32:58, about 60,000 attributions), and the second analysis pass. All three also ran together at 22:58 to 23:05, with 8 skips and a -2% change, and after each of the four purge rounds on 10-13 with a dip only after the first. So nothing found so far happens only once after a restart.
A small separate finding: three
PgDrillDownCollectorerrors (NpgsqlException: Exception while reading from stream, PLAN_REGRESSION -> CPU_SQL_PERCENT -> SOS_SCHEDULER_YIELD), each next to a purge end and a module_map refresh (22:59:38 and 23:00:16 on 550; 19:46:30 on 547). Not new in 550.Next check (cheap, on the same store): total collector time per collector in the 10 minutes after 21:28 against the 10 minutes after 22:58, and which collectors the 84 SKIPPED rows name. That shows what held the fleet slots the first time and not the second.
erikdarlingdata commentedon Oct 15, 2026
Claude posting for Erik Darling.
The per-collector check (same store,
collection_logby end time, SKIPPED rows excluded; rounded, top rows by difference):plan_correction, 4.0 s against 2.8 s over the same 84 runs). The per-minute collectors simply ran about 39% less often (250 runs against about 412).ag_database_replica_states,ag_replica_states,attention, 1 or 2 slots each): that is a tie broken alphabetically, not a signal. The message should say so.So the fleet slots were held by work that
collection_logdoes not record. A comment inDarlingWorker.cssays the analysis pass runs inside the per-server sweep body; if that body holds the server's fleet slot, a slow pass holds the slot, and the second pass after a restart sits inside the dip (comment above). Its run time is not recorded anywhere, so this cannot be shown from the store today. Inferred, not traced.Next, in code rather than in the store: (1) trace whether the analysis pass runs inside the fleet slot; (2) record each server's analysis-pass run time (a
collection_logrow, soget_collector_costand this check can see it); (3) make the SKIPPED message name "every due collector" when the slot counts tie; (4) read what the end of a purge round does that writes gigabytes of WAL whatever the row count, and that sits next to the threePgDrillDownCollectorstream errors. The next restart after that change answers the question with numbers.module_map refresh writes only new or changed rows (#5824)
get_collection_log's status parameter fits its tools/list budget again (
get_collection_log's run_count leaves out the analysis_pass row; a fi…
Pin two concurrent module_map refreshes completing without a deadlock (…
Record each scheduled analysis pass in the collection log and name it…
erikdarlingdata commentedon Oct 15, 2026
Claude posting for Erik Darling.
Field check on nightly 553 (3.10.0-nightly.20261015.553, dev ab5b0b7, carrying #5817, #5826 and #5828), installed on all four stores by 14:04Z. Numbers from the collection log of the 42-server store, read after the restart.
Successful collection runs per 5 minutes after the restart (every collector except the analysis pass):
On 547 and 550 the 30-35 minute bucket fell to 2,905 and 2,230. On 553 it is 4,587. SKIPPED rows between +15 and +45 minutes, the symptom this issue describes: 0.
The only SKIPPED rows are 29 in the first 10 minutes, one per server, all naming the analysis pass with the #5828 cause text: 18 waited for a fleet collection slot held by scheduled analysis passes, 11 had the previous pass's scheduled analysis holding the server's slot after its collectors.
Analysis pass durations over 42 servers: the second pass (+15 to +45 min) p50 15.7 s, p95 24.7 s, max 26.8 s; the quiet window (+75 to +105 min) p50 5.9 s, p95 17.9 s, max 22.1 s. The second pass still takes about 2.7 times the quiet p50, but it no longer starves collection.
One restart, not a trend. Closing as fixed in 553. The next nightly restart is the confirmation; this reopens if the dip comes back.