diff --git a/CHANGELOG.md b/CHANGELOG.md index d1f17fa0..7b304ce6 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 = 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 new file mode 100644 index 00000000..95828251 --- /dev/null +++ b/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; + +/// +/// 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, 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)); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index f1de6335..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,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(); 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; diff --git a/PerformanceMonitor.Collectors/CollectorContext.cs b/PerformanceMonitor.Collectors/CollectorContext.cs index 3efe0a4c..27e1a382 100644 --- a/PerformanceMonitor.Collectors/CollectorContext.cs +++ b/PerformanceMonitor.Collectors/CollectorContext.cs @@ -184,6 +184,41 @@ 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; } + + /// + /// 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