From f228e28cbcf8c6dea91c987c88af8122ac848a00 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Tue, 11 Aug 2026 01:25:53 +0200 Subject: [PATCH 1/2] Split per-database collection timing into open and drain (#2164) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A production measurement overturned this issue's premise: cutting the query_store text budget 64MB -> 12MB moved 5x fewer bytes and ~7x fewer rows while the batch clock stayed in its old band (358-480s -> 383s, 352s). So the dominant cost is upstream of shipping — but the single blended sql: number could not say WHICH statement, and the next fix (a known-hash plan skip aimed at plan-XML conversion in the FINAL select) would have been aimed at the same wrong term. ExecuteReaderAsync returns only when the first rowset is available, so timing the open separately splits the batch for free: open covers every preceding non-rowset statement — for query_store, the #pm_qs_slice aggregate — plus time-to-first-row, and the remainder is streaming. The two have different fixes, so they need to be separately visible. Zero means not measured (Lite does not measure it) and suppresses the split rather than printing open:0ms, which would read as free. Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 1 + .../StatementSplitTimingTests.cs | 80 +++++++++++++++++++ .../DarlingCollectorRunner.cs | 29 ++++++- .../CollectorContext.cs | 17 ++++ 4 files changed, 125 insertions(+), 2 deletions(-) create mode 100644 Darling/Darling.Tests/StatementSplitTimingTests.cs diff --git a/CHANGELOG.md b/CHANGELOG.md index d1f17fa0..9f26695a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added - **Every previously-hardcoded alert threshold is now a real setting** ([#2107], the split-out from gotqn's #2101 - "it was fine to hardcode these for development but any serious monitoring allows configuring of alert thresholds") - six new knobs ride the store control plane (V55), the Viewer's Settings window, and `get_alert_settings`/`update_alert_settings`, clamped on read like their siblings: the monitor store volume's self-alert warning percent (was 10), the Collection Stopped staleness window (was 30 minutes) and consecutive-failure fast path (was 10), the low-disk CRITICAL severity tier's percent and GB floors (were 3% / 2 GB - these grade the target-volume alert in BOTH apps, and Lite reads its pair from `settings.json` as `alert_disk_critical_free_percent` / `alert_disk_critical_free_gb`), and the analysis notification cooldown (was a hardcoded 360 in Darling while Lite always honored a configured value - the parity gap closed). MCP shape: `low_disk.critical_free_percent` / `low_disk.critical_free_gb`, a new `self_alerts` group, and `analysis.notify_cooldown_minutes`. +- **Per-database collection timing now separates server think-time from row streaming** ([#2164]) - the per-database Query Store line reports `sql:Xms = open:Yms + drain:Zms`, where open is everything before the first row arrives and drain is streaming those rows to the collector. This exists because of a measurement that overturned an assumption: cutting the text budget from 64 MB to 12 MB on a production server moved 5x fewer bytes and roughly 7x fewer rows, and the batch clock did not move at all. That says the cost lives upstream of shipping - in Query Store's own aggregation before the first row - which no client-side budget or payload trimming can shorten. The blended number could not show that, so the split is now visible: a pass that is nearly all `open` needs the server-side query narrowed, and a pass that is mostly `drain` is the one a smaller budget or a shorter network path helps. - **The two collector memory bounds are now operator knobs** ([#2164], [#2170]) - the per-database Query Store text budget (was a hardcoded 64 MB) and the fleet sweep width (was a hardcoded 4 servers) ride the store control plane (V59), the Viewer's Settings window, and the service's live reload, clamped [4,256] MB and [1,16] on read. Defaults reproduce the old constants exactly, so an upgrade changes nothing until a dial moves. Why both at once: peak transient memory is roughly the two multiplied, so an operator moving one needs the other in front of them. Lower the budget when the monitored fleet is a network hop away - the budget bounds memory, but it also sets how long one collector query holds the monitored server open draining to the client, which over a cross-region link is the tenant-visible cost (a smaller budget trades catch-up latency for shorter statements, never data, because every cut is resumable). Raise the sweep width when a large fleet queues behind 4-wide collection on a host with headroom, which is what makes the Fleet Health screen report staleness while every collector reports healthy. Narrowing the width never interrupts a running collection - the retiring permits are absorbed as bodies finish. - **The Query Store backfill has an off switch** ([#2167]) - the #2058 backfill previously ran unconditionally, and during a fleet consolidation a freshly restored database's imported catalog put it into sustained byte-budget drains against a cross-region production primary with no way to stop it short of disabling plan capture everywhere. `config_service.query_store_backfill_enabled` (V58, default on) is read live by the service's backfill loop - flip it in the Viewer's Settings window (new checkbox beside plan capture) and the loop idles from its next cycle, no restart; re-enabling resumes exactly where the watermarks left off. Live collection is never affected. - **The store measures its own background jobs** ([#2136], the visibility half) - the hourly #2068 self-metrics sweep now writes one row per TimescaleDB background job (object_kind `background_job`, V56 columns): last run duration, schedule interval, total runs, total failures. Why: the store's heaviest recurring work is its own job machinery - on the production 52-server store the four most expensive jobs are all the query_store_stats family (compression 157s, interval_hourly refresh 96s) - their runtimes scale SERIALLY with raw volume (the finalize hash-aggregate runs in one process), and a job that outgrows its own cadence compounds refresh lag silently. With the interval stored beside the duration, 'how close is each job to its ceiling' is one division over a 400-day series instead of archaeology - the number an onboarding wave moves first. A threshold alert on the series is the issue's next half. diff --git a/Darling/Darling.Tests/StatementSplitTimingTests.cs b/Darling/Darling.Tests/StatementSplitTimingTests.cs new file mode 100644 index 00000000..22ccc199 --- /dev/null +++ b/Darling/Darling.Tests/StatementSplitTimingTests.cs @@ -0,0 +1,80 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; +using PerformanceMonitor.Collectors; +using Xunit; + +namespace Darling.Tests; + +/// +/// Pins the open-vs-drain timing split (#2164). It exists because a single blended sql: number could +/// not answer the question a 5x payload cut raised on production: the byte budget moved bytes 5x and the +/// batch clock ~0%, so the cost is upstream of shipping — but WHICH statement was unprovable from the log, +/// and the next fix would have been a guess. Open time (everything before the first rowset) and drain time +/// (row streaming) have different fixes, so they must be separately visible. +/// +public sealed class StatementSplitTimingTests +{ + private static CollectorContext NewContext() => new() + { + ServerId = 1, + ServerName = "s", + CollectionTime = new DateTime(2026, 8, 10, 0, 0, 0, DateTimeKind.Utc), + Deltas = new CollectorDeltaCalculator(), + }; + + [Fact] + public void OpenMs_DefaultsToZero_SoAnUnmeasuredHostIsNotReadAsInstant() + { + /* Lite does not measure this today. Zero must mean "not measured", which is why the log only emits + the split when the value is positive rather than printing "open:0ms" and inviting the reader to + conclude the aggregate was free. */ + Assert.Equal(0, NewContext().PerItemOpenMs); + } + + [Theory] + /* An aggregate-bound pass: nearly all the batch is spent before the first row arrives, so no client + byte budget can shorten it — the query_store shape measured on the field server. */ + [InlineData(100_000L, 98_000L, 2_000L)] + /* A drain-bound pass: rows are cheap to produce and expensive to move, where the budget IS the lever. */ + [InlineData(100_000L, 3_000L, 97_000L)] + /* Degenerate: open exceeding the batch total (clock skew between the two watches) must clamp at zero + rather than print a negative drain, which would read as a measurement bug in the field. */ + [InlineData(5_000L, 6_000L, 0L)] + public void DrainIsTheRemainder_AndNeverNegative(long sqlMs, long openMs, long expectedDrain) + { + var context = NewContext(); + context.PerItemOpenMs = openMs; + + /* The same arithmetic the runner's log line performs. Pinned here so a refactor of that line cannot + silently start reporting negative drain. */ + var drain = Math.Max(0, sqlMs - context.PerItemOpenMs); + Assert.Equal(expectedDrain, drain); + } + + [Fact] + public void OpenMs_IsNotResetByTheQueryStoreRead_SoTheHostsMeasurementSurvivesToTheLog() + { + /* The query_store collector resets its OWN per-item signals at the top of a read. The host sets + PerItemOpenMs before calling that read, so the collector must leave it alone — otherwise the + split would always log zero and the instrumentation would be silently dead. */ + var context = NewContext(); + context.PerItemOpenMs = 4_242; + context.PerItemTextBudgetExceeded = true; + context.PerItemTextBytesShipped = 999; + + /* Mirrors the collector's documented reset set — deliberately enumerated rather than invoking the + read (which needs a live reader), so this test states the contract the read must honor. */ + context.PerItemTextBudgetExceeded = false; + context.PerItemTextBytesShipped = 0; + context.PerItemShippedBoundary = null; + + Assert.Equal(4_242, context.PerItemOpenMs); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index f1de6335..e3553c68 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs @@ -574,7 +574,18 @@ is the backfill TAIL's job by design. */ { var batch = new List(); using var itemCommand = CreateCollectorCommand(definition.BuildPerItemQuery(item, context), sqlConnection, itemTimeout); + /* #2164: time the OPEN separately from the drain. ExecuteReaderAsync returns only + when the first rowset is available, so for query_store's staged batch this is the + #pm_qs_slice aggregate plus time-to-first-row — the part no client-side budget can + shorten. Everything after is streaming, which the budget does govern. The blended + sql: number could not tell those apart, which is why a 5x payload cut looked like + it did nothing. */ + /* Cleared BEFORE the open so an item whose open faults cannot log the previous + item's split as its own — a stale timing is worse than no timing. */ + context.PerItemOpenMs = 0; + var openWatch = Stopwatch.StartNew(); using var itemReader = await itemCommand.ExecuteReaderAsync(ct); + context.PerItemOpenMs = openWatch.ElapsedMilliseconds; await definition.ReadItemAsync(item, itemReader, batch, context, ct); return batch; }, @@ -594,8 +605,22 @@ behind four quiet siblings. Quiet databases (0 rows — the 2-of-3 cycles betwee Query Store's 900s flushes) stay silent. */ if (batchCount > 0) { - _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms, pg:{PgMs}ms)", - server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs, itemStorageMs); + /* #2164: open vs drain, because they have different fixes. A pass that is nearly + all OPEN is bound by server-side work before the first row (for query_store, + the #pm_qs_slice aggregate) and no client-side budget or payload trimming will + touch it; a pass that is mostly drain is bound by moving rows, where the byte + budget and the link are the levers. Only emitted when the host measured it. */ + if (context.PerItemOpenMs > 0) + { + _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms = open:{OpenMs}ms + drain:{DrainMs}ms, pg:{PgMs}ms)", + server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs, + context.PerItemOpenMs, Math.Max(0, itemSqlMs - context.PerItemOpenMs), itemStorageMs); + } + else + { + _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms, pg:{PgMs}ms)", + server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs, itemStorageMs); + } } var capHit = definition.PerItemRowCountWarnThreshold is int cap && batchCount >= cap; diff --git a/PerformanceMonitor.Collectors/CollectorContext.cs b/PerformanceMonitor.Collectors/CollectorContext.cs index 3efe0a4c..20877fc8 100644 --- a/PerformanceMonitor.Collectors/CollectorContext.cs +++ b/PerformanceMonitor.Collectors/CollectorContext.cs @@ -184,6 +184,23 @@ public sealed class CollectorContext /// public bool PerItemTextBudgetExceeded { get; set; } + /// + /// Milliseconds spent waiting for ExecuteReaderAsync to return for the item just read (#2164), + /// set by the host around the open. Splits a batch's server time into the part the client cannot + /// influence and the part it can: + /// + /// For a multi-statement batch like query_store's staged shape, ADO.NET returns the reader only + /// when the first ROWSET is available — so this number spans every preceding non-rowset statement (the + /// SELECT … INTO #pm_qs_slice aggregate) plus the final select's time-to-first-row. The + /// remaining time, drain, is row streaming the client's byte budget and read loop actually govern. + /// + /// Why it exists: cutting the byte budget 64 MB → 12 MB on a production server moved bytes 5x and + /// the batch clock ~0%, which said the dominant term is upstream of shipping — but the single blended + /// sql: number could not prove WHICH statement, so any next fix would have been a guess. Zero + /// when the host does not measure it (Lite today), so a zero must never be read as "instant". + /// + public long PerItemOpenMs { get; set; } + /// /// Cumulative text bytes the budgeted read actually materialized for the item just read (#1960), /// reset and written alongside . Read by the host purely From ceca971bd0c5b9f37b67ca9c6581449dd3f8d145 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Tue, 11 Aug 2026 01:36:55 +0200 Subject: [PATCH 2/2] Review: subtract the watermark phase, and pin the shipped arithmetic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two findings, both real: 1. The driver's per-item stopwatch starts BEFORE the watermark refresh, which for query_store is a store read (plus a store write on the clamp path) — so those milliseconds were being counted as drain, in the exact metric this instrumentation exists to make trustworthy. Measured as its own phase and reported: wm + open + drain. 2. Two of the three tests re-implemented the formula instead of calling it, so they could not have caught (1). The subtraction now lives in CollectorContext.DrainMsFrom — one definition, called by both the log line and the tests — and the pins cover watermark exclusion, the clamp under stopwatch skew, and that the parts sum to the whole. Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 2 +- .../StatementSplitTimingTests.cs | 42 +++++++++---------- .../DarlingCollectorRunner.cs | 15 +++++-- .../CollectorContext.cs | 18 ++++++++ 4 files changed, 50 insertions(+), 27 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9f26695a..7b304ce6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added - **Every previously-hardcoded alert threshold is now a real setting** ([#2107], the split-out from gotqn's #2101 - "it was fine to hardcode these for development but any serious monitoring allows configuring of alert thresholds") - six new knobs ride the store control plane (V55), the Viewer's Settings window, and `get_alert_settings`/`update_alert_settings`, clamped on read like their siblings: the monitor store volume's self-alert warning percent (was 10), the Collection Stopped staleness window (was 30 minutes) and consecutive-failure fast path (was 10), the low-disk CRITICAL severity tier's percent and GB floors (were 3% / 2 GB - these grade the target-volume alert in BOTH apps, and Lite reads its pair from `settings.json` as `alert_disk_critical_free_percent` / `alert_disk_critical_free_gb`), and the analysis notification cooldown (was a hardcoded 360 in Darling while Lite always honored a configured value - the parity gap closed). MCP shape: `low_disk.critical_free_percent` / `low_disk.critical_free_gb`, a new `self_alerts` group, and `analysis.notify_cooldown_minutes`. -- **Per-database collection timing now separates server think-time from row streaming** ([#2164]) - the per-database Query Store line reports `sql:Xms = open:Yms + drain:Zms`, where open is everything before the first row arrives and drain is streaming those rows to the collector. This exists because of a measurement that overturned an assumption: cutting the text budget from 64 MB to 12 MB on a production server moved 5x fewer bytes and roughly 7x fewer rows, and the batch clock did not move at all. That says the cost lives upstream of shipping - in Query Store's own aggregation before the first row - which no client-side budget or payload trimming can shorten. The blended number could not show that, so the split is now visible: a pass that is nearly all `open` needs the server-side query narrowed, and a pass that is mostly `drain` is the one a smaller budget or a shorter network path helps. +- **Per-database collection timing now separates server think-time from row streaming** ([#2164]) - the per-database Query Store line reports `sql:Xms = wm:Wms + open:Yms + drain:Zms`, where wm is the watermark refresh (a monitor-store round trip the timer already started before), open is everything before the first row arrives, and drain is streaming those rows to the collector. This exists because of a measurement that overturned an assumption: cutting the text budget from 64 MB to 12 MB on a production server moved 5x fewer bytes and roughly 7x fewer rows, and the batch clock did not move at all. That says the cost lives upstream of shipping - in Query Store's own aggregation before the first row - which no client-side budget or payload trimming can shorten. The blended number could not show that, so the split is now visible: a pass that is nearly all `open` needs the server-side query narrowed, and a pass that is mostly `drain` is the one a smaller budget or a shorter network path helps. - **The two collector memory bounds are now operator knobs** ([#2164], [#2170]) - the per-database Query Store text budget (was a hardcoded 64 MB) and the fleet sweep width (was a hardcoded 4 servers) ride the store control plane (V59), the Viewer's Settings window, and the service's live reload, clamped [4,256] MB and [1,16] on read. Defaults reproduce the old constants exactly, so an upgrade changes nothing until a dial moves. Why both at once: peak transient memory is roughly the two multiplied, so an operator moving one needs the other in front of them. Lower the budget when the monitored fleet is a network hop away - the budget bounds memory, but it also sets how long one collector query holds the monitored server open draining to the client, which over a cross-region link is the tenant-visible cost (a smaller budget trades catch-up latency for shorter statements, never data, because every cut is resumable). Raise the sweep width when a large fleet queues behind 4-wide collection on a host with headroom, which is what makes the Fleet Health screen report staleness while every collector reports healthy. Narrowing the width never interrupts a running collection - the retiring permits are absorbed as bodies finish. - **The Query Store backfill has an off switch** ([#2167]) - the #2058 backfill previously ran unconditionally, and during a fleet consolidation a freshly restored database's imported catalog put it into sustained byte-budget drains against a cross-region production primary with no way to stop it short of disabling plan capture everywhere. `config_service.query_store_backfill_enabled` (V58, default on) is read live by the service's backfill loop - flip it in the Viewer's Settings window (new checkbox beside plan capture) and the loop idles from its next cycle, no restart; re-enabling resumes exactly where the watermarks left off. Live collection is never affected. - **The store measures its own background jobs** ([#2136], the visibility half) - the hourly #2068 self-metrics sweep now writes one row per TimescaleDB background job (object_kind `background_job`, V56 columns): last run duration, schedule interval, total runs, total failures. Why: the store's heaviest recurring work is its own job machinery - on the production 52-server store the four most expensive jobs are all the query_store_stats family (compression 157s, interval_hourly refresh 96s) - their runtimes scale SERIALLY with raw volume (the finalize hash-aggregate runs in one process), and a job that outgrows its own cadence compounds refresh lag silently. With the interval stored beside the duration, 'how close is each job to its ceiling' is one division over a 400-day series instead of archaeology - the number an onboarding wave moves first. A threshold alert on the series is the issue's next half. diff --git a/Darling/Darling.Tests/StatementSplitTimingTests.cs b/Darling/Darling.Tests/StatementSplitTimingTests.cs index 22ccc199..95828251 100644 --- a/Darling/Darling.Tests/StatementSplitTimingTests.cs +++ b/Darling/Darling.Tests/StatementSplitTimingTests.cs @@ -41,40 +41,36 @@ conclude the aggregate was free. */ [Theory] /* An aggregate-bound pass: nearly all the batch is spent before the first row arrives, so no client byte budget can shorten it — the query_store shape measured on the field server. */ - [InlineData(100_000L, 98_000L, 2_000L)] + [InlineData(100_000L, 0L, 98_000L, 2_000L)] /* A drain-bound pass: rows are cheap to produce and expensive to move, where the budget IS the lever. */ - [InlineData(100_000L, 3_000L, 97_000L)] - /* Degenerate: open exceeding the batch total (clock skew between the two watches) must clamp at zero + [InlineData(100_000L, 0L, 3_000L, 97_000L)] + /* The watermark phase is a STORE round trip the driver's stopwatch already started before. It must come + out of drain, not inflate it — the review catch this arithmetic exists to prevent. */ + [InlineData(100_000L, 40_000L, 55_000L, 5_000L)] + /* Degenerate: phases exceeding the batch total (skew across separate stopwatches) must clamp at zero rather than print a negative drain, which would read as a measurement bug in the field. */ - [InlineData(5_000L, 6_000L, 0L)] - public void DrainIsTheRemainder_AndNeverNegative(long sqlMs, long openMs, long expectedDrain) + [InlineData(5_000L, 3_000L, 6_000L, 0L)] + public void DrainExcludesWatermarkAndOpen_AndNeverGoesNegative(long sqlMs, long watermarkMs, long openMs, long expectedDrain) { var context = NewContext(); + context.PerItemWatermarkMs = watermarkMs; context.PerItemOpenMs = openMs; - /* The same arithmetic the runner's log line performs. Pinned here so a refactor of that line cannot - silently start reporting negative drain. */ - var drain = Math.Max(0, sqlMs - context.PerItemOpenMs); - Assert.Equal(expectedDrain, drain); + /* Calls the SHIPPED arithmetic (CollectorContext.DrainMsFrom) — the log line calls the same method, + so this cannot drift into pinning a copy of the formula the way the first cut did. */ + Assert.Equal(expectedDrain, context.DrainMsFrom(sqlMs)); } [Fact] - public void OpenMs_IsNotResetByTheQueryStoreRead_SoTheHostsMeasurementSurvivesToTheLog() + public void EveryPhaseAccountedFor_ThePartsNeverExceedTheWhole() { - /* The query_store collector resets its OWN per-item signals at the top of a read. The host sets - PerItemOpenMs before calling that read, so the collector must leave it alone — otherwise the - split would always log zero and the instrumentation would be silently dead. */ + /* The split's contract as a reader sees it: wm + open + drain == the sql: total, so nothing is + silently unattributed. Holds for any measurement where the phases fit inside the total. */ var context = NewContext(); - context.PerItemOpenMs = 4_242; - context.PerItemTextBudgetExceeded = true; - context.PerItemTextBytesShipped = 999; + context.PerItemWatermarkMs = 1_200; + context.PerItemOpenMs = 300_000; + const long sqlMs = 350_000; - /* Mirrors the collector's documented reset set — deliberately enumerated rather than invoking the - read (which needs a live reader), so this test states the contract the read must honor. */ - context.PerItemTextBudgetExceeded = false; - context.PerItemTextBytesShipped = 0; - context.PerItemShippedBoundary = null; - - Assert.Equal(4_242, context.PerItemOpenMs); + Assert.Equal(sqlMs, context.PerItemWatermarkMs + context.PerItemOpenMs + context.DrainMsFrom(sqlMs)); } } diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index e3553c68..bb2012db 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs @@ -506,6 +506,12 @@ Only query_store (the sole enumeration collector with a per-database timestamp ? null : async (item, ct) => { + /* #2164: the driver's per-item stopwatch starts BEFORE this delegate, so the + watermark refresh — a STORE read, plus a store write on the clamp path below — + 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(); var raw = await GetLastCollectedTimeForDatabaseAsync( server.ServerId, definition.TargetTable, definition.WatermarkColumn!, definition.PerDatabaseWatermarkColumn!, item, ct); @@ -569,6 +575,7 @@ is the backfill TAIL's job by design. */ } context.Watermark = clamped; + context.PerItemWatermarkMs = watermarkWatch.ElapsedMilliseconds; }, readItem: async (item, ct) => { @@ -581,7 +588,9 @@ is the backfill TAIL's job by design. */ sql: number could not tell those apart, which is why a 5x payload cut looked like it did nothing. */ /* Cleared BEFORE the open so an item whose open faults cannot log the previous - item's split as its own — a stale timing is worse than no timing. */ + item's split as its own — a stale timing is worse than no timing. The watermark + phase is NOT cleared here: it ran already, for THIS item, and clearing it would + hand its milliseconds to drain. */ context.PerItemOpenMs = 0; var openWatch = Stopwatch.StartNew(); using var itemReader = await itemCommand.ExecuteReaderAsync(ct); @@ -612,9 +621,9 @@ behind four quiet siblings. Quiet databases (0 rows — the 2-of-3 cycles betwee budget and the link are the levers. Only emitted when the host measured it. */ if (context.PerItemOpenMs > 0) { - _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms = open:{OpenMs}ms + drain:{DrainMs}ms, pg:{PgMs}ms)", + _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms = wm:{WatermarkMs}ms + open:{OpenMs}ms + drain:{DrainMs}ms, pg:{PgMs}ms)", server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs, - context.PerItemOpenMs, Math.Max(0, itemSqlMs - context.PerItemOpenMs), itemStorageMs); + context.PerItemWatermarkMs, context.PerItemOpenMs, context.DrainMsFrom(itemSqlMs), itemStorageMs); } else { diff --git a/PerformanceMonitor.Collectors/CollectorContext.cs b/PerformanceMonitor.Collectors/CollectorContext.cs index 20877fc8..27e1a382 100644 --- a/PerformanceMonitor.Collectors/CollectorContext.cs +++ b/PerformanceMonitor.Collectors/CollectorContext.cs @@ -201,6 +201,24 @@ public sealed class CollectorContext /// public long PerItemOpenMs { get; set; } + /// + /// Milliseconds the item's watermark refresh took (#2164), set by the host when it runs one. This is NOT + /// server think-time or streaming — for query_store it is a STORE read (and on the catch-up/adaptive + /// path a store write too), yet the driver's sql: stopwatch starts before it. Measured so it can + /// be subtracted rather than silently inflating drain, which would corrupt the one number this + /// instrumentation exists to make trustworthy. Zero when the host runs no per-item watermark. + /// + public long PerItemWatermarkMs { get; set; } + + /// + /// The item's row-STREAMING time: the driver's blended per-item total minus the phases that are not + /// streaming (, ). Lives here rather than at + /// the log site so the subtraction has exactly one definition and a test can pin the shipped arithmetic + /// instead of a copy of it. Clamped at zero: the phases are measured on separate stopwatches, so tiny + /// skew must never surface as negative drain. + /// + public long DrainMsFrom(long itemSqlMs) => Math.Max(0, itemSqlMs - PerItemOpenMs - PerItemWatermarkMs); + /// /// Cumulative text bytes the budgeted read actually materialized for the item just read (#1960), /// reset and written alongside . Read by the host purely