Repository navigation
Server-scoped watermark read is unbounded, times out, and silently degrades every collector to its fallback window #2795
Description
What
DarlingCollectorRunner.GetLastCollectedTimeAsync (the server-scoped watermark read) runs:
SELECT MAX(<watermark_column>) FROM <table> WHERE server_id = $1with no predicate on collection_time — the hypertable's partitioning column. So it scans every chunk in retention for that server, on every collector cycle.
#2344 fixed exactly this defect, but only in the per-database sibling GetLastCollectedTimeForDatabaseAsync. QueryStoreCollector declares both WatermarkColumn and PerDatabaseWatermarkColumn, so both reads run and the server-scoped one kept paying the unbounded cost.
Measured on the use1 monitoring host
query_store_stats is 62.5 GB across 19 chunks (24 h chunk interval, collection_time partitioning, retention drop_after: 4 days).
| form | time |
|---|---|
| unbounded (shipped) | 50,560 ms / 40,743 ms cold, 9,279 ms warm |
bounded at WatermarkPolicy.ReadFloor (now − 3 h) |
2,891 ms / 5,937 ms |
Npgsql's default CommandTimeout is 30 s, and no CommandTimeout was set on this command. So the read was routinely cancelled mid-flight.
The store's own PostgreSQL log for one day, grouped by the statement that followed each cancellation:
2092 x SELECT MAX(last_execution_time) FROM query_store_stats WHERE server_id = $N <- unbounded, this bug
631 x SELECT DISTINCT database_name FROM query_store_stats WHERE server_id = $N AND collection_time > $N
17 x SELECT MAX(last_execution_time) FROM query_store_stats WHERE server_id = $N AND database_name = $N AND collection_time > $N <- #2344's bounded sibling
Same store, same table, same column: 2,092 cancellations for the unbounded form against 17 for the bounded one.
Why it mattered more than the wasted time
The catch swallowed the exception with /* If the Postgres query fails, caller uses fallback window */ and no log line. A cancelled read returns null, and null is indistinguishable from a first run. So every timeout silently pushed the collector onto query_store's 60-minute fallback window instead of the ~5-minute incremental one — re-collecting data already stored, growing the table, and making the next read slower.
None of this reached collection_log or the service log. The only trace anywhere was a cancellation line in the store's own PostgreSQL log.
It also accounts for the user-visible errors: Npgsql cancels the command server-side on timeout (logged as canceling statement due to user request) and then throws Exception while reading from stream, which is the message on 146 Failed to check forced-plan failures and 22 PgAnomalyDetector ERROR lines the same day. Timestamps correlate tightly — PG cancel 20:53:30.040 → app ERROR 20:53:30.132.
Fix
- Add the
collectedSincebound toGetLastCollectedTimeAsync, mirroringGetLastCollectedTimeForDatabaseAsync, and passWatermarkPolicy.ReadFloor(collectionTime)from the caller under the sameQueryStoreCollectorname guard the per-database path already uses. The guard matters for the reasonWatermarkPolicy's remarks give: the bound is only sound where the caller clamps, and a ring-buffer source whose legitimate catch-up spans days must keep reading its whole history. - Set
CommandTimeoutexplicitly instead of inheriting Npgsql's 30 s. - Log a warning when the watermark read fails, naming the consequence, instead of swallowing it.
Losslessness is not argued from a sample: WatermarkPolicyTests.AnyWatermarkBelowTheReadFloor_ClampsToTheSameInstantAsFindingNothing already proves that any watermark at or below the read floor clamps to the same instant the caller derives when the read returns nothing, so bounding cannot change a caller's outcome.
Category, not instance
#2344 pinned the policy (WatermarkPolicyTests) but never the policy's application, which is why the sibling was missed for months with a green suite. The pin added here asserts over the method family by reflection, so a third timestamp-watermark reader is covered without anyone remembering to come back.
Not covered here
GetLastCollectedInstanceIdAsync (the bigint/instance_id twin, job_history) has the same missing timeout and the same silent catch, but reads a much smaller table and is not bounded by this guard. DarlingAlertReadAdapter has 18 NpgsqlCommands and zero CommandTimeouts; StoreConfigProvider 13/0; PgAlertStateStore 9/0 — all on Npgsql's 30 s default. Worth a follow-up audit; not folded in here.
Activity
Carry the timeout and the log line to both watermark siblings (#2795)
Don't log a service shutdown as a watermark failure (#2795)
erikdarlingdata commentedon Sep 3, 2026
Follow-up measurement on the "Not covered here" section, from the use1 monitoring host after this fix was deployed (22:54:56Z restart).
The fix worked as scoped. The unbounded
MAX(last_execution_time)form no longer appears in the store's cancellation log at all. Cancellations went from ~285/hr to ~93/hr.The remaining cancellations are now attributed — filed as #2810:
The earlier "1,673 blank STATEMENT" bucket was a parser artifact — PostgreSQL puts a multi-line statement on the lines after
STATEMENT:, so a parser reading only that line's remainder sees empty. Nothing was unattributed.The structural count in this issue understates it. This issue cites three files (18 + 13 + 9). Across all non-test, non-deprecated Darling production sources it is 35 files and 160
new NpgsqlCommandsites with noCommandTimeoutanywhere in the file — the analysis, alerting and config paths as a whole, not three classes.And the upstream cause of the slowness is operational, not code — #2809: the five
query_store*retention jobs arePausedsince 2026-08-17, soquery_store_statsholds 19 days at adrop_after: 4 dayspolicy (65 GB, 19 chunks). Every read over that table, including the one this issue bounded, is paying for ~5x the intended data. Worth fixing that before tuning any more reads.erikdarlingdata commentedon Sep 3, 2026
Resolved by #2796, merged to
dev. Closing manually:Fixes #Nonly fires on the dev->main release merge, so completed work otherwise sits open until release.Skip the server-scoped watermark read only where dispatch discards it (…
Skip the server-scoped watermark read only where dispatch discards it (…
Bound the server-scoped watermark read on the partitioning column (er…
Rewrite PlanRegressionSql dedup as GROUP BY + ordered array_agg
Document Lite's server-scoped watermark read as deliberately unbounded (
Deadline the command plane, the two budgeted loops and the reload beacon
Bound ring-buffer watermark reads to a recent window, fall back to un…