diff --git a/CHANGELOG.md b/CHANGELOG.md index 3f3be24f5..b961f6781 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -45,6 +45,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: a suspended secondary that is falling behind now raises the sync alert** ([#1700]) - the "AG Sync Fell Behind" lag trigger shipped in [#1692] made its seconds check ABSTAIN on a suspended row, written to MS Learn's statement that `secondary_lag_seconds` "shows as 0 if the data movement is suspended" - abstaining looked like the careful reading, since a zero would otherwise report the database that is furthest behind as caught up. **The documentation is wrong.** Measured against a live Availability Group (SQL Server 2022 16.0.4265.3, clusterless AG, write load, sampled across a `SUSPEND_FROM_USER` on the secondary), lag ACCRUES monotonically at wall-clock rate while suspended - 3993, 4005, 4017, 4029, 4041 across four 12-second intervals - and returns to 0 on resume. So the abstention was not caution, it was silencing the alert on suspended data movement: the single most common way a secondary falls behind, and the case an operator most needs paging for. A suspended secondary could drift arbitrarily far behind while only "AG Database Suspended" fired once, on the edge. Replaced with an asymmetry - **a suspended row may raise an alarm but may never clear one** - which is deliberately correct under BOTH behaviors rather than betting on the measurement: if lag accrues it crosses the threshold and fires, and if it ever did read 0 that zero is under the threshold and yields "not measurable" rather than "caught up", so it still cannot resolve a standing alert. The same rule now protects the redo-queue trigger, whose value FREEZES at its last reading while suspended (also measured): frozen and over the threshold is a real backlog worth firing on, frozen and under it is stale data that must not clear anything - previously a small frozen queue could resolve a live alert. Two more measured behaviors are documented rather than coded around: `log_send_queue_size` reads NULL while suspended instead of growing, so it is useless as a fell-behind signal (this evaluator never used it), and on RESUME the secondary has a genuine backlog to drain (388,620 KB after a 60-second suspend under load), so a single-sample redo threshold fires during legitimate catch-up - not wrong, since the data-loss window really is open until it drains, but it is why that trigger ships off. Evidence from the Docker AG fixture; the suspend/resume cycle was re-run independently before the shipped logic was changed. - **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. @@ -1673,6 +1674,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 [#1700]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1700 [#1690]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1690 diff --git a/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs b/Darling/PerformanceMonitor.Darling.Service/Compose/MeasureCatalog.cs index f6c58da2a..a0d3b6698 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 644d88ec6..debbcc236 100644 --- a/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs +++ b/PerformanceMonitor.Collectors/AgDatabaseReplicaStatesCollector.cs @@ -33,19 +33,42 @@ 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. /// +/// 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. +/// /// 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.) +/// 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 +/// 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. /// -/// 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. +/// 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