From 2d5f214935045424738d111bcbac1d076dc04729 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Wed, 19 Aug 2026 09:34:26 +0000 Subject: [PATCH] Bound the per-database watermark read to the clamp horizon With #2333's catalog walk gone, the per-database split named the phase that does not subside after catch-up: wm, 1-3s per database per cycle. It is a read against OUR store, not the monitored server -- an unbounded MAX over a non-partitioning timestamp, so it touches every chunk that database has. Measured on the live use1 store (106 GB, 5 chunks), same server/database pair: unbounded, cold: 25,766 buffer reads + 195 written (temp spill) unbounded, warm: 228 ms bounded to 3h: 29 ms, 5 chunks excluded The unbounded cost is a function of store size and cache residency rather than of the monitored workload, so it degrades precisely where an operator is weakest: a long-lived store, a busier Query Store, slower disks. The bound changes no answer, and that is the whole justification: every consumer ends at max(stored, now - MaxCatchup), because ClampCatchup floors anything older and a null result falls back to query_store's 60-minute first-run window -- the same instant as the floor. So a row below the horizon cannot move the result whether it is found or not, and the unbounded MAX was paying to confirm a value the clamp would have produced anyway. The predicate goes on collection_time (the partitioning column) because a predicate on the watermark column alone prunes nothing, and a row's watermark can never exceed its own collection_time, so nothing qualifying hides behind it. Bounded for query_store ONLY, on both hosts, name-guarded like the other query_store-specific behavior in these runners: a ring-buffer collector whose legitimate catch-up spans days must keep reading its whole history, and the floor would silently truncate it. WatermarkPolicy.ReadFloor carries the reasoning and the measurements; its tests pin that the floor sits strictly older than the clamp horizon and that a buried watermark and a not-found one reach the same instant. Closes #2344 Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 4 +- .../DarlingCollectorRunner.cs | 43 +++++++++++++++-- Lite.Tests/WatermarkPolicyTests.cs | 48 +++++++++++++++++++ ...RemoteCollectorService.DefinitionRunner.cs | 16 ++++++- Lite/Services/RemoteCollectorService.cs | 21 +++++++- .../WatermarkPolicy.cs | 35 ++++++++++++++ 6 files changed, 156 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4d11b323f..fcc09a608 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,7 +13,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed - **The store's scale test no longer asserts that TimescaleDB compresses more rows in more time** ([#2266] item 1, measured on a rig) - `ScaleTest_JobDurationGrowsWithVolume_...` required `d10 > d1` between two sub-second job durations, and it has failed on PR after PR whose diffs cannot reach it (`d1=970/d10=863`, then `d1=689/d10=689`). Fifteen consecutive runs of the exact sequence against TimescaleDB 2.29/PG17 settle what no amount of reasoning from CI logs could: the chunks compress perfectly (counts go 1, 2, 3; per-day rows are exactly 2000/50000/500000 every single time), so the earlier suspicion that both runs were compressing nothing is **refuted** - but a 10x volume increase buys only ~3.2x the duration, about **85 ms** of absolute signal, because compression cost is largely fixed per run. CI's baseline for the same pair is 690-970 ms, roughly twenty times that fixed cost, so the volume-dependent component there is ~10% of the measurement's own magnitude and sits inside the run-to-run variance of launching a background worker on Windows. That is a benchmark of somebody else's compression engine on shared hardware, and no threshold, ratio or volume rescues it: at ~0.19 ms per thousand rows it would take millions of rows per chunk to clear a variance nobody has measured on the platform that actually fails. The byte-identical pair was never as improbable as it looked either, because that pair is only ever read when the test FAILS, which selects for differences already near zero. **It is replaced by something strictly stronger, not weaker**: each measured run must have compressed the chunk its own seed created, and that chunk must hold exactly the seeded row count - exact counts instead of two timings. A negative control proves the difference rather than assuming it. Seed the 10x rows into a chunk that is not yet compression-eligible and the old assertion fails and the new ones fail too, naming `compressed=2`; but seed them into the **1x chunk** and the old assertion **passes 3/3 with a 6-8x ratio** while the fixture has quietly stopped producing two chunks at two volumes, and only the new assertions catch it (`rows=[2000,550000]`, `total=2`). So the shipped assertion was not merely flaky, it was blind to the fixture defect it was supposed to be guarding. What the product owns is asserted and unchanged: a real duration is measured, the V56 series records both readings in order, and the real evaluator fires the [#2136] cadence alert from a real reading. One gap closed on the way past - `d10 > 0` was never asserted, and `ReadJobDurationMsAsync` maps a NULL duration to 0, so a 10x run whose duration was unmeasurable satisfied the telemetry check as `0 == 0` and passed. The test is renamed to stop claiming what it no longer measures. - **The service now says WHY it cannot start when it is installed somewhere its own account cannot read** ([#2185]) - the last open half of the reported failure. #2186 decoded the loader status, #2197 stopped the missing-credential message from advising a restart that cannot help, and #2187 taught `install-darling.ps1` to refuse a user-profile or network install root - but the installer only guards installs that go through it, and the README's manual `sc create` path (or any hand-registered exe) bypasses it entirely. Those installs still reached the reporter's experience: an empty `Output:`, a bare exit code, then a missing `pg-admin-credential.dpapi` and advice to start the service once, which they had. The service now classifies its own install directory as the FIRST thing `ExecuteAsync` does - ahead of reading `darling.json`, which an unreadable tree also takes out, and long before the managed-Postgres bootstrap - and logs one critical line naming the offending path, the account it is actually running as, why a virtual service account cannot read that location, and where to move it. It diagnoses and continues rather than refusing to start, the same asymmetry the installer applies to an upgrade and for the same reason (#2187's rejected option 2: an operator may have granted the tree read + execute by hand, and stranding a deployment that runs today would be worse than the disease). Silent on a console run - an interactive run IS the profile owner, and test-driving the exe from a Desktop folder is something the README suggests - and unreachable on Linux/container hosts. The decision table is deliberately the installer's own (profile root from Windows rather than a hardcoded `C:\Users`, plus `%USERPROFILE%`; UNC excluding the `\\?\` long-path prefix; a drive letter whose type is network), and a new test runs BOTH implementations over ONE table under Windows PowerShell 5.1 so the two cannot drift apart silently. - +- **The per-database watermark read was an unbounded MAX over every chunk in retention** ([#2344]) - with #2333's catalog walk gone, the per-database log split exposed the phase that does NOT subside after catch-up: `wm`, at 1-3 seconds per database per cycle. It is not a query against the monitored server at all - it is `SELECT MAX(last_execution_time) FROM query_store_stats WHERE server_id = ? AND database_name = ?` against OUR store, and because the hypertable partitions on `collection_time`, a MAX over a different timestamp with no time predicate touches every chunk that database has. Measured on the live 106 GB use1 store: **25,766 buffer reads plus temp spill cold, 228 ms warm, against 29 ms bounded** with five chunks excluded - and the unbounded cost scales with STORE SIZE and cache residency rather than with anything the monitored server is doing, so it degrades exactly where an operator is weakest (long-lived store, busier Query Store, slower disks). The read is now bounded on the partitioning column, which is provably free: every consumer ends at `max(stored, now - MaxCatchup)` because the clamp floors anything older and a null result falls back to the same 60-minute instant, so a row below the horizon cannot change the answer whether it is found or not. Bounded for query_store ONLY, on both hosts - a ring-buffer collector whose legitimate catch-up spans days must keep reading its full history, so the clamp and the bound travel together. ## [3.5.0] - 2026-08-19 @@ -2794,7 +2794,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#2220]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2220 [#2228]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2228 [#2218]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2218 -[#2266]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2266 [#2235]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2235 [#2165]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2165 [#2255]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2255 @@ -2811,6 +2810,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#2246]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2246 [#2319]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2319 [#2340]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2340 +[#2344]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2344 [#2331]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2331 [#2181]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2181 [#2317]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2317 diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index 60af52503..d0dd78424 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs @@ -430,9 +430,16 @@ store round-trips on cancellationToken made THIS loop — the one the field repo specifically: a budget expiry abandons the whole pass, so the watermark does not advance, the clamp is re-derived next cycle, and the hole is re-recorded (merged wider with any already pending) rather than lost. */ + /* #2344: same bound as the enumerated arm. Safe here for the same reason and + by a different route — this branch does not clamp itself, but query_store's own + BuildCutoffParameters does (the #1836 double-clamp the policy documents), so the + value this read returns is clamped before anything uses it. */ + var azureReadFloor = string.Equals(definition.Name, QueryStoreCollector.Instance.Name, StringComparison.Ordinal) + ? WatermarkPolicy.ReadFloor(collectionTime) + : null; context.Watermark = await GetLastCollectedTimeForDatabaseAsync( server.ServerId, definition.TargetTable, definition.WatermarkColumn!, - definition.PerDatabaseWatermarkColumn!, databaseName, dbToken); + definition.PerDatabaseWatermarkColumn!, databaseName, dbToken, azureReadFloor); /* #2111 adaptive shrink, Azure arm — tighten BEFORE BuildQuery: the definition's own clamp only floors OLDER watermarks, so a tighter one @@ -745,9 +752,17 @@ would otherwise be silently counted as row-streaming time. Measured here so DrainMsFrom can subtract it; the whole point of the split is that each number names one real phase. */ var watermarkWatch = Stopwatch.StartNew(); + /* #2344: bound the read for the ONE collector whose value is clamped right + below. Name-guarded rather than applied to every enumerating definition, + for the reason WatermarkPolicy's remarks give: a ring-buffer source whose + legitimate catch-up spans days must keep reading its whole history, and the + floor would silently truncate it. The clamp and the bound travel together. */ + var readFloor = string.Equals(definition.Name, QueryStoreCollector.Instance.Name, StringComparison.Ordinal) + ? WatermarkPolicy.ReadFloor(collectionTime) + : null; var raw = await GetLastCollectedTimeForDatabaseAsync( server.ServerId, definition.TargetTable, definition.WatermarkColumn!, - definition.PerDatabaseWatermarkColumn!, item, ct); + definition.PerDatabaseWatermarkColumn!, item, ct, readFloor); var clamped = WatermarkPolicy.ClampCatchup(raw, collectionTime); if (raw.HasValue && clamped != raw) { @@ -2076,17 +2091,35 @@ public async Task WriteBackfillBatchAsync( /// value for ONE database, for definitions with a PerDatabaseWatermarkColumn (Azure SQL DB /// per-database XE capture, #1535). Null on first run for that database or on failure — the /// caller falls back to the definition's documented window. + /// + /// bounds the read on collection_time — the + /// PARTITIONING column, so the bound actually prunes chunks (#2344). Null keeps the unbounded + /// behaviour, which is correct for any reader whose watermark is NOT clamped; pass + /// only from a caller whose value is, and read that method's + /// remarks for why the bound provably changes no answer. Unbounded, this is a MAX over a + /// non-partitioning column with no time predicate — every chunk in retention, per database, per + /// cycle, at a cost that grows with the store rather than the workload. /// public async Task GetLastCollectedTimeForDatabaseAsync( - int serverId, string tableName, string columnName, string databaseColumnName, string databaseName, CancellationToken cancellationToken) + int serverId, string tableName, string columnName, string databaseColumnName, string databaseName, + CancellationToken cancellationToken, DateTime? collectedSince = null) { try { await using var connection = await _postgres.OpenConnectionAsync(cancellationToken); - using var command = new NpgsqlCommand( - $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2", connection); + var sql = collectedSince is null + ? $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2" + : $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2 AND collection_time > $3"; + using var command = new NpgsqlCommand(sql, connection); command.Parameters.AddWithValue(serverId); command.Parameters.AddWithValue(databaseName); + if (collectedSince is DateTime floor) + { + /* Naive like every other timestamp bound in this store (#1969): a Utc Kind infers + timestamptz and Postgres would convert it into the session zone on the way in. */ + command.Parameters.AddWithValue(DateTime.SpecifyKind(floor, DateTimeKind.Unspecified)); + } + var result = await command.ExecuteScalarAsync(cancellationToken); if (result is DateTime dt) { diff --git a/Lite.Tests/WatermarkPolicyTests.cs b/Lite.Tests/WatermarkPolicyTests.cs index 329ce2bf5..b610e29b4 100644 --- a/Lite.Tests/WatermarkPolicyTests.cs +++ b/Lite.Tests/WatermarkPolicyTests.cs @@ -83,4 +83,52 @@ clamp sat far above the cost tipping point on big databases and never interrupte Assert.Equal(TimeSpan.FromHours(1), WatermarkPolicy.MaxCatchup); Assert.Equal(QueryStoreBackfillState.MaxSliceSpan, WatermarkPolicy.MaxCatchup); } + + /// + /// #2344: the read floor must sit STRICTLY OLDER than the clamp horizon, because that ordering is the + /// whole safety argument. A floor at or newer than the horizon could hide a row the clamp would have + /// honoured; older by any margin cannot, since every outcome is max(stored, now - MaxCatchup) and a row + /// below the horizon produces the same answer found or not. + /// + [Fact] + public void ReadFloor_SitsStrictlyOlderThanTheClampHorizon() + { + var floor = WatermarkPolicy.ReadFloor(Now); + + Assert.NotNull(floor); + Assert.True(floor < Now - WatermarkPolicy.MaxCatchup, + "the read floor must be older than the clamp horizon, or the bound could hide a row the clamp would honour"); + Assert.Equal(Now - WatermarkPolicy.MaxCatchup - WatermarkPolicy.ReadFloorMargin, floor); + } + + /// + /// The equivalence the bound rests on, stated as a test rather than a comment: for any watermark at or + /// below the read floor, the CLAMPED result is the horizon — identical to what the caller derives when + /// the bounded read returns nothing at all (null falls back to query_store's 60-minute window, which is + /// the same instant as the horizon). So bounding the read cannot change a single caller's outcome. + /// + [Theory] + [InlineData(4)] + [InlineData(6)] + [InlineData(48)] + [InlineData(24 * 90)] + public void AnyWatermarkBelowTheReadFloor_ClampsToTheSameInstantAsFindingNothing(int hoursOld) + { + var floor = WatermarkPolicy.ReadFloor(Now)!.Value; + var buried = Now.AddHours(-hoursOld); + Assert.True(buried <= floor, "fixture must sit at or below the read floor"); + + /* Found-but-old and not-found-at-all reach the same place. */ + var clampedIfFound = WatermarkPolicy.ClampCatchup(buried, Now); + Assert.Equal(Now - WatermarkPolicy.MaxCatchup, clampedIfFound); + Assert.Equal(Now.AddMinutes(-60), clampedIfFound); + Assert.Null(WatermarkPolicy.ClampCatchup(null, Now)); + } + + /// A default input yields no floor — callers pass it straight through as "unbounded". + [Fact] + public void ReadFloor_OnDefault_IsNull() + { + Assert.Null(WatermarkPolicy.ReadFloor(default)); + } } diff --git a/Lite/Services/RemoteCollectorService.DefinitionRunner.cs b/Lite/Services/RemoteCollectorService.DefinitionRunner.cs index a8ab74417..9df6ec313 100644 --- a/Lite/Services/RemoteCollectorService.DefinitionRunner.cs +++ b/Lite/Services/RemoteCollectorService.DefinitionRunner.cs @@ -249,9 +249,14 @@ store round-trips on cancellationToken made THIS loop — the one the field repo specifically: a budget expiry abandons the whole pass, so the watermark does not advance, the clamp is re-derived next cycle, and the hole is re-recorded (merged wider with any already pending) rather than lost. */ + /* #2344: same bound as the enumerated arm, safe by the other route — this + branch does not clamp itself, but query_store's BuildCutoffParameters does. */ + var azureReadFloor = string.Equals(definition.Name, QueryStoreCollector.Instance.Name, StringComparison.Ordinal) + ? WatermarkPolicy.ReadFloor(collectionTime) + : null; context.Watermark = await GetLastCollectedTimeForDatabaseAsync( serverId, definition.TargetTable, definition.WatermarkColumn!, - definition.PerDatabaseWatermarkColumn!, databaseName, dbToken); + definition.PerDatabaseWatermarkColumn!, databaseName, dbToken, azureReadFloor); /* #2111 adaptive shrink, Azure arm — tighten BEFORE BuildQuery: the definition's own clamp only floors OLDER watermarks, so a tighter one @@ -559,9 +564,16 @@ Only query_store (the sole enumeration collector with a per-database timestamp ? null : async (item, ct) => { + /* #2344: bound the read for the ONE collector whose value is clamped on the + next line. Name-guarded rather than applied to every enumerating definition: + a ring-buffer source whose legitimate catch-up spans days must keep reading + its whole history, so the clamp and the bound travel together. */ + var readFloor = string.Equals(definition.Name, QueryStoreCollector.Instance.Name, StringComparison.Ordinal) + ? WatermarkPolicy.ReadFloor(collectionTime) + : null; var raw = await GetLastCollectedTimeForDatabaseAsync( serverId, definition.TargetTable, definition.WatermarkColumn!, - definition.PerDatabaseWatermarkColumn!, item, ct); + definition.PerDatabaseWatermarkColumn!, item, ct, readFloor); var clamped = WatermarkPolicy.ClampCatchup(raw, collectionTime); if (raw.HasValue && clamped != raw) { diff --git a/Lite/Services/RemoteCollectorService.cs b/Lite/Services/RemoteCollectorService.cs index 13bfac501..4b95f344f 100644 --- a/Lite/Services/RemoteCollectorService.cs +++ b/Lite/Services/RemoteCollectorService.cs @@ -1237,18 +1237,35 @@ protected internal static int GetServerId(ServerConnection server) /// (Azure SQL DB per-database XE capture): the newest already-collected value for ONE database, /// so each database's ring buffer dedups against its own history. Null on first run for that /// database or on failure — the caller falls back to the definition's documented window. + /// + /// bounds the read on collection_time (#2344). Null + /// keeps the unbounded behaviour, correct for any reader whose watermark is NOT clamped; pass + /// only from a caller whose value is, and read that method's + /// remarks for why the bound provably changes no answer. Unbounded, this is a MAX over the + /// whole of a database's history every cycle — measured at multiple seconds per database on the + /// Darling twin's larger store, and the same shape here. DuckDB does not partition the way the + /// Postgres store's hypertables do, so the win is min-max index pruning and a smaller scan rather + /// than chunk exclusion, but the predicate is the same and so is the argument for it. /// protected async Task GetLastCollectedTimeForDatabaseAsync( - int serverId, string tableName, string columnName, string databaseColumnName, string databaseName, CancellationToken cancellationToken) + int serverId, string tableName, string columnName, string databaseColumnName, string databaseName, + CancellationToken cancellationToken, DateTime? collectedSince = null) { try { using var conn = _duckDb.CreateConnection(); await conn.OpenAsync(cancellationToken); using var cmd = conn.CreateCommand(); - cmd.CommandText = $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2"; + cmd.CommandText = collectedSince is null + ? $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2" + : $"SELECT MAX({columnName}) FROM {tableName} WHERE server_id = $1 AND {databaseColumnName} = $2 AND collection_time > $3"; cmd.Parameters.Add(new DuckDB.NET.Data.DuckDBParameter { Value = serverId }); cmd.Parameters.Add(new DuckDB.NET.Data.DuckDBParameter { Value = databaseName }); + if (collectedSince is DateTime floor) + { + cmd.Parameters.Add(new DuckDB.NET.Data.DuckDBParameter { Value = floor }); + } + var result = await cmd.ExecuteScalarAsync(cancellationToken); if (result is DateTime dt) return dt; diff --git a/PerformanceMonitor.Collectors/WatermarkPolicy.cs b/PerformanceMonitor.Collectors/WatermarkPolicy.cs index 31881a315..16be1e958 100644 --- a/PerformanceMonitor.Collectors/WatermarkPolicy.cs +++ b/PerformanceMonitor.Collectors/WatermarkPolicy.cs @@ -72,4 +72,39 @@ public static class WatermarkPolicy var floor = now - MaxCatchup; return watermark.Value < floor ? floor : watermark; } + + /// + /// Extra history the watermark READ may look at beyond (#2344). Purely a + /// safety margin for clock disagreement between a monitored server and the store — the correctness + /// argument needs none of it, so it is generous rather than tuned. + /// + public static readonly TimeSpan ReadFloorMargin = TimeSpan.FromHours(2); + + /// + /// The oldest collection_time a clamped watermark read has to consider (#2344), or null when + /// is default — callers pass this straight through to the store read as an + /// optional bound. + /// + /// Why bounding the read changes no answer. Every consumer of a clamped watermark ends + /// up at max(stored, now - MaxCatchup): floors anything older, and a + /// NULL result falls back to query_store's documented 60-minute first-run window — the same instant as + /// the floor. So a row older than the horizon cannot move the result whether it is found or not, and + /// the unbounded MAX that used to find it was paying to confirm a value the clamp would have + /// produced anyway. Measured on the 106 GB use1 store: 25,766 buffer reads plus temp spill cold, 228 ms + /// warm, against 29 ms bounded (five chunks excluded) — and the unbounded cost scales with STORE SIZE + /// and cache residency rather than with anything the monitored server is doing, so it degrades exactly + /// where an operator is weakest. + /// + /// Bound the PARTITIONING column, not the watermark column. The hypertables partition on + /// collection_time; a predicate on the watermark column alone prunes nothing. This is safe + /// because a row's watermark value can never exceed its own collection_time — an execution + /// cannot be collected before it happens — so no qualifying row hides behind the bound. + /// + /// Only for readers whose value is clamped. The clamp is scoped to query_store (see the + /// class remarks); a ring-buffer collector whose legitimate catch-up spans days must keep reading its + /// full history, and handing it this floor would silently truncate that. A future definition wanting + /// the bound has to adopt first — the two travel together. + /// + public static DateTime? ReadFloor(DateTime now) => + now == default ? null : now - MaxCatchup - ReadFloorMargin; }