Skip to content

Under store contention the alert pass fails first and silently, so the self-alert that would report it is the first thing lost #3013

Description

@erikdarlingdata

When the store is contended, the reads that fail first are the alerting subsystem's — including the self-alert whose job is to report that collection is unhealthy. The operator loses the warning at exactly the moment it becomes true.

Observed

During a period of store-side lock contention, the service log carried 41 → 61 [ERROR lines per hour, rising. Every one is a store read from the alerting/analysis side:

[ERROR] [DarlingWorker] Failed to check forced-plan failures for <server>: Exception while reading from stream
[ERROR] [DarlingWorker] [<server>] Collection-health self-alert failed: Exception while reading from stream

Over the same hours, actual collector failures in collection_log were falling — 23 in the 09:00 hour, then 7, then 5, then 2.

Two populations, moving in opposite directions, and the one that was rising is the one nobody sees: these reads are not collector runs, so they produce no collection_log row and appear on no health surface. Only a log grep finds them.

Why the split goes this way

Deadline stratification. The alert pass runs on the ~10 s budget from #2882; collectors run on much longer ones. As store latency rises, the short-deadline consumers cross their limit first and at a rising rate, while the long-deadline ones still complete. So the first casualty of store contention is the alerting layer, and the last is the thing alerting is meant to report on.

That ordering is the defect. It means the system's failure mode is to go quiet rather than to complain: collection degrades, the self-alert that would say so times out, and the surfaces stay green because a failed alert read is not a failed collection.

Relationship to existing work

Same family as #2953 (every health surface reports healthy when the store is unreachable) — that issue is about the store being down; this is the same blindness arriving through the store merely being slow, which is both more common and harder to notice. #2882 chose the 10 s alert budget deliberately and correctly for its own reasons; the problem is not the number but that nothing reports when it is being exceeded.

What would fix it

The failures are already caught and logged — they simply do not reach any surface a person reads. Options, ascending:

  1. Count them. A per-pass counter of alert-read failures, exposed where collection health is exposed. A nonzero value means "this instance's alerting is degraded" and is currently unavailable at any price.
  2. Alert on the alerting. A failed self-alert read is exactly the condition the self-alert exists for; the delivery path does not depend on the store read that failed, so it can still fire.
  3. Distinguish the exhaustion. A read that fails on deadline under contention is a different fact from one that fails because the store is unreachable, and the operator action differs (wait / tune the store vs. the store is down). Today both render as the same seven-word Npgsql message.

(1) is the minimum that closes the blind spot.

Not verified

Whether the alert deliveries were also missed, or only these particular reads — the alert history was not checked against the same window, and it is possible the pass recovered on a later cycle and delivered late rather than not at all. That check needs the alert-history table over the contended hours and would sharpen the severity either way.

Activity

  1. erikdarlingdata commented on Sep 5, 2026

    @erikdarlingdata
    OwnerAuthor

    Claude posting for Erik Darling

    Closed by #3040, merged to dev at e022af1d2e4c25f598fbe4fb7a4adc4d0a8c796c. Closing by hand because a closing keyword does not fire against dev.

    The alert pass now reports its own failed store reads, at both scopes — a per-server-only figure would have reproduced this issue's defect one level down, since the fleet-scoped conditions belong to no server. The counter lives in memory in PerformanceMonitor.Alerting and is deliberately not persisted: what it counts is a failure to read the store.

    The most consequential thing this produced is not the counter. Instrumenting the pass exposed a latent outage-shaped behaviour in it. A failed latest-CPU read — the pass's first store read, on the shortest deadline, so the first to fail under exactly the contention this issue documents — aborted the entire shared sweep for that server that tick. Blocking, deadlocks, poison waits, long-running queries, TempDB, low disk, PVS, file growth, jobs, database state and forced plans all went unevaluated, with nothing saying so. Pre-existing; the counter only made it visible, and it could not be made honest without fixing it. The read now has its own try and degrades to a null CPU pair, which the snapshot already documents as normal input.

    One correction to this issue's framing, in the reassuring direction. Alert history was reachable, contrary to the brief: 66 rows across the contended window, continuous every hour, every send_error null, firing and resolution pairs complete. Deliveries were not missed — only the reads were. That lowers the severity and is worth having on the record.

    Population: 27 counted sites, 17 exempt, each with a stated reason.

    Four review findings, three upheld and one declined with the measurement — SaveFailedJobWatermarkAsync cannot throw, because both stores swallow and log it, so the reported mislabel was unreachable. Chasing it anyway found a real inconsistency: a target-side msdb read was being counted here while the identical population was exempted in the worker.

    Not verified: no live-store round trip on either SKU, the counter has never been observed non-zero in production, and the web panel is unrendered. The CPU-read isolation is pinned structurally rather than exercised at runtime — reaching that body needs a live store, and a test that opens a socket to prove a control-flow property is a flaky test proving what the source already settles.

    One question this raised is still open and is not part of this issue. With alerts.enabled off, the PostgreSQL Tier 0 predictors still read, still evaluate and still deliver — measured as zero AlertsEnabled references in DarlingWorker.cs against one in AlertEngine.cs and ten in DarlingSelfAlertEvaluator.cs. That pre-dates this counter. Gating it changes what alerts fire on a live fleet, which is not something a reporting change should decide by side effect, so it is routed rather than assumed in either direction. Filed separately once answered.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions