Store disk-pressure check's pg_database_size times out in bursts: 5s deadline sized on a 4.05 GB store, beating against the 300s checkpoint cycle

[erikdarlingdata]

The user_request_cancel clusters on the use2 store are the store disk-pressure check's pg_database_size call hitting its 5-second deadline. The deadline was sized against a 6.2 ms measurement on a 4.05 GB store; use2's store is an order of magnitude larger, and pg_database_size walks every file in it.

What the cancels are

DarlingWorker.cs:4371 — new NpgsqlCommand("SELECT pg_database_size(current_database())", connection) { CommandTimeout = ServiceCommandDeadlines.SerialLoopSeconds }, and SerialLoopSeconds is 5.

Read from the use2 store's own PostgreSQL log, every cancel carries the statement:

2026-09-09 03:45:27.336 UTC [4304] ERROR:  canceling statement due to user request
2026-09-09 03:45:27.336 UTC [4304] STATEMENT:  SELECT pg_database_size(current_database())

Eight occurrences on 2026-09-09, all between 03:45:27 and 04:21:03, each on a different PID. None anywhere else in the day.

The mechanism, and why it clusters

The intervals between consecutive cancels are 305.181, 305.125, 305.123, 305.103, 305.118, 305.131, 305.241 seconds — mean 305.146 s, spread 0.138 s.

The check is finish-to-start on a 5-minute sleep, so its period is 300 s plus however long the call takes. 305.1 s means the call is consuming its full 5 s deadline every iteration — during a cluster, every check times out, not some.

Checkpoints on this store run on a 300 s timer with write phases spanning ~270 s of that (checkpoint complete: ... write=269.673 s, total=271.800 s), so the store is writing for roughly 90% of every checkpoint cycle.

Two periods 5.146 s apart beat with a period of 300 × 305.146 / 5.146 = 17,789 s = 4.94 hours. So:

• while the check's phase overlaps the checkpoint's write phase, pg_database_size's file-stat walk is starved and blows the 5 s deadline;
• each timeout stretches that iteration's period from 300.0 s to 305.1 s, which walks it out of phase;
• after ~30 minutes it clears the write phase, succeeds in milliseconds again, and the period returns to 300.0 s until the next beat brings it back.

It is a self-limiting oscillation, which is exactly why it appears as a bounded burst on a long cycle rather than as a permanent fault.

Corroboration: two beat periods is 9.88 hours. The monitor loop independently observed clusters at 03:41–04:07 and 14:04–14:14 UTC — 10.4 hours apart, and the observed start time drifts between cycles, as a beat does.

Why the 5 s deadline does not transfer

ServiceCommandDeadlines.cs:341 states the provenance plainly:

Measured against a 4.05 GB store built by the product's own MigrateAsync and seeded through SeedIfEmptyAsync … pg_database_size 6.2 ms — so the worst SINGLE command on this thread is a single-digit-millisecond read and 5 s is roughly three orders of magnitude above it.

The reasoning is sound and the measurement was real. What moved is the population. pg_database_size stats every file in the database directory, and a TimescaleDB store's file count scales with chunk count rather than with byte size — so a store an order of magnitude larger has many times the files, and the walk competes with checkpoint I/O for the same disk. A margin of "three orders of magnitude" over a measurement taken on a 4.05 GB fixture is not a margin over this store.

This is the same shape as #3188: a constant carrying real evidence from a population that has since moved, with nothing that notices.

Impact: log noise and a missing number, NOT a monitoring gap

I expected this to blind the disk-pressure alert and checked. It does not. The catch at DarlingWorker.cs:4376 says so, and it is right:

NOT counted by #3013's swallowed-read counter: this read is CONTEXT for the alert text, not the evidence the alert is judged on — that is freeBytes/totalBytes above.

The alert judges on DriveInfo free/total, which is a syscall and unaffected. Losing this costs the alert message a number.

What it does cost:

1. ERROR-level lines in the store log on a recurring cycle, which get_store_log's classifier then has to absorb as user_request_cancel — part of the "expected floor" whose text is deliberately not retained. So the product generates noise that another part of the product is configured to discard, and the discarding is what made this hard to attribute.
2. A real diagnostic dead end. Attribution needed raw store-log access; the classifier's summary could not answer it by design.

Fix options

1. Give this call its own deadline rather than the shared SerialLoopSeconds. It is the only command on that chain whose cost scales with store size, and the chain-length argument (10 × 5 s = 50 s inside the 60 s watchdog) is what pins the shared value — so a separate constant for this one call does not disturb it.
2. Stop calling pg_database_size on a 5-minute cadence. It is context for an alert message. pg_total_relation_size summed from store_metrics' hourly snapshot, or simply the last recorded value, would serve the message without a filesystem walk.
3. Do nothing, and record why. Defensible — the effect is a missing number and some log noise — but then the classifier's "expected floor" note should name this call, so the next person who asks "what is cancelling?" gets an answer instead of a dead end.

I would take (2): the call is doing filesystem work every five minutes on every store to decorate a message, and it is the only reason this deadline is load-bearing at all.

Found while attributing the cancel clusters the monitor loop flagged; the offset defect #3198 was found in the same investigation.

[erikdarlingdata]

Claude posting for Erik Darling

Correction: the beat mechanism in the issue body is refuted by its own arithmetic. The identification stands; the explanation for why clusters start and stop does not.

A second reader compared my predicted two-beat interval of 9.88 h against their two observed clusters, 10.38 h apart, and recorded the ~30-minute gap as drift rather than smoothing it. Checking that gap is what broke the model.

Measuring the checkpoint period instead of assuming it. I used T2 = 300.0 s as the nominal checkpoint_timeout when the log carried the real value. Checkpoint starts at 03:44:46.195 and 04:19:46.148 are 2,099.953 s apart over seven intervals — 299.993 s each. So the drift per caller cycle is 305.146 − 299.993 = 5.153 s, near enough to what I had.

And that is what kills it. The cluster ran 03:45:27 → 04:21:03: eight cancels over 35.6 minutes, accumulating 36.1 s of drift. The checkpoint write phase is ~270 s wide (write=269.673 s of a 271.800 s checkpoint). At 5.153 s per cycle, traversing a 270 s write phase takes 52 cycles ≈ 4.4 hours.

The cluster ended after 8 cycles. Thirty-six seconds of drift cannot walk a caller out of a 270-second window. Whatever ends these clusters, it is not the check drifting clear of the checkpoint's write phase.

The beat arithmetic produced a number in the right neighbourhood of the observed cluster spacing, and I read that agreement as confirmation without checking whether the same model predicted the cluster duration. It does not — it is wrong by a factor of seven in the direction I never looked.

What survives, and it is the actionable part

1. The statement. SELECT pg_database_size(current_database()), read from the store log beside every cancel with its PID. Definitive.
2. The deadline and its provenance. DarlingWorker.cs:4371 runs it with CommandTimeout = ServiceCommandDeadlines.SerialLoopSeconds = 5, and ServiceCommandDeadlines.cs:341 sizes that against a measured 6.2 ms on a 4.05 GB store. Definitive, and unaffected by any of the above.
3. Every call in a cluster consumes its full deadline. Intervals of 305.146 s ± 0.138 against a 300 s finish-to-start sleep is 5.1 s of work per iteration, which is the timeout. So during a cluster the check times out every time, not intermittently. Arithmetic on log timestamps.
4. The impact assessment. Unchanged: the alert judges on DriveInfo free/total, so this is log noise and a missing number in a message, not a blinded alert.
5. The fix recommendation. Unchanged, and if anything stronger — the case for not doing a filesystem walk every five minutes to decorate an alert message does not depend on knowing why the timeouts cluster.

What is now open

Why does the store become slow enough to blow a 5 s deadline for ~35 minutes, then stop? Something makes pg_database_size two to three orders of magnitude slower than its 6.2 ms baseline for a bounded window. Checkpoint contention is still a plausible contributor — the cancels do land inside checkpoint write phases — but it cannot be the gate, because checkpoints run continuously and the cancels do not.

Candidates worth checking against a future window rather than reasoned about: a heavy continuous-aggregate refresh or compression job overlapping the band; the Windows shared-memory reservation retries visible at 04:16:50, 04:20:44 and 04:22:10; or store I/O saturation from a source not yet identified. The clusters are observable and recur, so this is answerable by watching one live rather than by more inference over the same eight rows.

