Skip to content

Fix Poison Wait alert re-firing on an unrefreshed wait_stats row - #2704

Merged
erikdarlingdata merged 1 commit into
devfrom
fix/poisonwait-cooldown-refire
Aug 31, 2026
Merged

erikdarlingdata merged 1 commit into
devfrom
fix/poisonwait-cooldown-refire

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

Fixes #2703.

Problem

`AlertEngine.CheckPoisonWaitsAsync` gates re-firing purely on wall-clock cooldown (`CooldownElapsed`). `IAlertReadAdapter.GetPoisonWaitDeltasAsync` always asks "what's the newest poison-wait `wait_stats` row within the last 10 minutes" (`ORDER BY collection_time DESC LIMIT 3`) — independent of whether that row is NEW since the last ask. When the collector's delivered cadence lags the alert cooldown (documented fleet behavior at load), the same still-unrefreshed row answers the question twice, and the engine fires again on data it already reported. Observed live: byte-identical `RESOURCE_SEMAPHORE_QUERY_COMPILE` alerts on the same server 6.5 minutes apart, same avg/delta/task values to the decimal.

This is unlike CPU's alert, which is correctly level-triggered (resampled live every sweep — an identical reading really is a fresh observation of a standing condition). A wait_stats delta is one collector cycle's computation; reading it twice is the same event, not two observations.

