What
DarlingCollectorRunner.GetLastCollectedTimeAsync (the server-scoped watermark read) runs:
SELECT MAX(<watermark_column>) FROM <table> WHERE server_id = $1
with 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
collectedSince bound to GetLastCollectedTimeAsync, mirroring GetLastCollectedTimeForDatabaseAsync, and pass WatermarkPolicy.ReadFloor(collectionTime) from the caller under the same QueryStoreCollector name guard the per-database path already uses. The guard matters for the reason WatermarkPolicy'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
CommandTimeout explicitly 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.
What
DarlingCollectorRunner.GetLastCollectedTimeAsync(the server-scoped watermark read) runs:with no predicate on
collection_time— the hypertable's partitioning column. So it scans every chunk in retention for that server, on every collector cycle.#2344fixed exactly this defect, but only in the per-database siblingGetLastCollectedTimeForDatabaseAsync.QueryStoreCollectordeclares bothWatermarkColumnandPerDatabaseWatermarkColumn, so both reads run and the server-scoped one kept paying the unbounded cost.Measured on the use1 monitoring host
query_store_statsis 62.5 GB across 19 chunks (24 h chunk interval,collection_timepartitioning, retentiondrop_after: 4 days).WatermarkPolicy.ReadFloor(now − 3 h)Npgsql's default
CommandTimeoutis 30 s, and noCommandTimeoutwas 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:
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
catchswallowed the exception with/* If the Postgres query fails, caller uses fallback window */and no log line. A cancelled read returnsnull, andnullis 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_logor 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 throwsException while reading from stream, which is the message on 146Failed to check forced-plan failuresand 22PgAnomalyDetectorERROR lines the same day. Timestamps correlate tightly — PG cancel20:53:30.040→ app ERROR20:53:30.132.Fix
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.CommandTimeoutexplicitly instead of inheriting Npgsql's 30 s.Losslessness is not argued from a sample:
WatermarkPolicyTests.AnyWatermarkBelowTheReadFloor_ClampsToTheSameInstantAsFindingNothingalready 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
#2344pinned 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_idtwin,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.DarlingAlertReadAdapterhas 18NpgsqlCommands and zeroCommandTimeouts;StoreConfigProvider13/0;PgAlertStateStore9/0 — all on Npgsql's 30 s default. Worth a follow-up audit; not folded in here.