From 83bad62764fa71fa6e53dfac940ed23a8c4928b8 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sun, 26 Jul 2026 15:12:39 -0400 Subject: [PATCH 1/2] AG suspension semantics: one rule that holds either way (#991) The collector's doc comments treated the SUSPENDED state as a single quirk about secondary_lag_seconds. Measuring the rest of the surface on the live Docker AG fixture showed it is broader, and that the columns disagree with each other in OPPOSITE directions. While a replica is suspended: - secondary_lag_seconds ACCRUES (measured twice: 0/15/31/46/62s and 30/45/60/75s), though MS Learn claims it reads 0. - log_send_queue_size goes NULL. - redo_queue_size FREEZES at its last value. - All four *_time columns FREEZE at their last pre-suspension instant. So a cross-replica commit-time delta stops growing exactly when replication has stopped - understating the problem at its worst - while the lag column overstates it. Averaging or cross-checking the two without reading is_suspended first gives nonsense. The sharpest edge is a measure this release shipped: est_redo_completion_time_min is queue / rate, and with both frozen it holds a small, static, reassuring value (0.0144 min, flat across a 45s suspension) when the honest answer is "never, movement is stopped". A suspended replica makes a drain panel look HEALTHIER than reality. All of it reduces to one rule, now stated on the collector and mirrored on the compose measures: a suspended row may RAISE an alarm but may never CLEAR one. That holds under both the documented and the measured behavior, so nothing downstream has to bet on which is true - WSFC and other builds remain untested, so a rule beats a new absolute. Framing credit to ag-alerts-builder, who landed the same asymmetry in the alert evaluator. Also documented: last_received_time read NULL in every sample, healthy or suspended; and last_commit_time / last_redone_time sit still on an IDLE database, so `now - last_commit_time` is not a lag measure - on a quiet, healthy replica it grows without bound. Doc-only; no behavior change. Fixture left as found (both replicas SYNCHRONIZED, probe table dropped). Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 2 + .../Compose/MeasureCatalog.cs | 15 ++++--- .../AgDatabaseReplicaStatesCollector.cs | 42 +++++++++++++------ 3 files changed, 42 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d3ab0119..7f2fd12a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -44,6 +44,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **AG suspension semantics: one rule that holds whether or not the vendor docs are right** ([#1702]) - the AG collector's doc comments described the SUSPENDED state as a single quirk about `secondary_lag_seconds`. Measuring the rest of the surface on the live Docker AG fixture showed it is broader, and that the columns disagree with each other in OPPOSITE directions, which is the part that could bite. While a replica is suspended: `secondary_lag_seconds` ACCRUES (measured twice - 0/15/31/46/62s and 30/45/60/75s - though MS Learn claims it reads 0), `log_send_queue_size` goes NULL, `redo_queue_size` FREEZES at its last value, and all four `*_time` columns FREEZE at their last pre-suspension instant. So a cross-replica commit-time delta stops growing exactly when replication has stopped, understating the problem at its worst, while the lag column overstates it. **The sharpest edge is a measure this release shipped**: `est_redo_completion_time_min` is queue / rate with both frozen, so it holds a small, static, reassuring value (0.0144 min, flat across a 45s suspension) when the honest answer is "never, movement is stopped" - a suspended replica makes a drain panel look HEALTHIER than reality. All of it now reduces to one rule stated on the collector and mirrored on the compose measures: **a suspended row may RAISE an alarm but may never CLEAR one**, which is correct under both the documented and the measured behavior, so nothing downstream has to bet on which is true (WSFC and other builds remain untested). Also documented: `last_received_time` read NULL in every sample, healthy or suspended; and `last_commit_time` / `last_redone_time` sit still on an IDLE database, so `now - last_commit_time` is not a lag measure - on a quiet healthy replica it grows without bound. Doc-only; no behavior change. - **Darling: the Availability Group store reads are now executed against a real Postgres in CI** ([#1697]) - the two AG reads added in [#1692] had no test that ran their SQL, and that was the one gap that mattered: the defect they were corrected for during review is invisible to a unit test. Both grains were briefly read as two statements over a SINGLE command to save a round trip, which PostgreSQL rejects - Npgsql only splits multi-statement text into a batch when it parses the SQL for NAMED placeholders, so with the positional (`$1`) parameters those reads use it sends one extended-protocol `Parse` and the server answers `cannot insert multiple commands into a prepared statement`. Every AG path is failure-isolated, so it would not have crashed anything; it would have logged one error per server per sweep with the whole alert family silently dead, which is the worst failure mode a monitoring product has - the thing that is broken is the thing that tells you something is broken. The new `DARLING_TEST_PG`-gated test seeds both collector tables and asserts what only real SQL can prove: that each query executes, that the newest-snapshot predicate excludes an older one, that a row with a NULL identity column is dropped rather than keyed under a placeholder, that NULL lag and suspend-reason columns round-trip, and that the path reaches the sweep entry point and fires exactly one alert off freshly seeded rows. - **Lite + Darling: recovery notices were being styled and counted as live alerts in Alert History and the Daily Summary** ([#1692]) - `AlertMetricClassifier.IsResolution` is the shared source of truth for "this row is good news, not something to act on", and it recognized only the `Cleared` / `Resolved` / `Restored` suffixes. Darling's self-alert recoveries have been emitting `Collection Resumed`, `Agent Restarted` and `Compression Job Recovered` - written by the very same recovery path as the recognized `Capture Restored` - and every one of them landed in BOTH apps' Alert History grids styled as an actionable alert, and was counted as one in the Daily Summary's per-day alert totals. This is the same drift #1225 fixed one layer up, recurring one layer down. Widened the suffix set to `Resumed` / `Restarted` / `Recovered` / `Reconnected` (no actionable metric name in either app contains those words, so nothing real turns green), and widened both hand-maintained SQL copies of that list - Darling's `DailySummarySql` and Lite's `LocalDataService.DailySummary` - which is where the miscount came from. @@ -1671,6 +1672,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#1692]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1692 [#1695]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1695 [#1699]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1699 +[#1702]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1702 [#1697]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1697 [#1690]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1690 [#1693]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1693 diff --git a/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs b/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs index f6c58da2..a0d3b669 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs @@ -1053,11 +1053,16 @@ intervals now ships as a Weighted ratio (SUM(avg * execution_count) / SUM(execut per-second nature stated in the display name rather than implied by a unit the picker would render as a plain size. - Lag trap worth knowing when reading these: secondary_lag_seconds reads 0, not NULL, while data - movement is SUSPENDED, so a suspended replica charts as zero lag. The two state columns are - exposed as DIMENSIONS so that is actionable rather than merely documented — filter a lag panel - to synchronization_state_desc <> 'NOT SYNCHRONIZING', or group by suspend_reason_desc, and a - suspended replica stops masquerading as a healthy one. ── */ + SUSPENSION is the trap under all of these, and it does NOT hit them the same way. Measured on a + live 2022 AG: secondary_lag_seconds ACCRUES while suspended (the docs claim it reads 0 — either + way a lag panel is safe, it can only over-report), but every other measure here goes STALE. + log_send_queue_size reads NULL, redo_queue_size FREEZES at its last value, and — the sharp one — + ag_est_redo_drain_min is queue ÷ rate with both frozen, so it holds a small, static, reassuring + number (0.0144 min, flat across a 45 s suspension) when the true answer is "never, movement is + stopped". So a suspended replica can make a drain or queue panel look HEALTHIER than reality, + never worse. That is why the two state columns are dimensions rather than just documented: + filter to synchronization_state_desc <> 'NOT SYNCHRONIZING', or group by suspend_reason_desc, + before trusting any panel on this source to say something has recovered. ── */ new ComposeMeasure { Key = "ag_log_send_queue", DisplayName = "AG log send queue", Category = CatAvailabilityGroups, SourceTable = "ag_database_replica_states", diff --git a/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs b/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs index 644d88ec..75db6714 100644 --- a/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs +++ b/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs @@ -33,19 +33,37 @@ namespace PerformanceMonitor.Collectors; /// last_hardened_lsn is a log-block id padded with zeroes, so neither is safe to do arithmetic on. /// Deriving a byte distance between them is ANALYSIS, deliberately left to a reader. /// -/// secondary_lag_seconds is 2016+ and the repo floor IS 2016, so it is referenced directly -/// with no version branch. MEASURED BEHAVIOR, which contradicts the docs: MS Learn says it "shows as 0 -/// if the data movement is suspended", but on a live SQL Server 2022 (16.0.4265.3) CLUSTER_TYPE = NONE -/// AG it does the inverse — it reads 0 while movement is ACTIVE and caught up, and accrues monotonically -/// once SUSPENDED (0 → 15 → 31 → 46 → 62 s across a 60 s SUSPEND_FROM_USER, back to 0 on resume). So a -/// suspended replica does NOT hide as zero lag, and a lag threshold fires on its own. Read is_suspended -/// alongside it to explain WHY lag is climbing, not to catch lag that is being masked. (Validated on a -/// clusterless AG on one build; WSFC untested, so treat the doc sentence as unreliable rather than -/// inverted-everywhere.) +/// THE RULE FOR EVERY COLUMN HERE, and the only safe one: while a replica is SUSPENDED, a reading +/// may RAISE an alarm but may never CLEAR one. That asymmetry holds under both the documented and the +/// measured behavior, so nothing downstream has to bet on which is true — which matters, because they +/// disagree. /// -/// Two more measured quirks of the SUSPENDED state, both relevant to anyone thresholding these: -/// log_send_queue_size goes NULL rather than growing, while redo_queue_size FREEZES at its last value — -/// so a redo-queue reading on a suspended replica is stale, not current. +/// secondary_lag_seconds is 2016+ and the repo floor IS 2016, so it is referenced directly with no +/// version branch. MS Learn says it "shows as 0 if the data movement is suspended". Measured on a live +/// SQL Server 2022 (16.0.4265.3) CLUSTER_TYPE = NONE AG it does the inverse — 0 while movement is ACTIVE +/// and caught up, accruing monotonically once suspended (two independent runs: 0→15→31→46→62 s, and +/// 30→45→60→75 s, back to 0 on resume). Under the docs a suspended replica hides as zero lag; under the +/// measurement it announces itself. The asymmetry above covers both: a growing lag fires, a zero lag on a +/// suspended row resolves nothing. WSFC untested, one build — hence the rule rather than a new absolute. +/// +/// The rest of the SUSPENDED surface, all measured, all pointing the same way — STALE, NOT CURRENT: +/// log_send_queue_size goes NULL rather than growing; redo_queue_size FREEZES at its last value; and all +/// four *_time columns FREEZE at their last pre-suspension instant. So a commit-time delta computed across +/// replicas stops growing exactly when replication has stopped, understating the problem at the moment it +/// is worst — the opposite direction from secondary_lag_seconds, which is why the two must never be +/// averaged or cross-checked against each other without reading is_suspended first. +/// +/// The drain estimates inherit that freeze and are the sharpest edge of it: est_redo_completion_time_min +/// is queue ÷ rate, and with BOTH frozen it holds a small, static, reassuring value (measured 0.0144 min +/// held flat across a 45 s suspension) when the honest answer is "never, movement is stopped". +/// est_send_drain_time_min at least reads NULL, because its queue goes NULL. Threshold the redo estimate +/// on its own and a suspended replica looks healthy; that is precisely the alarm a suspended row must +/// never be allowed to clear. +/// +/// last_received_time read NULL in every sample on that fixture, healthy and suspended alike, so +/// treat it as optional rather than expected. last_commit_time and last_redone_time also sit still on an +/// IDLE database — they are "time of last commit", not a heartbeat — so now - last_commit_time is +/// not a lag measure: on a quiet, perfectly healthy replica it grows without bound. /// /// GRAIN WARNING: on a SECONDARY, sys.dm_hadr_database_replica_states carries only the LOCAL /// replica's rows, so this INNER JOIN narrows to a one-row self-view even though From b6a5591a8a1dbe769e1b058652748feca3a877f4 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sun, 26 Jul 2026 15:19:41 -0400 Subject: [PATCH 2/2] Carry ag-fixture-builder's lag mechanism into the suspension doc block Their correction (feature/991-ag-fixture, 5f7a20b8) explains the lag mechanism better than mine did, and it is NOT on dev: PR #1689 merged an earlier state of that branch, so 5f7a20b8 is not an ancestor of dev and would not have shipped. Their branch also predates #1695, so merging it now would revert the six V36 columns along with the comment. Adopted their paragraph essentially verbatim here instead, on a branch that is current with dev: - While suspended, secondary_lag_seconds reports roughly how STALE the secondary's last hardened log is (now - last_hardened_time), NOT time since suspension. That reconciles the two runs that looked contradictory: near-zero start under write load, thousands of seconds immediately on an idle group. - It does not latch the moment movement stops - a suspended row can still report 0 for the first sample or two. - The magnitude is staleness, not volume at risk; log_send_queue_size would be the volume measure and it is NULL while suspended, which dovetails with the freeze findings already in this block. - Points at tools/ag-fixture/VALIDATION.md for the numbers. My own measurements stay: the freeze of all four *_time columns, the drain-estimate edge, the idle-database commit-time trap, and the last_received_time NULL observation. Co-Authored-By: Claude Fable 5 --- .../AgDatabaseReplicaStatesCollector.cs | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs b/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs index 75db6714..debbcc23 100644 --- a/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs +++ b/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs @@ -38,13 +38,18 @@ namespace PerformanceMonitor.Collectors; /// measured behavior, so nothing downstream has to bet on which is true — which matters, because they /// disagree. /// -/// secondary_lag_seconds is 2016+ and the repo floor IS 2016, so it is referenced directly with no -/// version branch. MS Learn says it "shows as 0 if the data movement is suspended". Measured on a live -/// SQL Server 2022 (16.0.4265.3) CLUSTER_TYPE = NONE AG it does the inverse — 0 while movement is ACTIVE -/// and caught up, accruing monotonically once suspended (two independent runs: 0→15→31→46→62 s, and -/// 30→45→60→75 s, back to 0 on resume). Under the docs a suspended replica hides as zero lag; under the -/// measurement it announces itself. The asymmetry above covers both: a growing lag fires, a zero lag on a -/// suspended row resolves nothing. WSFC untested, one build — hence the rule rather than a new absolute. +/// secondary_lag_seconds is 2016+ and the repo floor IS 2016, so it is referenced directly +/// with no version branch. MS Learn documents it reading 0 while data movement is SUSPENDED +/// — DO NOT BUILD ON THAT SENTENCE, it is contradicted by measurement. On 16.0.4265.3 it reads 0 +/// while movement is ACTIVE and caught up, and ACCRUES once suspended. What it reports on a +/// suspended row is roughly how stale the secondary's last hardened log is +/// (now - last_hardened_time), NOT time since suspension: under write load that starts near +/// zero and climbs (measured 0→15→31→46→62 s and 30→45→60→75 s on two loaded runs), but on an IDLE +/// group it starts at however long since the last write and can be thousands of seconds immediately. +/// It also does not latch the moment movement stops — a suspended row can still report 0 for the +/// first sample or two. So the magnitude is STALENESS, not volume at risk (log_send_queue_size would +/// be the volume measure, and it is NULL while suspended). is_suspended is collected alongside so +/// that reading is possible. Evidence: tools/ag-fixture/VALIDATION.md. /// /// The rest of the SUSPENDED surface, all measured, all pointing the same way — STALE, NOT CURRENT: /// log_send_queue_size goes NULL rather than growing; redo_queue_size FREEZES at its last value; and all