Health dashboard renders in 5 s when the Notification Outbox holds ~1M Parked rows (KPI tile timeout and uncached) #122

Closed
opened 2026-11-10 15:58:30 -05:00 by dohertj2 · 1 comment
Owner

Found by the #49 [xc-8] UI run (docs/plans/2026-11-10-wp4-residual-scope-results.md §6, docker/measure-ui-responsiveness.sh).

Symptom. On the docker rig, /monitoring/health takes up to 5.0 s to render (idle P50 3.4 s, max 5.05 s over 5 loads). Every other page renders in 25–425 ms. The Notification Outbox tile then shows "Notification Outbox KPIs unavailable: KPI query timed out."

Cause.

  • The rig's Notifications table holds 4.35 M rows: 944,597 Parked (soak traffic since 2026-08-01) and 3.4 M Delivered.
  • NotificationOutboxRepository.ComputeKpisAsync has to count every Parked row. Measured on the rig: a parallel clustered scan, 374,043 logical reads, 1.3 s elapsed warm, per query.
  • The page runs the global, per-site and per-node outbox KPIs. Together they exceed Health.razor's 5 s TileTimeout.
  • A timed-out snapshot is never cached, so the next render pays the full 5 s again. The tile loads run inside OnInitializedAsync, so prerender blocks the whole page for the timeout.
  • Under load (6 other operator sessions keeping the snapshot cache warm), the same page renders in 38 ms. So this hits the first viewer on a cold cache, i.e. a lone operator.

Why it matters. Parked rows are not purged (only terminal rows age out), so any central with a long-running delivery fault will build a backlog like this. A misconfigured SMTP for a few weeks is enough.

Options (not decided).

  • Count Parked from a narrow index: the (Status, NextAttemptAt) index covers Status = 'Parked', but the OR'd predicate makes the optimizer scan the clustered index. Split the conditional aggregate into per-status seeks.
  • And/or cache the last good snapshot and let a timed-out refresh keep showing it, marked stale.
  • And/or load the tiles after first render rather than in prerender.
Found by the #49 `[xc-8]` UI run (`docs/plans/2026-11-10-wp4-residual-scope-results.md` §6, `docker/measure-ui-responsiveness.sh`). **Symptom.** On the docker rig, `/monitoring/health` takes up to **5.0 s** to render (idle P50 3.4 s, max 5.05 s over 5 loads). Every other page renders in 25–425 ms. The Notification Outbox tile then shows *"Notification Outbox KPIs unavailable: KPI query timed out."* **Cause.** - The rig's `Notifications` table holds 4.35 M rows: 944,597 `Parked` (soak traffic since 2026-08-01) and 3.4 M `Delivered`. - `NotificationOutboxRepository.ComputeKpisAsync` has to count every Parked row. Measured on the rig: a parallel clustered scan, 374,043 logical reads, 1.3 s elapsed warm, per query. - The page runs the global, per-site and per-node outbox KPIs. Together they exceed `Health.razor`'s 5 s `TileTimeout`. - A timed-out snapshot is never cached, so the next render pays the full 5 s again. The tile loads run inside `OnInitializedAsync`, so prerender blocks the whole page for the timeout. - Under load (6 other operator sessions keeping the snapshot cache warm), the same page renders in 38 ms. So this hits the first viewer on a cold cache, i.e. a lone operator. **Why it matters.** Parked rows are not purged (only terminal rows age out), so any central with a long-running delivery fault will build a backlog like this. A misconfigured SMTP for a few weeks is enough. **Options (not decided).** - Count Parked from a narrow index: the `(Status, NextAttemptAt)` index covers `Status = 'Parked'`, but the OR'd predicate makes the optimizer scan the clustered index. Split the conditional aggregate into per-status seeks. - And/or cache the last good snapshot and let a timed-out refresh keep showing it, marked stale. - And/or load the tiles after first render rather than in prerender.
dohertj2 added the priority:p2type:bug labels 2026-11-10 15:58:53 -05:00
Author
Owner