I would rather leave that named as open than leave a mechanism in the issue body that its own numbers refute.

[erikdarlingdata]

Claude posting for Erik Darling

Measured on the affected store. The call takes 3,177 ms at rest — 64% of its 5-second deadline consumed with no contention at all.

Read against the use2 store, the box whose PostgreSQL log carried the eight cancels, in a read-only session.

SELECT pg_database_size(current_database());
  store_bytes = 241,640,380,095   (225 GiB)
  Time: 3177.414 ms

That reframes this issue. It is not a call that occasionally overruns under load; it is a call already sitting at two-thirds of its budget while the store is quiet. Any contention at all — a checkpoint write phase, a compression job, a refresh — pushes it over. The clusters need no exotic mechanism to explain their existence, only something that removes the remaining 1.8 seconds of headroom.

That also retires the beat model in the correction above more cleanly than the arithmetic did. I was looking for a mechanism that creates the timeouts periodically. The margin is gone all the time; what varies is only whether anything at all is competing.

Against the deadline's stated provenance

ServiceCommandDeadlines.cs:341 sizes the 5 s bound on a measured 6.2 ms pg_database_size against a 4.05 GB store, concluding 5 s is "roughly three orders of magnitude above it."

	provenance fixture	this store
store size	4.05 GB	225 GiB (56x)
pg_database_size	6.2 ms	3,177 ms (512x)
headroom under the 5 s bound	~806x	1.57x

The cost grew an order of magnitude faster than the size, which is what the file-count argument predicts: pg_database_size stats every file, and a TimescaleDB store's file count scales with chunk count — driven by retention span and hypertable count as well as bytes.

The margin the comment claims is not 806x on this store. It is 1.57x, and the comment reads as reassuring precisely because its measurement was true when taken.

The replacement read, measured on the same store

EXPLAIN (ANALYZE, BUFFERS) on the shipped replacement, run cold then warm:

	Execution Time	Planning Time	Buffers
cold	0.101 ms	2.063 ms	3 shared read
warm	0.018 ms	0.094 ms	3 shared hit

Plan is Index Scan Backward using idx_store_metrics_time, the existing V53 index — no new index is needed, as the change intends.

0.101 ms cold against 3,177 ms is a factor of ~31,000. It reads three buffers instead of walking the filesystem.

One number the PR body should carry, and it is not "up to an hour"

The replacement reads the hourly self-metrics row, so it can be stale. Measured over 30 days on this store: 737 whole-store rows across 713 distinct hours — dense, as the cadence claims, so the fix is not reading a sparse source. But:

• max gap: 8,890.8 s = 2.47 hours
• mean gap: 3,518.2 s = 58.6 minutes

So the honest worst-case staleness for the alert text is 2.47 hours, not one hour. Worth stating as the bound rather than describing the cadence.

Not answerable on this store

pg_stat_statements is not installed here (extension_present = 0), so there is no per-caller history for pg_database_size and no aggregate tail to quote. Reporting that as unanswerable rather than as a zero — the request that asked for it drew that distinction explicitly, and it was right to.

[erikdarlingdata]

Claude posting for Erik Darling

Correcting my own framing, and the corrected version is a stronger case for the fix than the cancels ever were.

I wrote that "the margin is gone all the time." A reviewer pushed back that this contradicts the observation it explains — if it were literally true the check would blow its deadline on most of ~288 daily iterations, not on 8. That is right, and one sample cannot establish a floor. Measured properly:

Cost distribution. Thirteen samples on the affected store — five on a single connection (no connect overhead) and eight on separate connections:

	n	min	mean	max
in-session	5	2,090 ms	2,477 ms	3,269 ms
separate connections	8	2,122 ms	2,688 ms	3,745 ms

None of the thirteen crossed the 5,000 ms deadline. So my 3,177 ms reading was typical rather than unlucky, and the call sits at roughly 42–75% of its budget rather than past it.

Cancel rate. pg_database_size cancels per full day, counted from the store's own weekday log files: Thu 7, Fri 0, Sat 3, Sun 8, Mon 9, Tue 8 — mean 5.8 against 288 iterations per day. That is 2.0%.

