diff --git a/CHANGELOG.md b/CHANGELOG.md index b961f678..e4cf43eb 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 +- **Darling: the AG lag alert now says what its number actually measures** ([#1703]) - follow-up to [#1700], which got the rule right but the mechanism wrong, and the mechanism is what an operator needs to tune a threshold. While data movement is suspended `secondary_lag_seconds` reports the **staleness of the last hardened log** (roughly `now - last_hardened_time`), which then grows at wall-clock rate; it is NOT time since suspension. That reconciles two measurements that looked contradictory: under write load the last hardening is near-now, so it starts around 0 and climbs, while on an idle group it starts at however long since the last write and can jump straight to a large number. Chasing that turned up something sharper, measured across a 60-second suspend on an idle group sampled every 15 seconds: lag read **0 at every single sample** while the replica was already `NOT SYNCHRONIZING` and its last hardened log aged from 262 to 322 seconds. It did not latch late - it never latched. So a suspended replica can report zero lag for an entire outage, which makes [#1700]'s "a sub-threshold reading on a suspended row is never *caught up*" load-bearing for a far more common case than the inverted-documentation one it was written for. The corollary is now stated plainly in the code: **the lag trigger alone cannot detect suspended data movement on a quiet group** - "AG Database Suspended" is the alert that owns that case, which is why the family has both. The alert detail text also now explains that the figure is staleness rather than volume of queued data, since on a quiet group a large value can simply mean nothing has been written recently, and the volume measure (`log_send_queue_size`) reports nothing at all while suspended. Documentation and alert text only; no logic change. The rule is also now stated as a property of suspended ROWS rather than of the two columns it started on: ag-collector-builder's measurement of the four `*_time` columns (#1702) found they all FREEZE at their last pre-suspension instant, so a cross-replica commit-time delta stops growing exactly when replication stops, and any drain-time measure (queue divided by rate, both frozen) holds a small, static, healthy-looking number - measured at a flat 0.0144 minutes across an entire suspension - when the true answer is “never”. Three different columns, three different mechanisms, all erring in the REASSURING direction, which is the half that fails silently. Anything added later that judges a suspended row has to route through the same may-fire-never-clear gate. - **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. @@ -1677,6 +1678,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#1702]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1702 [#1697]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1697 [#1700]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1700 +[#1703]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1703 [#1690]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1690 [#1693]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1693 [#1694]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1694 diff --git a/Darling/Darling.Tests/DarlingSelfAlertTests.cs b/Darling/Darling.Tests/DarlingSelfAlertTests.cs index 7d411995..a9284edd 100644 --- a/Darling/Darling.Tests/DarlingSelfAlertTests.cs +++ b/Darling/Darling.Tests/DarlingSelfAlertTests.cs @@ -1011,9 +1011,11 @@ silenced exactly that case. */ Judge(DatabaseRow(lagSeconds: 9999, suspended: true), 300, 0)); /* The other half of the asymmetry, and the reason this is not simply "judge suspended rows normally": - a suspended reading UNDER the threshold is not evidence of recovery. Were the documented zero-lag - behavior ever real, this is the row it would produce, and calling it CaughtUp would resolve a - standing alert at the exact moment things got worse. NotMeasurable is correct under both behaviors. */ + a suspended reading UNDER the threshold is not evidence of recovery. This row is NOT hypothetical: + sampled every 15s across a 60-second suspend on an IDLE group, secondary_lag_seconds read 0 at every + sample while synchronization_state_desc was already NOT SYNCHRONIZING — on a quiet group it may + never latch at all. Calling that CaughtUp would clear a standing alarm on a replica receiving + nothing. (It also covers the documented flat-zero behavior, if any build really does that.) */ Assert.Equal( DarlingSelfAlertEvaluator.AgSyncJudgement.NotMeasurable, Judge(DatabaseRow(lagSeconds: 0, suspended: true), 300, 0)); diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs index e30b3661..b6423695 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs @@ -694,18 +694,42 @@ internal enum AgSyncJudgement /// SUSPENDED ROWS MAY RAISE AN ALARM BUT MAY NEVER CLEAR ONE. That asymmetry replaces an earlier rule /// that made the seconds trigger abstain entirely while suspended, which was written to MS Learn's claim /// that secondary_lag_seconds "shows as 0 if the data movement is suspended". THE DOCUMENTATION IS - /// WRONG. Measured against a live AG (SQL Server 2022 16.0.4265.3, clusterless AG, write load, sampled - /// across a SUSPEND_FROM_USER): lag ACCRUES monotonically at wall-clock rate while suspended - /// (…3993 → 4005 → 4017 → 4029 → 4041 over four 12-second intervals) and returns to 0 on resume. Abstaining - /// therefore silenced the lag alert on a suspended secondary — the single most common way a secondary falls - /// behind, and the case an operator most needs paged for. - /// The alarm/clear asymmetry is deliberately correct under BOTH behaviors, so this does not have to - /// bet on one: if lag accrues (measured), a suspended secondary crosses the threshold and fires; if it ever - /// did read 0 (documented), that 0 is below threshold and yields NotMeasurable rather than - /// CaughtUp, so it still cannot resolve a standing alert. The same rule protects the redo trigger, whose - /// value FREEZES at its last reading while suspended (also measured) — a frozen value over the threshold is - /// a real backlog worth firing on, while a frozen value under it is stale data that must not clear - /// anything. + /// WRONG, and abstaining silenced the lag alert on a suspended secondary — the single most common way a + /// secondary falls behind, and the case an operator most needs paged for. + /// What the column actually does while suspended (measured on a live clusterless AG, SQL Server 2022 + /// 16.0.4265.3, across a SUSPEND_FROM_USER): it reports the STALENESS OF THE LAST HARDENED LOG — + /// approximately now - last_hardened_time — which then grows at wall-clock rate. It is NOT time + /// since suspension, and the starting value depends on write activity: under load the last hardening is + /// near-now so it starts around 0 and climbs (0 → 15 → 31 → 46 → 62 across a 60-second suspend); on an IDLE + /// group it starts at however long since the last write and so can jump straight to a large number + /// (…3993 → 4005 → 4017 → 4029 → 4041 over four 12-second intervals). Both were measured; they are the same + /// behavior from different starting points. It returns to 0 on resume. + /// THE CONSEQUENCE the asymmetry exists to survive, and it is not hypothetical: the column does not + /// latch when movement stops, and ON A QUIET GROUP IT MAY NEVER LATCH AT ALL. Sampled every 15 seconds + /// across a 60-second suspend on an idle group, secondary_lag_seconds read 0 at every single + /// sample while synchronization_state_desc was already NOT SYNCHRONIZING and the last hardened log + /// aged from 262 to 322 seconds. So a suspended, genuinely-stopped replica can report zero lag for the + /// entire outage. A rule that read that zero as "caught up" would clear a standing alarm on a replica that + /// is receiving nothing. (The same guard also covers the documented flat-zero behavior, if any build really + /// does that.) The corollary is that THE LAG TRIGGER ALONE CANNOT DETECT SUSPENDED DATA MOVEMENT on a quiet + /// group — "AG Database Suspended" is the alert that owns that case, which is why the family has both. + /// The same rule protects the redo trigger, whose value FREEZES at its last reading while suspended (also + /// measured) — a frozen value over the threshold is a real backlog worth firing on, while a frozen value + /// under it is stale data that must not clear anything. + /// TREAT THIS AS A RULE ABOUT SUSPENDED ROWS, NOT ABOUT THESE TWO COLUMNS. Every measured signal on a + /// suspended replica is untrustworthy in the REASSURING direction, and they fail that way for different + /// reasons: lag can sit at 0 because it never latched, the redo queue is frozen, and the four + /// *_time columns freeze at their last pre-suspension instant — so a cross-replica commit-time delta + /// stops growing exactly when replication stops, i.e. it looks like it is catching up. The sharpest example + /// is any DRAIN-TIME measure: queue ÷ rate with both frozen holds a small, static, healthy-looking number + /// (measured at a flat 0.0144 minutes across an entire suspension) when the true answer is "never, movement + /// is stopped". A drain-time or commit-delta trigger added here would therefore fail SILENT rather than + /// loud, which is worse. Anything new that judges a suspended row must route through the same + /// may-fire-never-clear gate below rather than being trusted on its own. + /// WHAT THE NUMBER IS NOT: it measures staleness, not volume. On an idle group a large lag means + /// "nothing has been hardened in a while", which is not the same as "a lot of data is at risk" — the + /// backlog measure would be log_send_queue_size, and that reads NULL while suspended. Worth knowing + /// before tuning ag_lag_alert_seconds by staring at the value. /// Not clearing has to be its OWN answer rather than a false, or the caller reads it as /// recovery: a lagging database that becomes suspended (or whose columns go NULL under quorum loss) would /// emit "AG Sync Recovered — has caught up with the primary" in the same sweep that reports it suspended. @@ -929,7 +953,11 @@ await FireAsync( "secondary's redo thread (it is single-threaded per database on older versions and is " + "easily starved by CPU or storage latency on the secondary), and whether something on the " + "primary — an index rebuild, a bulk load, a long transaction — is generating log faster " + - "than the secondary can consume it.", + "than the secondary can consume it. Read the figures for what they measure: the lag " + + "seconds are how STALE the secondary's last hardened log is, not how much data is queued " + + "behind it, so on a quiet group a large value can simply mean nothing has been written " + + "recently. While data movement is suspended the redo queue is frozen at its last reading, " + + "and log_send_queue_size — the actual backlog measure — reports nothing at all.", severity: AlertSeverityLevel.Warning, shortMessage: behindReason, cancellationToken); }