Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This removes the [#2266]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2266 link-reference definition, but [#2266] is still referenced three times elsewhere in this file (lines ~30, ~38, ~46 in the new version, in the entries for the scale-test reporting fix, the skipped-maintenance-cycle log line, and the heal-test flakiness fix). With the definition gone, those three occurrences will render as literal [#2266] text instead of links to the issue. Looks like an unintended deletion — please restore the line (or drop it back in alongside the [#2344] addition) rather than removing it.

[#2235]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2235
[#2165]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2165
[#2255]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2255
Expand All @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Comment on lines +433 to +439

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bounding the read here can silently drop a real backfill hole. ReadFloor's "found vs. not-found reach the same clamped instant" argument only covers the value that flows into BuildCutoffParameters/ClampCatchup. But the adaptive-shrink block right below this (lines ~449-475) also consumes the raw watermark for a different purpose: if context.Watermark is DateTime azureRaw is true, a stale azureRaw gets recorded via RecordQueryStoreBackfillHoleAsync(..., azureRaw, tighterFloor, ...) so the backfill worker knows to trickle in the real gap.

If the true stored watermark is older than ReadFloor (now - 3h) — e.g. this database has been failing for a while, or the service just came back from being down for days (the original #1556 scenario) — the bounded read now returns null where it used to return the true stale timestamp. That flips execution into the else branch at line ~466, which explicitly records no hole ("pre-watermark history is the tail's job") and skips the clamp WARNING too. So for the exact outage-recovery case this whole system was built for, the real historical gap now goes unrecorded and unlogged, whereas before this PR it would have been correctly captured.

Worth considering: either read the raw watermark unbounded specifically for this hole-recording path, or explicitly detect "found nothing because it's outside the read floor" vs. "genuinely never collected" so the hole can still be recorded (even if only approximately, e.g. from the read floor itself).

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
Expand Down Expand Up @@ -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;
Comment on lines +755 to +762

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same issue as the Azure arm above, on this enumerated path: with the bound in place, raw comes back null instead of a true-but-stale watermark once it's older than now - 3h. That skips the raw.HasValue && clamped != raw block entirely (line ~767) — no WARNING, no RecordQueryStoreBackfillHoleAsync call for the real gap — and then the adaptive-shrink block below (line ~793) falls into the "never-succeeded" branch, which also records no hole by design. A multi-hour+ outage's history gap now goes unrecorded/unlogged where the unbounded read used to catch it correctly.

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)
{
Expand Down Expand Up @@ -2076,17 +2091,35 @@ public async Task<int> WriteBackfillBatchAsync<TRow>(
/// 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.
///
/// <para><paramref name="collectedSince"/> bounds the read on <c>collection_time</c> — 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
/// <see cref="WatermarkPolicy.ReadFloor"/> 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 <c>MAX</c> 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.</para>
/// </summary>
public async Task<DateTime?> 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)
{
Expand Down
48 changes: 48 additions & 0 deletions Lite.Tests/WatermarkPolicyTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

/// <summary>
/// #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.
/// </summary>
[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);
}

/// <summary>
/// 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.
/// </summary>
[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));
}

/// <summary>A default input yields no floor — callers pass it straight through as "unbounded".</summary>
[Fact]
public void ReadFloor_OnDefault_IsNull()
{
Assert.Null(WatermarkPolicy.ReadFloor(default));
}
}
16 changes: 14 additions & 2 deletions Lite/Services/RemoteCollectorService.DefinitionRunner.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Comment on lines +252 to +256

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lite's twin of the same issue flagged on Darling's Azure arm: ReadFloor's safety argument covers the clamped instant, not the raw watermark that the adaptive-shrink block below (line ~264 onward) uses to decide whether/how to call RecordQueryStoreBackfillHoleAsync. Once the true stored watermark predates the read floor (now - 3h), the bounded read returns null, the code takes the "never-succeeded" branch at line ~281, and the real gap goes unrecorded with no WARNING — for exactly the extended-outage scenario this backfill machinery exists to handle.

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
Expand Down Expand Up @@ -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;
Comment on lines +567 to +573

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same issue on the enumerated arm: once the true stored watermark is older than the read floor, raw comes back null, skipping both the WARNING/hole-record at line ~578 and falling into the no-hole "never-succeeded" branch of the adaptive-shrink block at line ~614 — silently dropping the real gap for a database that's been failing/down for more than ~3 hours.

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)
{
Expand Down
Loading
Loading