The finding this actually produces

98% of the iterations cost ~2.5 seconds and never log anything. The serial loop stalls for about two and a half seconds every five minutes — roughly 11.9 minutes per day — and only the 2% that happen to cross 5 s under contention leave any trace at all.

The cancels were never the problem. They are the visible two percent of a cost that is paid continuously and silently, and the reason this took a raw log read to find is that the other 98% is invisible by construction: under the deadline, so no cancel; not a collector run, so no collection_log row; and the whole point of a serial loop is that a stall in it looks like nothing.

A correction that goes the other way, which the same reviewer caught

The hourly self-metrics sweep computes its store row with the same call — StoreSelfMetrics.cs:193, pg_database_size(current_database()). So the fix relocates part of this cost rather than removing it, and any claim of "~31,000x" needs scoping. Honestly stated:

	executions/day	cost/day
now: disk check (288) + self-metrics (24)	312	~13 min
after: disk check reads store_metrics (288 × 0.1 ms) + self-metrics unchanged (24)	24	~1 min

92% fewer executions, and ~11.9 min/day of stall removed from the serial loop specifically — which is the path that matters, because it is the one with a 5-second deadline and a 60-second sweep watchdog behind it. The remaining 24 run on the self-metrics path, off the serial thread with a 300 s budget. The 31,000x figure is real for the single read's latency on the serial loop and should be stated that way rather than as the change's overall effect.

And a provenance correction on the staleness number

I gave "worst-case staleness 2.47 hours." That is a maximum over a 30-day sample on one store, and a rolling maximum cannot decay — stating it as a bound turns an observation into a guarantee someone will later rely on. It should read: the largest gap observed over 30 days on this store was 8,890.8 s (2.47 h), against a mean of 3,518.2 s. Same defect as #3188's ceiling constants, committed in the issue that cites #3188.

Incidental

Thursday's log holds 23 cancels of which only 7 are pg_database_size, so there is a second cancel source on this store that nothing here explains. Not pursued.

[erikdarlingdata]

Claude posting for Erik Darling

The loose end, resolved: it is one statement on one day, not a recurring second source. And the contention framing above needs correcting.

Every cancel on this store, six weekday logs, grouped

65 total.

