Repository navigation
The watermark read is an unbounded MAX over every chunk in retention — 1-3s per database per cycle, and it scales with store size, not workload #2344
Description
Filed off the #2333 post-install measurement. With the plan-fetch walk gone, the per-database log split shows the phases that remain, and one of them does not subside after catch-up: wm, running 1–3 seconds per database per cycle on the use1 primaries box.
wm is not a query against the monitored SQL Server. It is a read against our own store:
SELECT MAX(last_execution_time) FROM query_store_stats WHERE server_id = $1 AND database_name = $2(DarlingCollectorRunner.GetLastCollectedTimeForDatabaseAsync.) query_store_stats is a hypertable partitioned on collection_time, so a MAX over a different timestamp column with no time predicate has to touch every chunk in retention for that (server, database).
Measured on the live use1 store (106 GB, 5 chunks, 42 primaries)
Same server/database pair, EXPLAIN (ANALYZE, BUFFERS), current form vs. the same query with a collection_time predicate added:
| current (unbounded) | bounded to 3h | |
|---|---|---|
| cold (first touch) | 25,766 buffer reads + 195 written (temp spill) | 5 chunks excluded, 29 ms |
| warm (cache primed) | 228 ms | 29.5 ms |
Warm is a 7.7x difference. The cold row is the one that matters for the field: ~200 MB of physical I/O per database per cycle, and the cost is a function of store size and cache residency, not of anything the monitored server is doing. So it degrades exactly where a customer is weakest — a long-lived store, a busier Query Store, slower disks, a box whose cache is not dominated by this one query. Our dogfood store is 5 chunks; a 90-day-retention store is far more.
The bound is provably free
Every consumer of this value ends up at max(stored, now - 1h):
WatermarkPolicy.MaxCatchupis 1 hour, andClampCatchupfloors anything older tonow - 1h.- A null result falls back to the definition's documented first-run window, which is 60 minutes (
QueryStoreCollector.BuildCutoffParameters) — the same instant.
So a row whose last_execution_time is older than an hour cannot change the answer: found or not found, the caller proceeds from now - 1h. Adding a time predicate is therefore behaviour-identical, not an approximation — the first thing to check when this is implemented, because "identical" is the whole justification.
Fix shape
- Bound the read on the partitioning column (
collection_time), which is what enables chunk exclusion — a predicate onlast_execution_timealone would not prune. A row'slast_execution_timecannot exceed itscollection_time(you cannot collect an execution from the future), socollection_time > now() - margincannot hide a qualifying row. Use a margin comfortably wider thanMaxCatchup(3h against a 1h horizon) so clock skew between the monitored server and the store cannot bite. - Do not hardcode the horizon in the generic helper.
GetLastCollectedTimeForDatabaseAsyncserves any definition with aPerDatabaseWatermarkColumn; the 1-hour clamp is query_store's policy. Pass the bound in (nullable — no bound = today's behaviour) so a future collector without a clamp keeps correct semantics rather than silently inheriting a horizon it never agreed to. - Check the siblings.
GetLastCollectedTimeAsync(server-scoped) and Lite's DuckDB twin have the same unbounded-MAX shape. Lite's store is smaller but the argument is identical, and a fix on one SKU only is the drift this codebase keeps paying for. - While here:
idx_query_store_stats_server_db_query_plan_timeexists but is not serving this MAX. Worth checking whether the bounded form wants a supporting index or whether chunk exclusion alone is enough — the measurement above says exclusion alone gets it to 29 ms, so an index is probably unnecessary write tax.
Why this is worth doing before the release
Erik's framing: "there's no accounting for local factors, e.g. busier query stores, worse hardware." This particular multi-second cost is not the customer's SQL Server at all — it is our store, it scales with how long they have been running, and it is removable by adding a predicate that provably cannot change the answer. That is the cheapest juice left in the collection path.
Activity
Bound the per-database watermark read to the clamp horizon
Bound the per-database watermark read to the clamp horizon
Bound the per-database watermark read to the clamp horizon
Bound the query_store watermark read to the window the clamp can actu…
erikdarlingdata commentedon Aug 19, 2026
Fixed in #2346.
The per-database watermark read is now bounded to
now - MaxCatchup - ReadFloorMarginoncollection_time, so TimescaleDB can exclude chunks instead of scanning every one in retention to compute a MAX.The equivalence is exact, not approximate: every consumer of a clamped watermark lands on
max(stored, now - MaxCatchup), becauseClampCatchupfloors anything older and a NULL result falls back to query_store's documented 60-minute first-run window — the same instant. A row below the floor therefore cannot change the answer whether it is found or not, which is what makes declining to look for it free rather than a trade-off.Two details that were easy to get wrong and are worth recording:
collection_time— an execution cannot be collected before it happens — so no qualifying row hides behind the bound.Falsifiable prediction to check after the nightly lands on use1:
wmon the worst server drops from the 1–3s it sits at now to roughly 30ms, taking that server's Query Store phase from ~9.3s to ~5.5s. I will post the measured split rather than assume it.Related, found on the way: #2351 is the same unbounded-MAX shape in the alert read adapter, 11 times over.
erikdarlingdata commentedon Aug 19, 2026
Pre-registering the baseline before the fix is installed, so the comparison afterwards is a prediction rather than a story fitted to whatever the numbers do.
use1, 30-minute window ending 2026-08-19 10:33 UTC, 223 query_store collections, catch-up substantially drained:
wmopenplan_fetchtext_fetchAll milliseconds.
wmis 20.5% of total collection time across the window.A correction to my own earlier number. I said
wmwas up to 42% of the worst server's time. That was true of a single worst sample and I should not have let it stand as the headline — aggregated over 223 runs it is 20.5%, and that is the figure to predict against. The single-sample number made the case look stronger than the evidence supports.Prediction:
wmavg drops from 986ms to roughly 30ms (the bounded read measured 29ms against 228ms warm on the 106 GB store), taking total avg from 4,809ms to about 3,850ms — a ~20% cut in Query Store collection time, on top of the ~6x the activity-driven fetch already delivered. Ifwmdoes not fall below ~100ms, the bound is not being applied and I want to know that rather than average it away.Two things I am NOT predicting, so they do not get quietly credited to this change:
plan_fetchandtext_fetchare still draining backlog and will keep falling on their own, and thattext_fetchmax of 100.5s is a real outlier I have not explained yet. Neither is this fix's doing.Also worth stating: total avg has gone 46.2s → 7.7s → 4.8s over the morning purely as catch-up drains, so any measurement taken after the install has to account for that trend rather than attribute it all to the bound. The
wmcolumn is the clean read, because it is the one phase that does not subside with backlog.erikdarlingdata commentedon Aug 19, 2026
Measured after installing
3.5.0-nightly.20260819on use1. The prediction was half wrong and I want that on the record.Same box, same log parsing, same phase split. Baseline is the 30-minute window I pre-registered before installing; "after" is a 6-minute window starting 11:05.
wmopenplan_fetchtext_fetchwmshare of total collection time: 20.5% → 8.3%.What I got right and what I got wrong
Right:
wmwas the phase to attack, and bounding the read moved it. Average down 2.7x, median down 3x, p95 down 2.6x, and the tail max down from 4.7s to 2.1s. The mechanism is doing what the change claims.Wrong: I predicted
wmwould fall to roughly 30ms. It fell to 367ms — off by about 12x. I took the 29ms from a bounded query measured in isolation on a warm cache and treated it as the production figure. In production that read is one of many concurrent queries against a busy store, it carries connection acquisition and round-trip, and it runs per-database across 42 servers at once. An isolated query timing is a floor, not a forecast, and I presented it as a forecast.The stated falsification threshold was "if
wmdoes not fall below ~100ms, the bound is not being applied". By that line I would have to call this a failure, and that would be the wrong conclusion — the threshold was badly chosen, derived from the same isolated measurement. The bound is clearly applied: a 2.7x drop with the tail compressing is not what an unbounded scan looks like. But I set the threshold before seeing the data specifically so I could not move it afterwards, so I am recording that I got it wrong rather than quietly restating it.What this does NOT show yet
Total collection time is roughly flat, and that comparison is not fair to either side. The "after" window starts 6 minutes post-restart, which carries a catch-up burst; the "before" window had a morning of catch-up already drained.
plan_fetchreading higher afterwards is almost certainly that burst rather than a regression. Withwmat 20% of the total, the arithmetic ceiling on this change was always ~12% off the total anyway.Re-measuring on a 30-minute window well clear of the restart before claiming anything about the total.
Where the time actually goes now
With
wmdown to 8.3%, the remaining split isplan_fetch~48%,text_fetch~28%,open~13%.plan_fetchandtext_fetchare still draining backlog and should keep falling on their own.open— the monitored server's own#pm_qs_sliceaggregate — is flat at ~550ms and is the next honest target, since it is the one phase that runs on the customer's hardware rather than ours.erikdarlingdata commentedon Aug 19, 2026
Longer window, and it walks back the number I posted an hour ago. The 6-minute sample was too small and too flattering.
use1, window from 11:05, now n=138 over ~22 minutes:
wmopenplan_fetchtext_fetchAverages in ms.
wmshare of total: 20.5% → 10.1%.wmis 636ms, not the 367ms I reported. Same box, same install, larger sample — the earlier figure was a 66-run window and I should have waited. The improvement over the 986ms baseline is 1.55x, not the 2.7x I posted. That is still a real gain and the share of total still halved, but I have now quoted three different numbers for this phase today and the largest sample is the only one worth keeping.Total collection time is UP, not down — 6,289ms against a 4,809ms baseline. That is the post-restart catch-up burst I flagged, and
plan_fetchcarries it (avg 3,309, with a 116-second outlier in the window). It is not a regression from this change, and it is also not something I can prove is not a regression from this window. A clean read needs the box well clear of the restart.So the honest state of #2344: the mechanism works and
wmhalved as a share of collection time. Everything I have said about the total is still unsupported in both directions. Re-measuring after the box has been up for several hours, and that measurement is the one that should be quoted.Bound PLAN_REGRESSION on the partitioning column too (#2390)
Carry the timeout and the log line to both watermark siblings (#2795)
Give every fact-collector read an explicit command deadline (Fixes #2810
Bound the server-scoped watermark read on the partitioning column (er…
Make PR CI run the cross-app parity guards it was skipping (erikdarli…
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…