Fixed in 424db155.

Root cause, re-measured. My earlier 1.3 s figure was wrong. sqlcmd runs with QUOTED_IDENTIFIER OFF by default, which disables filtered indexes. Re-run with sqlcmd -I, the global outbox KPI query on the rig (4.35 M rows: 945 k Parked, 3.4 M Delivered) took 0.7–2.6 s and 76 k logical reads, with a parallel clustered scan. The cause is the OR of Pending | Retrying | Parked | (Delivered AND DeliveredAt >= since) in the pre-filter: it stops the optimizer from seeking any of the three indexes that cover the legs.

Fix. NotificationOutboxRepository.ComputeKpisAsync / ComputePerSiteKpisAsync / ComputePerNodeKpisAsync now run three status-equality legs and merge them in memory:

leg index reads time
live Status IN (Pending, Retrying): depth, stuck, oldest (Status, NextAttemptAt) 195 ~1 ms
Status = Parked count (Status, NextAttemptAt) 18 k ~0.1 s
Delivered AND DeliveredAt >= since filtered IX_Notifications_Delivered 5 ~0 ms

Global snapshot: 0.7–2.6 s → ~0.12 s. Per-site/per-node still have to read every parked row to group it (~1 s on the rig), but the live and delivered legs no longer ride along. No schema change and no migration.

NotificationOutboxRepositoryKpiQueryShapeTests now pins at most three queries per snapshot, and that no query ORs Parked with the live statuses. A new merge test covers keys that appear in only one leg.

I did not change the Health page's caching or prerender: with the query at ~0.12 s the 5 s tile timeout is no longer reached. Rig check after redeploy: five lone-viewer cold-cache loads of /monitoring/health, 12 s apart, rendered in 0.12–0.52 s (was P50 3.4 s, max 5.05 s), with every KPI tile populated.

Fixed in 424db155. **Root cause, re-measured.** My earlier 1.3 s figure was wrong. `sqlcmd` runs with `QUOTED_IDENTIFIER OFF` by default, which disables filtered indexes. Re-run with `sqlcmd -I`, the global outbox KPI query on the rig (4.35 M rows: 945 k Parked, 3.4 M Delivered) took **0.7–2.6 s** and 76 k logical reads, with a parallel clustered scan. The cause is the OR of `Pending | Retrying | Parked | (Delivered AND DeliveredAt >= since)` in the pre-filter: it stops the optimizer from seeking any of the three indexes that cover the legs. **Fix.** `NotificationOutboxRepository.ComputeKpisAsync` / `ComputePerSiteKpisAsync` / `ComputePerNodeKpisAsync` now run three status-equality legs and merge them in memory: | leg | index | reads | time | |---|---|---|---| | live `Status IN (Pending, Retrying)`: depth, stuck, oldest | `(Status, NextAttemptAt)` | 195 | ~1 ms | | `Status = Parked` count | `(Status, NextAttemptAt)` | 18 k | ~0.1 s | | `Delivered AND DeliveredAt >= since` | filtered `IX_Notifications_Delivered` | 5 | ~0 ms | Global snapshot: 0.7–2.6 s → **~0.12 s**. Per-site/per-node still have to read every parked row to group it (~1 s on the rig), but the live and delivered legs no longer ride along. No schema change and no migration. `NotificationOutboxRepositoryKpiQueryShapeTests` now pins at most three queries per snapshot, and that no query ORs `Parked` with the live statuses. A new merge test covers keys that appear in only one leg. I did not change the Health page's caching or prerender: with the query at ~0.12 s the 5 s tile timeout is no longer reached. Rig check after redeploy: five lone-viewer cold-cache loads of `/monitoring/health`, 12 s apart, rendered in 0.12–0.52 s (was P50 3.4 s, max 5.05 s), with every KPI tile populated.
Sign in to join this conversation.