Split per-database collection timing into open + drain — the measurement the next QS fix needs (#2164)

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 = 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.

Darling/Darling.Tests/StatementSplitTimingTests.cs

@@ -0,0 +1,76 @@
+/*
+ * 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;
+
+/// <summary>
+/// Pins the open-vs-drain timing split (#2164). It exists because a single blended <c>sql:</c> 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.
+/// </summary>
+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, 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, 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, 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;
+
+        /* 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 EveryPhaseAccountedFor_ThePartsNeverExceedTheWhole()
+    {
+        /* 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.PerItemWatermarkMs = 1_200;
+        context.PerItemOpenMs = 300_000;
+        const long sqlMs = 350_000;
+
+        Assert.Equal(sqlMs, context.PerItemWatermarkMs + context.PerItemOpenMs + context.DrainMsFrom(sqlMs));
+    }
+}

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,12 +575,26 @@ is the backfill TAIL's job by design. */
                             }
 
                             context.Watermark = clamped;
+                            context.PerItemWatermarkMs = watermarkWatch.ElapsedMilliseconds;
                         },
                     readItem: async (item, ct) =>
                     {
                         var batch = new List<TRow>();
                         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. 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);
+                        context.PerItemOpenMs = openWatch.ElapsedMilliseconds;
                         await definition.ReadItemAsync(item, itemReader, batch, context, ct);
                         return batch;
                     },
@@ -594,8 +614,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 = wm:{WatermarkMs}ms + open:{OpenMs}ms + drain:{DrainMs}ms, pg:{PgMs}ms)",
+                                    server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs,
+                                    context.PerItemWatermarkMs, context.PerItemOpenMs, context.DrainMsFrom(itemSqlMs), 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;

PerformanceMonitor.Collectors/CollectorContext.cs

@@ -184,6 +184,41 @@ public sealed class CollectorContext
     /// </summary>
     public bool PerItemTextBudgetExceeded { get; set; }
 
+    /// <summary>
+    /// Milliseconds spent waiting for <c>ExecuteReaderAsync</c> 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:
+    ///
+    /// <para>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
+    /// <c>SELECT … INTO #pm_qs_slice</c> 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.</para>
+    ///
+    /// <para>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
+    /// <c>sql:</c> 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".</para>
+    /// </summary>
+    public long PerItemOpenMs { get; set; }
+
+    /// <summary>
+    /// 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 <c>sql:</c> 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.
+    /// </summary>
+    public long PerItemWatermarkMs { get; set; }
+
+    /// <summary>
+    /// The item's row-STREAMING time: the driver's blended per-item total minus the phases that are not
+    /// streaming (<see cref="PerItemWatermarkMs"/>, <see cref="PerItemOpenMs"/>). 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.
+    /// </summary>
+    public long DrainMsFrom(long itemSqlMs) => Math.Max(0, itemSqlMs - PerItemOpenMs - PerItemWatermarkMs);
+
     /// <summary>
     /// Cumulative text bytes the budgeted read actually materialized for the item just read (#1960),
     /// reset and written alongside <see cref="PerItemTextBudgetExceeded"/>. Read by the host purely