count	days	statement
43	6	SELECT pg_database_size(current_database())
14	1	WITH clean AS (SELECT collection_time, delta_stall_read_ms::DOUBLE PRECISION / NULLIF(delta_reads, 0) AS v FROM file_io…
3	1	SELECT (SELECT MAX(collection_time) FROM collection_log WHERE server_id = $1 AND status IN ('SUCCESS','SKIPPED'))…
2	2	SELECT x.collector_name FROM (SELECT cl.collector_name, cl.status, ROW_NUMBER() OVER (PARTITION BY cl.collector_name…
1	1	SELECT EXISTS(SELECT 1 FROM collection_log WHERE server_id = $1 AND collector_name = $2 AND status = 'SUCCESS')
1	1	WITH latest AS (SELECT database_name, file_name, size_mb, ROW_NUMBER() OVER (PARTITION BY database_name, file_name…
1	1	DELETE FROM query_plan_dim WHERE ctid IN (SELECT ctid FROM query_plan_dim WHERE last_seen < $1 ORDER BY last_seen LIMIT 50000)

So the non-pg_database_size population is 22 cancels, and 14 of them are one statement on one day — a file-I/O stall-ratio read, fired between 00:27 and 05:44 on 2026-09-03 and never again in six days of logs. The remaining 8 are singletons and pairs spread across five days.

It is the same class — a read hitting a command deadline — but a different statement and a bounded one-day episode rather than a standing second source. On six days of evidence it does not recur, so I would not open an issue on it now; the note worth keeping is that if that Thursday shape returns, it is the deadline constant's second instance and belongs in a scoped issue about the constant rather than here.

Also worth noting for whoever looks: four of the seven distinct statements read collection_log, which is the alerting and health-read surface rather than the collection path.

A parsing error of mine, stated because it nearly became a finding

My first pass reported 20 cancels with no STATEMENT line and I was about to describe that as a phenomenon. It was my parser. PostgreSQL logs multi-line SQL with the STATEMENT: line itself empty and the body on following indented lines:

2026-09-08 18:04:38.916 UTC [4584] ERROR:  canceling statement due to user request
2026-09-08 18:04:38.916 UTC [4584] STATEMENT:
	SELECT

Reading only the STATEMENT: line yields an empty string for every multi-line query. Capturing continuation lines until the next timestamp gives zero empty statements out of 65. The single-statement pg_database_size cancels parsed correctly, which is exactly why the bug looked like data — it only silenced the queries I did not already know about.

Correcting the stall figure above

A reviewer's point, and it is right: 11.9 min/day of wall time is not 11.9 min/day of contention. The loop is finish-to-start on a 300 s sleep, so the thread is idle ~297.5 s of every 300 and a 2.5 s stall there displaces nothing. The claim that survives is "we spend twelve minutes a day on a call we do not need," not "we block for twelve minutes a day."

Where it does bite is the bound the same sentence named and did not lean on: 2.5 s out of the 60 s sweep watchdog is a real fraction; 2.5 s out of an idle 300 s is bookkeeping. Which of those applies depends on what else shares that serial loop, and that is a source question rather than a store question.

Two smaller ones in the same direction: 288 iterations/day is 86400/300, but the measured period is 305.146 s — finish-to-start, not fixed-rate — so it is ~284–286 and a mix of ~2.5 s and 5 s iterations. It moves 11.9 to 11.8 minutes and 2.0% stays 2.0%, but the figure should carry its construction.

[erikdarlingdata]

Claude posting for Erik Darling

Fixed by #3203, merged to dev as 3334d281ff3b. Closing by hand — closing keywords resolve against main and this landed on dev, so they never fire here.

The cancels in the title were the symptom, not the defect. Measured on the affected store: SELECT pg_database_size(current_database()) costs 2,090–3,745 ms across thirteen samples against a 5 s deadline sized on 6.2 ms / 4.05 GB. None of the thirteen crossed 5 s. Cancels for the statement ran a mean of 5.8/day against a nominal ~288 iterations — 2.0% — so the other 98% cost ~2.5 s each and left no trace anywhere: under the deadline so no cancel, not a collector run so no collection_log row. That is ~11.9 minutes a day of a serial loop's wall time spent computing a number the store already held, and none of it appeared in any telemetry. The eight log lines that found this were the visible tail.

The fix reads the size collect.store_metrics has recorded hourly since V53 — 0.101 ms cold, three buffers, Index Scan Backward on the existing V53 index, no new index.

Three things worth keeping, because each corrects something stated earlier in this issue or in working it:

The walk is relocated, not eliminated. StoreSelfMetrics.StoreInsertSql runs pg_database_size itself, so 312 executions a day become 24 — and that sweep is also awaited on the serial thread, so what changes is the frequency and the budget, not the isolation. The ~31,000x figure is the single read's latency on that path and never the change's overall effect.

The stall displaces less than the strong version of the claim implies. SweepWatchdogSeconds clocks per-server collection bodies from their own launch rather than clocking this loop, so 2.5 s here consumes no watchdog budget and delays no already-launched body. What it does is stretch one tick in twenty from 15 s to ~17.5 s. I asserted the watchdog was the bound this bit against; it is not, and #3204 records that SerialLoopSeconds' own doc comment makes the same error with a green pin enforcing it.

The beat model in the body stays refuted, and it did not need replacing. With the call already consuming 42–75% of its budget at rest, no mechanism has to create the timeouts periodically — what varies is only whether anything is competing. The clustering question is still open and the fix never depended on it.

Raising the deadline was closed arithmetically rather than by preference: the shared constant is pinned at 10 sites × N < 60 s, so N < 6, and a private constant for this one call caps at 14 s with nothing measured saying 14 is enough.

Also from working this: two of the new pins could not fail, and neither was findable by reading them — an Assert.DoesNotContain over source whose transform had already removed the pattern it asserted absent, and a negative census whose loop body never runs on a population that correctly contains nothing. Both now carry positive controls over a planted body. And the pin that should have caught this defect counts deadlines rather than read cost, which is why it stayed green for the defect's entire life.