Repository navigation
Darling: the daily retention purge runs inline in the collection launch loop, so each SQL store stops collecting for 7–10 minutes a day #4130
Description
Activity
- added a commit that references this issue
on Sep 24, 2026 Closed by the watcher: delivered in PR #4133, merged to dev.
Reopening on evidence from the first nightly that carries #4133 (3.8.0-nightly.20260924.467). #4133 moved the daily purge off the collection launch loop, so it now runs alongside collector writes. On the largest SQL Server store (43 servers), the first purge after the install failed, and collector writes failed during it. The pre-registered watch bar for #4133 was one purge-window retention failure, and this is one.
What the service log shows (all times UTC, the day of the install):
- 22:13:34: the collection loop starts, and the purge launches with it (Fix #4130: fire-and-track the daily retention purge off the launch loop #4133's first-start run).
- 22:14:23: the deadlock re-mask stage fails with
57014: canceling statement due to statement timeout. - 22:15:58: a collector's
query_storestore write fails:store-write COPY data phase (rows in flight under the collection-sweep deadline): Exception while reading from stream. - 22:29:32:
Could not read config_version … Exception while reading from stream. - 22:32:09:
Retention purge failed for query_plan_dim after removing 250000 row(s): Exception while reading from stream. - 22:32:10:
Retention purge: 85 table(s) purged, 293188 row(s) deleted, 0 chunk(s) dropped, 1 failed, 1116220ms. - 22:35:04: a second collector
query_storeCOPY fails (Exception while writing to stream). - 22:37:13:
module_map refresh failed … Exception while reading from stream. Nothing failed after this.
Measured, for comparison:
- The purge took 1,116 s. The same store's inline purge took 346–400 s before Fix #4130: fire-and-track the daily retention purge off the launch loop #4133.
- Its previous run, inline at 03:31 the same day, was SUCCESS (838,989 rows, 26 chunks). This is the first non-success
data_retentionrow on that store in 8 days. - Store-write COPY failures of this kind also occur without a purge running: 1–2 on each of 4 of the previous 7 days. So those two alone are not new; the new part is that they fell inside the purge window.
- The other three stores on the same build ran their first-start purge with no failure.
Not yet shown (inferred, not measured): the stream errors are Npgsql command timeouts on the store, caused by the purge's
query_plan_dimdelete contending with collector COPYs and the post-start refresh/backfill work. Other load was also present right after the restart: acollection_health_hourlyrefresh of 95 s, and autovacuum workers active afterwards. So this run may be a first-start worst case rather than the steady state.Next:
- The next purge on that store is due about 24 h after the start (Fix #4130: fire-and-track the daily retention purge off the launch loop #4133 re-anchors it). That run shows whether this is first-start only.
- If it fails again, the
query_plan_dimpurge needs a bound: a smaller batch, a per-statement timeout with resume, or running after the start-up convergence has settled.
Mechanism evidence for the first-start
query_plan_dimfailure (the store that failed, build .467, read 2026-09-25 ~02:15–02:20Z; read-only).The failing statement was the sixth 50,000-row batch of the row-capped plan-dimension delete, cancelled by the client:
- The store's PostgreSQL log at
2026-09-24 22:32:09.163 UTC:ERROR: canceling statement due to user request;STATEMENT: DELETE FROM query_plan_dim WHERE ctid IN (SELECT ctid FROM query_plan_dim WHERE last_seen < $1 ORDER BY last_seen LIMIT 50000).
- The service log 4 ms later:
Retention purge failed for query_plan_dim after removing 250000 row(s): Exception while reading from stream, then85 table(s) purged, 293188 row(s) deleted, … 1 failed, 1116220ms. - "Exception while reading from stream" plus a server-side "user request" cancel is what an Npgsql
CommandTimeoutexpiry looks like. That fitsDarlingRetention.DeleteTimeoutSeconds = 300. I haven't seen the innerTimeoutException, because the service logs only the outer message.
Why a batch can reach 300 s on this store (
get_store_query_stats, owner role, since the restart):- The five batches that succeeded averaged 152.7 s (max 195.8 s), about 330 rows/s.
PlanDimDeleteRowCap's doc sizes 50 k at ~50 s (~1,000 rows/s measured on the other SQL store), for "about 5x margin" against the 300 s timeout. On this store the steady margin is ~2x, not 5x. The first-start burst (catch-up COPYs, the store-timeout window 22:14–22:37Z) was enough to push one batch past it.- For comparison, the other SQL store's batches since its restart: 11 calls, mean 30.7 s, max 43.2 s.
query_plan_dimhere is 67 GB, 63 GB of it TOAST (pg_toast_17428). An autovacuum of that TOAST relation was cancelled at 23:13:50Z, at block 4,075,763. So the table is also carrying vacuum debt, which is consistent with the slower per-row delete cost. That's an inference, not measured.
What this suggests for tonight's read and after:
- Tonight's run is not a first start, so on this evidence it most likely finishes inside 300 s per batch. A success would mean "first-start only", as the bar says. But the margin is ~2x, not the 5x the cap was sized for.
- A durable fix sizes the batch from measured throughput instead of a constant. For example, adapt the cap per statement toward a target of ~60 s (halve after a slow batch, grow after a fast one). Alternatively, catch the timeout and retry that slice once at half the cap, instead of failing the table for the day. Either keeps the purge progressing under load.
- The store's PostgreSQL log at
- added a commit that references this issue
on Sep 25, 2026 Closed by #4210, merged to dev.
Field evidence, 2026-09-25. This replaces tonight's scheduled purge read, which the host resize cancelled.
The largest field store moved to a host with twice the RAM (32 GiB to 63 GiB, the same 8 vCPU). It restarted at 03:20:35Z. The service ran its first-start purge during the catch-up burst, on a cold cache.
- The purge succeeded. It took 701,498 ms across 86 tables, deleted 262,687 rows, and dropped 31 chunks. Last night's first-start purge failed at 1,116 s, after a 300 s cancel on batch 6.
- The plan-dimension DELETE batches (LIMIT 50000) did not get faster. In
pg_stat_statementsthe statement went from 5 calls to 9. The 4 new batches averaged about 163 s. One took 210 s, which is 70% of the 300 s command timeout. - The batches still run about 3 times longer than the ~50 s the cap was sized for. The worst batch left a margin of about 1.4x.
So last night's failure and today's success differ in margin, not in mechanism. More RAM did not change the batch cost. The adaptive batch cap in #4210 is still needed.
Problem
On the SQL Server stores, the scheduled daily retention purge runs inline in the collection launch loop. For as long as the purge runs, no new per-server sweep is launched, so every monitored server goes stale.
Measured on two production SQL stores on 2026-09-24 (MCP reads):
data_retentionrun took 400,781 ms and deleted about 839k rows. Staleness peaked at 13.4 minutes, and 31 of 43 servers read Warning "collection stale". The same hole appeared the day before.Where
Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs, about lines 2556–2565, inside the sweep-launch loop:if (DateTime.UtcNow >= _nextPurgeUtc) { _nextPurgeUtc = now + 24h; await DarlingRetention.PurgeAsync(...); await ...CleanupOldFindingsAsync(...) }While those awaits run, the loop launches nothing. In-flight sweeps finish, then every server goes stale until the purge returns.
_nextPurgeUtcstarts atDateTime.MinValue, so the first purge runs at service start and then every 24 hours. The daily hole is anchored to the last restart.The
purge_nowcommand's own comment says a purge "takes NO collection gate" and "may safely overlap the daily sweep". So by the code's own reasoning, running the scheduled purge off the launch loop is safe. That is inferred, not tested.Fix
_nextPurgeUtc's schedule and the purge's own logging and self-metrics as they are.Also check
Why no staleness self-alert fired during a 13-minute stall. The stale threshold may be above 13 minutes, or the evaluator may run on the stalled loop. If the evaluator shares the loop, the fix above covers it too. Otherwise, report the threshold.