Fix

  • `PoisonWaitDelta` gains `CollectionTime` (the row's own `collection_time`).
  • Both read-adapter implementations (Darling/Postgres, Lite/DuckDB) select and populate it — one added column in an already-parameterized query, no behavior change to what rows are selected.
  • `AlertEngine` tracks the collection_time it last actually fired on, per server, in a new `_lastPoisonWaitCollectionTime` dictionary (mirroring the existing per-family cooldown dictionaries). Re-fire now requires BOTH cooldown elapsed AND a newer collection_time than last fired — a cooldown-elapsed re-ask against unrefreshed data waits for the next sweep instead of re-firing.

Test plan

  • `dotnet build` (full solution) clean, 0 errors
  • New test `PoisonWait_DoesNotRefire_OnTheSameCollectionTime_EvenAfterCooldownElapses` in `AlertEngineTests.cs`: fires once, then asserts a cooldown-elapsed re-ask against the SAME collection_time does NOT re-fire, then asserts a genuinely new collection_time (same wait-type/value shape) DOES fire. Hand-traced against the new gating logic; Darling.Tests can't run on macOS (net10.0-windows) — relying on CI's `Darling PostgreSQL tests`/`build` jobs to actually execute it.
  • Existing `PoisonWait_FiresWithWorstWaitNumerics_AndResolvesWhenGone` and Lite's `PoisonWait_ToastBody_UsesTheWorstWait` unaffected — both fire only once per test, so the new gate is a no-op on their paths (empty tracking dictionary on first fire).

🤖 Generated with Claude Code

CheckPoisonWaitsAsync gated re-fire purely on wall-clock cooldown, with no
way to know whether the underlying wait_stats delta had actually changed
since the last fire. When the collector's delivered cadence lagged the
cooldown, the read adapter's "newest row in the last 10 minutes" query
handed back the SAME row on consecutive sweeps, producing byte-identical
duplicate alerts (observed live: two RESOURCE_SEMAPHORE_QUERY_COMPILE
alerts 6.5 minutes apart with identical avg/delta/task values).

PoisonWaitDelta now carries the row's own collection_time, threaded
through both read adapters (Darling/Postgres and Lite/DuckDB). AlertEngine
tracks the collection_time it last fired on per server and requires it to
be newer than that, in addition to cooldown elapsed, before re-firing.
Unlike CPU (legitimately level-triggered — resampled live every sweep), a
wait_stats delta is one collector cycle's computation; reading it twice
is the same event surfacing twice, not a fresh observation.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@claude

claude Bot commented Aug 31, 2026

Copy link
Copy Markdown

Reviewed. This is a clean, well-scoped fix.

Correctness: The gating logic is sound. triggered is already ordered by collection_time DESC (both adapters), so triggered.Max(w => w.CollectionTime) is consistent with whatever subset survives the post-fetch threshold filter — no mismatch between "worst" (triggered[0]) and "newest" in practice. The new dictionary is only stamped inside the same gate that fires the alert, mirroring the existing _lastPoisonWaitAlert[key] = now pattern.

Parity: AlertEngine is shared between Lite and Darling, so the core gating change only needed to land once. Both read adapters — DarlingAlertReadAdapter.PoisonWaitsSql (Postgres) and LocalDataService.GetLatestPoisonWaitAvgsAsync (DuckDB) — got the same collection_time column added at the same select-list position (ordinal 4), and both constructors populate it via reader.GetDateTime(4) with no IsDBNull guard, consistent with how collection_time is already handled elsewhere in DarlingAlertReadAdapter.cs (e.g. CurrentBlockingWaitSql). No drift.

Tests: PoisonWaits_ToastBody_UsesTheWorstWait (Lite) and PoisonWait_FiresWithWorstWaitNumerics_AndResolvesWhenGone (Darling) both fire only once per test, so CollectionTime defaulting to DateTime.MinValue on those un-updated PoisonWaitDelta literals is harmless — the new gate is a no-op on the first observation for any key (empty dictionary → hasFreshCollection = true). The new regression test correctly advances the clock past the 5-minute default cooldown before asserting no re-fire on the same collection_time, then advances again with a new collection_time to assert it does fire.

Minor, pre-existing, not introduced by this PR: triggered[0] is documented ("worst… highest avg ms/wait") but the query only orders by collection_time DESC, not by avg_ms_per_wait. So "worst" is really "most recently collected," not "worst by magnitude," whenever more than one wait type triggers in the same window. Out of scope here since the diff doesn't touch that ordering, just flagging for awareness.

No correctness, parity, security, or performance concerns that block this.

@erikdarlingdata
erikdarlingdata merged commit 02ae97c into dev Aug 31, 2026
6 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/poisonwait-cooldown-refire branch August 31, 2026 10:46
erikdarlingdata added a commit that referenced this pull request Aug 31, 2026
Never deduping RootBackendId == 0 rows (the fix for the earlier collision
finding) traded one bug for another: the SAME persisting vanished-root
block, sampled every sweep, added a new list entry every cycle, so
RollingCountAlertGate's watermark kept climbing and "Blocking Detected"
would re-fire every cooldown for one ongoing incident - exactly the
#1091/#2704/#2708 class this design is supposed to be immune to.

Fixed: sentinel rows now dedupe by RootPid instead of never deduping,
narrowing the risk to pid reuse inside one rolling 1-hour window rather
than either merging unrelated incidents (the original bug) or guaranteed
re-alerting on a persisting one (this regression). RootPid was already
the identity BuildPgBlockingIncident folds into that case's DedupKey, so
this makes the count and the fingerprint agree on what identifies a
sentinel incident.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
pull Bot pushed a commit to ehtick/PerformanceMonitor that referenced this pull request Sep 10, 2026
…ctor_cost row (erikdarlingdata#2707)

DarlingSelfAlertEvaluator.ApplyCostRegressionsAsync gated re-firing on
cooldown-elapsed alone, with no memory of which collect.collector_cost
data point it last alerted on. If the hourly store-metrics tick's cadence
ever outpaces the cooldown, or the flush itself lags a tick, re-asking
GetCostRegressionsAsync hands back the identical latest_ms computed from
the identical underlying rows - observed today as byte-identical repeat
alerts on harvest-01/plan_correction and multi-24/ag_replica_states.

Same shape as erikdarlingdata#2703/erikdarlingdata#2704 (Poison Wait). Added LatestMetricTime to
CostRegression - the newest collect.collector_cost row actually folded
into latest_ms - and require it to have advanced past what was last
alerted on before re-firing, in addition to cooldown-elapsed.

Verified the SQL change against a real local Postgres 17: latest_metric_time
stays put with no new hourly row, advances only once one lands.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
pull Bot pushed a commit to ehtick/PerformanceMonitor that referenced this pull request Sep 10, 2026
The Postgres analogue of SQL Server's Poison Wait alert, watching the
IPC:BtreePage / IPC:BufferIo pair identified by the issue's fleet
research: near-zero on a healthy server, a structural inter-backend
contention signal no other alert covers when it accumulates. Fires on
total accumulated wait time normalized to a 10-minute window (Warning
at an average of one backend continuously stuck, Critical at ten),
per event, because an avg-ms-per-wait bar can never see 1-2 ms waits
at six-figure volumes.

Follows the engine-gated sibling path (PostgresAlertEvaluator +
DarlingPostgresAlertReadAdapter, delivered from DarlingWorker), the
shared PoisonWaitEnabled switch (erikdarlingdata#2722's precedent), per-subject
cooldown keying (erikdarlingdata#1140), the unrefreshed-source-row guard (erikdarlingdata#2704),
and history-seeded restart survival (erikdarlingdata#2716/erikdarlingdata#2723).

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01JgLaaxFenZFZs1SntKQDEg
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant