test(perf): measure phase-8 WP-4 residual criteria xc-3/4/5/8 (#49)

New ResidualBench tool (eventlog, flatten, audit, audit-contention) and
docker/measure-ui-responsiveness.sh. All four residuals pass; results in
docs/plans/2026-11-10-wp4-residual-scope-results.md. Findings filed as
#122, #123 and #124 (fixed in the following commit).
This commit is contained in:
Joseph Doherty
2026-11-10 16:46:42 -05:00
parent 48517b49fb
commit 2b80a6defa
13 changed files with 1619 additions and 2 deletions
@@ -30,7 +30,7 @@ All 7 fix-now items landed via PLAN-04/05/06/07/08 (verified in review 08 round
| 27 | ~~External-system per-system retry config (`MaxRetries`/`RetryDelay`) never reaches sites, and has no CLI/management surface~~ **RESOLVED 2026-08-15 (`41a5ecf1`).** The gap was transport + persistence only — the consumption end already worked (`ExternalSystemClient.CachedCallAsync` already passed `system.MaxRetries`/`RetryDelay` to `EnqueueAsync` with 0-as-unset, and the Central UI form already collected both fields, inert until now with defaults 3×5s that will take effect on next deploy). Shipped: artifact fields, additive `site_command.proto` fields 7/8 (regen via `docker/regen-proto.sh`, csproj left clean), site `external_systems` columns `max_retries`/`retry_delay_ms` as REAL COLUMNS — not a JSON bag; verified safe against the AckTime precedent in the LocalDb source (capture triggers are DROP-then-CREATE from `PRAGMA table_info` each boot, and the fail-closed handshake digest turns a mixed-version pair into a loud sync refusal, no new constraint since both-nodes-together is already the standing pair rule; `timeout_seconds` set the additive-column precedent on this exact table) — apply path, and CLI `--max-retries`/`--retry-delay-seconds` (+`--retry-delay` alias). Bonus fix: `ArtifactDiff.CompareExternalSystem` never compared the retry fields, so a bundle import changing a retry budget previewed as "Identical". Fail-before verified on the site round-trip + apply tests; 12 suites green. | Found live 2026-08-01 (rig session, #11 gRPC live checks) | Closed 2026-08-15. | — |
| 28 | ~~Health-dashboard "Trigger failover" confirm dialog's confirm button is labeled **"Delete"**~~ **RESOLVED 2026-08-15 (`0db253b5`).** Structural, not a missing argument: `IDialogService.ConfirmAsync` had NO label parameter — `DialogHost` derived the verb from `danger` alone (`danger ? "Delete" : "Confirm"`), so no call site could ever have passed one. New optional `confirmLabel`; `danger` now selects styling only. Full audit of all 34 `ConfirmAsync` call sites (the only confirmation path — no `window.confirm`, no per-page modals): NINE were wrongly labeled "Delete" — both failover buttons, secured-write **Approve** and **Reject**, instance Disable, and four Discard actions — all now name their action; 18 genuine deletes + 7 non-danger sites verified correct. The `danger→"Delete"` fallback deliberately kept: forcing an explicit label would churn ~20 correct sites, and a missed site would silently degrade to "Confirm", detectable only by the rig-dependent Playwright suite — contract pinned in the interface XML doc, Component-CentralUI.md, and a fallback test instead. Gotcha recorded in the tests: adding an optional parameter silently un-matches existing 3-arg NSubstitute stubs (returns null Task → NRE). Follow-ups: rows 75 (Approve's red styling), and the bUnit real-dialog deadlock hazard documented in `FailoverConfirmLabelTests`. | Found live 2026-08-01 (rig session, #11 TriggerSiteFailover check) | Closed 2026-08-15. | — |
| 29 | ~~**1-hour sustained run to settle the memory-slope ambiguity (load-test finding F1)**~~ **RESOLVED 2026-08-15 — run, and F1 is settled: NOT a leak.** Full 1-hour protocol executed (same harness/scale, `--sustain-minutes 60`, 135,041,250 updates at 37,511/s = 100.0 % of nominal, concurrent with the live docker rig AND a central failover drill on the same host). Decisive: **working-set slope −28.89 MB/min** (2,722 → 1,757 MB over the 3,600 s window, peak 3,258 MB) with **one gen-2 collection observed** and threads flat at 59 — a working set that FALLS ~1 GB across a sustained hour is incompatible with a slow leak; the positive managed-heap least-squares slope was the sawtooth-segment artifact F1 hypothesised. All other metrics held or improved vs the 20-min run: P99 4.01 ms, 0 healthy-subscriber drops, 744/744 debug snapshots, S&F drain to depth 0. Full numbers appended to the results doc F1 section. | `docs/plans/2026-08-15-target-scale-load-test-results.md` F1 postscript | Closed 2026-08-15. | — |
| 30 | **→ #49** **WP-4 residual scope: `[xc-3]` site-event-log retention volume, `[xc-4]` audit-load-vs-central degradation, `[xc-5]` large-template flattening time, `[xc-8]` UI responsiveness under load** | `docs/plans/2026-08-15-target-scale-load-test-results.md` §6 + row 25 closure note | The row-25 harness is a site-runtime rig; these four WP-4 sub-criteria are central-cluster/browser concerns it deliberately does not cover. Recorded so the row-25 closure never reads as "WP-4 fully done" — phase-8 WP-4 is closed for the site-runtime data path only. | Before declaring phase-8 WP-4 complete, or production go-live at target scale |
| 30 | **→ #49 — measured 2026-11-10, all four PASS (`docs/plans/2026-11-10-wp4-residual-scope-results.md`; follow-ups #122–#124)** **WP-4 residual scope: `[xc-3]` site-event-log retention volume, `[xc-4]` audit-load-vs-central degradation, `[xc-5]` large-template flattening time, `[xc-8]` UI responsiveness under load** | `docs/plans/2026-08-15-target-scale-load-test-results.md` §6 + row 25 closure note | The row-25 harness is a site-runtime rig; these four WP-4 sub-criteria are central-cluster/browser concerns it deliberately does not cover. Recorded so the row-25 closure never reads as "WP-4 fully done" — phase-8 WP-4 is closed for the site-runtime data path only. | Before declaring phase-8 WP-4 complete, or production go-live at target scale |
| 31 | **Unpaced-burst absorption is bounded by the shared publish stage, not per-subscriber buffers (load-test finding F3 caveat)** | `docs/plans/2026-08-15-target-scale-load-test-results.md` F3 | Measurement-backed design note, no defect: slow-subscriber isolation is structural and total (a stalled reader loses events only in its own bounded `DropOldest` channel; healthy subscribers delivered 100.00%), but the publish `Source.ActorRef` **upstream** of the `BroadcastHub` is shared, so an unpaced burst degrades every subscriber equally — that stage, not per-subscriber buffering, is the burst ceiling. | First field report of event loss on *healthy* subscribers during a burst, or any redesign of the site stream publish stage |
| 32 | ~~**`QueueDepthGaugeTests` full-suite flake — shared static gauge (load-test finding F4)**~~ **RESOLVED 2026-08-15 (`65b19516`).** Reproduced first (2 failures in 5 parallel runs — the gauge read a sibling class's provider). The register's suggested fix (per-test meter) was rejected on inspection: the slot is process-global by product design and 3 of the 6 facts assert the slot-ownership semantics themselves (compare-and-clear identity, stop/restart re-seed), so per-test instances would change what they prove. Correct isolation is mutual exclusion — the three `StartAsync`-calling classes now share xunit collection `QueueDepthGaugeCollection` (with a `[CallerFilePath]`-anchored source-scan drift guard that names an offending file), the other eight classes stay parallel, and `parallelizeTestCollections` was flipped back ON so the fix is exercised rather than masked. Negative control: dropping the attribute fails the guard AND resurfaces the original flake in the same run. 8/8 green parallel runs. | `tests/…StoreAndForward.Tests/QueueDepthGaugeTests.cs`; surfaced by the row-25 verification runs | Closed 2026-08-15. | — |
| 33 | ~~**`LocalDbOplogBacklog` has no threshold, KPI history, or dashboard treatment**~~ **RESOLVED 2026-08-15 (`8da60f57`).** Both halves shipped: sampled into KPI history via `SiteHealthKpiSampleSource` (conditionally — 12 samples unreplicated / 14 replicated, so a series gap truthfully means "not replicated") plus a backlog trend chart on the site health panel, and a SUSTAINED threshold badge (`LocalDbBacklogThreshold` 1000 held for `LocalDbBacklogSustainedFor` 15 min, anchored by `LocalDbBacklogAboveSince` in the aggregator) — a bare instantaneous threshold would fire on every replicated site every day from the documented purge burst. Null backlog is a deliberate third branch: it leaves the anchor unchanged (neither evidence of a drain nor of a backlog), so unreplicated sites can never anchor and can never be badged. NOTE the row's premise was false — the `SiteAuditBacklog` "configurable threshold badge" it told us to mirror was described twice in `Component-HealthMonitoring.md` but NEVER BUILT; both stale doc claims corrected, and the new badge was modeled on the real Metrics-stale badge instead. | Found by R7 while documenting the purge burst | Closed 2026-08-15. | — |
@@ -296,7 +296,8 @@ Recorded rather than silently dropped (deviation D7):
| `[xc-8]` UI workflows remain responsive | Needs a browser + a live central cluster (Playwright territory) |
These remain open scope for WP-4 and should be tracked separately rather than being
considered closed by this run.
considered closed by this run. **Covered 2026-11-10 (#49):** see
`docs/plans/2026-11-10-wp4-residual-scope-results.md`.
## 7. Reproducing
@@ -0,0 +1,339 @@
# WP-4 residual scope — results (`[xc-3]`, `[xc-4]`, `[xc-5]`, `[xc-8]`, ScadaBridge#49)
**Date:** 2026-11-10
**Closes:** the four WP-4 sub-criteria that the target-scale load test left open
(`docs/plans/2026-08-15-target-scale-load-test-results.md` §6, deferred-work register row 30 → #49).
**Tools (committed):** `tests/ZB.MOM.WW.ScadaBridge.ResidualBench/` (modes `eventlog`, `flatten`, `audit`)
and `docker/measure-ui-responsiveness.sh`.
## 1. Environment
| | |
|---|---|
| Host | Apple M4 Pro, 14 logical cores, 48 GB RAM, macOS 26.5.2 |
| Runtime | .NET 10.0.14, Release, server GC |
| Commit | `48517b49` + the bench tool in this change |
| Rig data (for `[xc-8]`) | 14 instances, 36 templates, **10.9 M `AuditLog` rows, 4.35 M `Notifications`** (944,597 Parked) from months of soak traffic |
| SQL Server | `scadabridge-mssql` — SQL Server 2022 RTM-CU22 Developer, **amd64 image under emulation** on Apple silicon (OrbStack, 14 vCPU / 16 GB VM). Absolute SQL timings are pessimistic; compare ratios. |
| Concurrent load | The 8-node `docker/` rig stayed up throughout (it is the target of `[xc-8]`), as in the 2026-08-15 run. Benchmarks were run one at a time, never overlapping. |
## 2. Verdict summary
| Criterion | Threshold used | Measured | Verdict |
|---|---|---|---|
| `[xc-3]` site event logging handles volume within the 30-day / 1 GB limits | writer keeps up with any realistic event rate without loss; queries usable on a full 1 GB log; the cap is enforced | 1 GB = 2.36 M events = 30 days only at ≤ 0.91 events/s per site; writer 10,500 events/s with CDC (11,500× that); storms ≤ 10,000 absorbed with 0 drops; every query ≤ 0.5 s warm on a full 1 GB log; one purge tick restores the cap in 12.8 s; no writer impact from concurrent scans | **PASS**, with an operational caveat: above ~1 event/s the **1 GB cap**, not the 30 days, sets retention (§3.1) |
| `[xc-4]` audit logging does not degrade central | central read P95 stays inside the UI budget (< 1 s) while ingest runs at and above the expected fleet rate | 1 M rows / 3.26 GB seeded through the production ingest path; reads P95 ≤ 22 ms up to 500 rows/s ingest, ≤ 160 ms at the single-writer ceiling (~1,000–1,500 rows/s); non-audit reads unaffected; 0 deadlocks with one writer | **PASS**, with an observation: concurrent set-based inserts deadlock (1205, #124) |
| `[xc-5]` flattening/validation within acceptable time for large templates | deploy-gate validate of one large template < 5 s; 500-instance bulk CPU well inside the 120 s site-deploy budget | 4,400-attribute / 400-alarm / 220-script, 8-deep template: flatten 3.6 ms, deploy-gate validate 1.9 s cold / 2.3 ms warm, hash 5.7 ms; 500 instances flatten+validate+hash in 3.5 s | **PASS** (34× inside the 120 s budget) |
| `[xc-8]` UI workflows remain responsive | page usable P95 < 3 s under load, no page > 10 s | 14 pages, rig with 10.9 M AuditLog / 4.35 M Notification rows; under 6 concurrent operator sessions + 20 inbound API calls/s: P50 46 ms, P95 1.18 s, max 3.0 s (Audit Log). Idle: every page ≤ 0.7 s **except Health, up to 5.05 s** | **PASS** against the threshold, with one defect: the Health dashboard blocks up to 5 s on a cold KPI cache (#122) |
The requirements give no numeric thresholds for these four. The thresholds above were chosen
for this run and are stated so the verdicts can be re-judged.
---
## 3. `[xc-3]` Site event log — `ResidualBench eventlog`
Real `SiteEventLogger`, `EventLogQueryService` and `EventLogPurgeService` over a real
`ZB.MOM.WW.LocalDb` file. The event mix models the post-WP3.2 stream (per-run script events
off): 45% alarm transitions, 25% script failures/warnings, 15% connection quality changes,
10% S&F parks, 5% lifecycle; 2-in-3 rows carry an instance id and 1-in-10 carry an ~800-byte
stack trace.
### 3.1 What 1 GB holds
| | |
|---|---|
| On-disk bytes per row (table + 4 indexes + PK) | **454** |
| Rows at the 1 GB cap | **2,364,426** |
| Sustained rate that keeps 30 days inside 1 GB | **≤ 0.91 events/s per site** (78,800/day; **158 per instance per day** at 500 instances) |
| Retention actually achieved at 5 events/s | 5.5 days |
| Retention actually achieved at 20 events/s | 1.4 days |
**The binding limit is the 1 GB cap, not the 30-day window, for any site averaging more than
about one event per second.** That is by design — `MaxStorageMb` wins over `RetentionDays`
(the cap trim deletes oldest-first) — but it means "30-day event history" holds only for quiet
sites. A 500-machine site whose alarms average more than ~150 transitions per machine per
day will keep less than 30 days. Raise `ScadaBridge:SiteEventLog:MaxStorageMb` for such
sites if 30 days matters; disk cost is ~0.45 KB per event.
### 3.2 Writer throughput
| | CDC off (unreplicated site) | CDC on (`RegisterReplicated`, the replicated site-a shape) |
|---|---|---|
| Sustained drain (200,000 events, offered in 5,000-event windows) | **34,000 events/s**, 0 failed | **10,500 events/s**, 0 failed |
| vs the 30-day-in-1-GB rate | 37,000× | 11,500× |
| Storm of 5,000 / 10,000 events offered at once | settled in 0.23 / 0.42 s, **0 dropped** | 0.70 / 1.43 s, **0 dropped** |
| Storm of 25,000 events offered at once | **14,723 dropped** | **14,733 dropped** |
The bounded write queue (`WriteQueueCapacity` 10,000, DropOldest) absorbs any single burst
up to its capacity. A burst much larger than that, arriving faster than the writer drains,
loses the oldest queued events — counted in `FailedWriteCount` and surfaced on the health
report as `SiteEventLogWriteFailures`, never silent. CDC capture triggers cost ~3.2× on
write throughput; the replicated rate is still four orders of magnitude above the rate the
storage cap can retain.
### 3.3 Queries on a full 1 GB, 30-day log (page size 500)
| query (page size 500) | first ms | warm P50 ms | warm max ms | rows | has more |
|---|---|---|---|---|---|
| no filter, page 1 (oldest first) | 8.5 | 1.1 | 1.1 | 500 | True |
| last 1 h | 1.3 | 1.1 | 1.1 | 500 | True |
| last 24 h | 1.2 | 1.0 | 1.0 | 500 | True |
| severity=Error, 30 d | 2286.8 | 114.5 | 485.6 | 500 | True |
| severity=Error, last 24 h | 117.3 | 104.5 | 110.0 | 500 | True |
| event_type=alarm, last 24 h | 215.6 | 148.5 | 168.1 | 500 | True |
| instance=Machine-0042, 30 d | 4.3 | 3.7 | 4.3 | 500 | True |
| keyword 'timeout' (clamped to 7 d) | 1.5 | 0.8 | 0.9 | 500 | True |
| keyword with no match (full 7 d window scan) | 91.9 | 91.9 | 105.8 | 0 | False |
| keyword 'Machine-0042', last 24 h | 14.2 | 13.3 | 13.5 | 105 | False |
| 20 keyset pages, last 24 h | | 0.7 | 4.1 | 500/page | |
Every shape is under 0.5 s warm. The slowest are equality filters on `severity` or
`event_type`: SQLite (no `ANALYZE` statistics) picks the single-column index, then reads and
sorts *every* matching row in the table before returning the first page (`USE TEMP B-TREE FOR
ORDER BY`), so their cost grows with table size, not page size — 2.3 s on the first, cold
run. Adding composite indexes would fix it, but would also change the row model that the
storage-cap estimate depends on (register row 93). This is filed as a low-priority follow-up,
not a failure.
### 3.4 Writer while queries run
200 events/s offered for 20 s (≈ 220× the 30-day rate), first with no queries, then while a
back-to-back worst-case keyword scan (no match, a full 7-day-window scan, ~92 ms each) ran on
another thread:
- writer at 200 ev/s, idle: enqueue->durable n=3999 P50 0.39 ms, P95 1.46 ms, P99 17.27 ms, max 33.44 ms; failed 0
- writer at 200 ev/s, with a back-to-back no-match keyword scan loop (207 scans): enqueue->durable n=3999 P50 0.13 ms, P95 0.55 ms, P99 0.96 ms, max 43.38 ms; failed 0
No degradation: reads use their own WAL connection and never take the writer's lock
(review 2026-10-21 02/P1), and the numbers confirm it.
### 3.5 Cap enforcement
One real purge tick on a table 10% over the cap: **2,608,866 → 2,379,761 rows in 12.8 s**
(229,105 deleted, under the 250,000 per-tick ceiling, so a single tick restored the cap to
within the size model's error). Consistent with the 2026-08-15 measurement (~17 s for a full
250,000-row tick).
---
## 4. `[xc-5]` Template flattening and validation — `ResidualBench flatten`
Production `FlatteningService` → `ValidationService.Validate` (the deploy gate: trust check
plus a real Roslyn compile of every script, plus all semantic checks) → `RevisionHashService`,
in-process. Each level of the inheritance chain adds attributes/alarms/scripts and overrides
a fifth of its parent's attribute values. Feature modules are composed on the base template
and each composes one sub-module. The instance overrides 10% of the attributes and binds
every data-sourced attribute. Scripts are ~35 lines each, and every script's code is unique,
so a cold compile really compiles every one. Not in frame: the configuration-database read
`FlatteningPipeline` does before this (one `FlattenSession` per batch).
| shape | chain depth | flattened attrs / alarms / scripts | flatten P50 ms | validate, cold compile ms | validate, warm cache P50 ms | validate, compile off P50 ms | hash P50 ms | errors |
|---|---|---|---|---|---|---|---|---|
| typical | 2 | 100 / 12 / 8 | 0.05 | 402 | 0.08 | 0.07 | 0.10 | 0 |
| large | 5 | 1,100 / 100 / 60 | 0.70 | 1549 | 0.77 | 0.63 | 1.62 | 0 |
| extra-large | 8 | 4,400 / 400 / 220 | 3.62 | 1876 | 2.27 | 1.89 | 5.73 | 0 |
- large: flatten+validate+hash of 500 instances sharing one template, serial: 1.97 s total; per instance n=500 P50 2.81 ms, P95 3.45 ms, P99 7.22 ms, max 477.72 ms
- extra-large: flatten+validate+hash of 500 instances sharing one template, serial: 3.49 s total; per instance n=500 P50 3.80 ms, P95 5.14 ms, P99 18.59 ms, max 1282.61 ms
- Flattening itself is milliseconds even for the 4,400-attribute shape.
- The cost is the first, cold compile of a template's scripts — about 1.5–2 s for 60–220
unique scripts — and it is paid once per distinct script body, thanks to
`ScriptCompileVerdictCache`.
- After that, every instance of the template is a cache hit. A 500-instance bulk deploy of
the extra-large template spends 3.5 s of central CPU in flatten+validate+hash, versus the
120 s budget for deploying 500 instances to a site.
---
## 5. `[xc-4]` Audit logging vs central — `ResidualBench audit`
A throwaway database on `scadabridge-mssql`, migrated with the production EF chain (the
partitioned `AuditLog`, clustered `(OccurredAtUtc, EventId)` from #111, all NC indexes),
dropped afterwards. Rows are site-shaped (~1.5 KB, 10 sites × 500 instances, 4% failures) and
inserted through the production `AuditLogRepository.InsertManyIfNotExistsAsync` in 256-row
packets — the same set-based anti-semi-join insert `AuditLogIngestActor` runs.
**One serial writer, as in production.** `AuditLogIngestActor` is a cluster singleton that
awaits each packet inside `ReceiveAsync`, so central never runs two site-ingest inserts at
once. A first attempt with four concurrent writers hit **SQL error 1205 (deadlock victim)**
within seconds. Production can still see concurrent writers on this table (the
reconciliation singleton, central direct writes), and `AuditIngestErrorClassifier` already
treats 1205 as transient, so the site re-sends. That is recorded here as an observation, not
a defect.
```
seeded 1,000,192 rows (45 days) in 934 s = 1,071 rows/s (1 serial writer, 256-row packets)
AuditLog size 3259 MB
```
### no ingest: achieved ingest 0 rows/s, deadlock retries so far 0
| read | P50 ms | P95 ms | P99 ms | max ms | n |
|---|---|---|---|---|---|
| Audit Log page 1 (newest 50, no filter) | 1.8 | 10.4 | 18.9 | 149.5 | 3052 |
| channel=ApiOutbound, last 24 h, 50 | 2.0 | 10.2 | 20.2 | 43.0 | 3052 |
| site=site-07, last 7 d, 100 | 3.4 | 11.2 | 24.7 | 59.0 | 3052 |
| status=Failed, last 24 h, 50 | 2.9 | 10.7 | 24.3 | 66.9 | 3052 |
| KPI snapshot, 1 h window | 1.0 | 10.0 | 17.3 | 33.0 | 3052 |
| non-audit: templates + sites list | 1.1 | 14.1 | 26.5 | 46.5 | 3052 |
### ingest 100 rows/s: achieved ingest 98 rows/s, deadlock retries so far 0; 256-row packet n=23 P50 230.05 ms, P95 495.30 ms, P99 731.88 ms, max 731.88 ms
| read | P50 ms | P95 ms | P99 ms | max ms | n |
|---|---|---|---|---|---|
| Audit Log page 1 (newest 50, no filter) | 2.4 | 11.2 | 20.6 | 598.0 | 1635 |
| channel=ApiOutbound, last 24 h, 50 | 2.7 | 11.2 | 12.7 | 78.0 | 1635 |
| site=site-07, last 7 d, 100 | 4.4 | 13.1 | 30.3 | 166.5 | 1635 |
| status=Failed, last 24 h, 50 | 4.0 | 12.3 | 24.6 | 151.0 | 1635 |
| KPI snapshot, 1 h window | 2.9 | 10.7 | 17.0 | 214.7 | 1635 |
| non-audit: templates + sites list | 1.9 | 21.0 | 23.3 | 56.9 | 1635 |
### ingest 500 rows/s: achieved ingest 499 rows/s, deadlock retries so far 0; 256-row packet n=117 P50 203.94 ms, P95 577.36 ms, P99 713.85 ms, max 1133.67 ms
| read | P50 ms | P95 ms | P99 ms | max ms | n |
|---|---|---|---|---|---|
| Audit Log page 1 (newest 50, no filter) | 2.7 | 22.2 | 122.9 | 247.6 | 1273 |
| channel=ApiOutbound, last 24 h, 50 | 2.8 | 11.2 | 104.4 | 1143.9 | 1273 |
| site=site-07, last 7 d, 100 | 4.3 | 18.8 | 137.8 | 318.8 | 1273 |
| status=Failed, last 24 h, 50 | 3.7 | 12.8 | 100.5 | 293.0 | 1273 |
| KPI snapshot, 1 h window | 8.8 | 19.2 | 114.2 | 356.7 | 1273 |
| non-audit: templates + sites list | 1.8 | 20.5 | 21.7 | 36.5 | 1273 |
### ingest 2,000 rows/s: achieved ingest 1,474 rows/s, deadlock retries so far 0; 256-row packet n=346 P50 125.09 ms, P95 397.36 ms, P99 732.35 ms, max 956.29 ms
| read | P50 ms | P95 ms | P99 ms | max ms | n |
|---|---|---|---|---|---|
| Audit Log page 1 (newest 50, no filter) | 4.8 | 94.7 | 147.7 | 381.7 | 593 |
| channel=ApiOutbound, last 24 h, 50 | 3.5 | 30.4 | 90.7 | 1380.4 | 593 |
| site=site-07, last 7 d, 100 | 5.1 | 42.9 | 146.6 | 1750.2 | 593 |
| status=Failed, last 24 h, 50 | 4.3 | 25.9 | 128.8 | 359.8 | 593 |
| KPI snapshot, 1 h window | 30.6 | 135.4 | 188.5 | 704.0 | 593 |
| non-audit: templates + sites list | 2.1 | 3.1 | 4.9 | 27.2 | 593 |
### ingest unthrottled (1 serial writer): achieved ingest 1,032 rows/s, deadlock retries so far 0; 256-row packet n=243 P50 190.53 ms, P95 557.43 ms, P99 900.67 ms, max 1223.08 ms
| read | P50 ms | P95 ms | P99 ms | max ms | n |
|---|---|---|---|---|---|
| Audit Log page 1 (newest 50, no filter) | 12.3 | 116.8 | 199.9 | 284.5 | 382 |
| channel=ApiOutbound, last 24 h, 50 | 3.7 | 13.3 | 107.7 | 159.1 | 382 |
| site=site-07, last 7 d, 100 | 7.4 | 49.9 | 125.3 | 644.6 | 382 |
| status=Failed, last 24 h, 50 | 4.7 | 76.7 | 176.2 | 1491.2 | 382 |
| KPI snapshot, 1 h window | 69.3 | 160.0 | 345.6 | 681.9 | 382 |
| non-audit: templates + sites list | 2.3 | 4.2 | 11.8 | 42.2 | 382 |
Reading the numbers:
- **Ingest ceiling, one serial writer: ~1,000–1,500 rows/s** on this emulated SQL Server.
The seed sustained 1,071 rows/s while the table grew to 1 M rows / 3.26 GB. Each
256-row packet takes 125–230 ms P50. That is the central ingest capacity on this box, and
it is far above any audit volume the rig produces.
- **Reads barely move at realistic rates.** At 100 and 500 rows/s every read's P95 stays
≤ 22 ms, against 10–14 ms with no ingest.
- **At the ceiling, P95 reaches 117–160 ms.** The worst are the Audit Log page 1 and the KPI
snapshot, which compete with the insert for the newest partition's pages. There are rare
outliers up to 1.75 s. Still well inside the 1 s P95 budget.
- **Non-audit central reads are unaffected** (P95 ≤ 21 ms in every phase).
- **Deadlocks: 0** with one writer. Four concurrent writers deadlocked within seconds (see
above) — **#124** (p3).
---
## 6. `[xc-8]` UI responsiveness — `docker/measure-ui-responsiveness.sh`
Real Chromium (host Playwright) against the rig through Traefik. A load is a full navigation,
timed until the page is usable: the Blazor circuit is up and no spinner or "Loading…" text
remains. 14 pages, 5 loads each, idle first and then under load.
**Under load**: 6 operator sessions (7.0 page loads/s), inbound API 20.0 calls/s offered, 652/652 HTTP 200, API latency P50 92 ms / P95 980 ms / max 1264 ms
| page | idle P50 ms | idle max ms | load P50 ms | load max ms |
|---|---|---|---|---|
| Dashboard | 29 | 32 | 52 | 86 |
| Health | 3362 | 5048 | 38 | 128 |
| Topology | 38 | 52 | 148 | 201 |
| Instances | 42 | 64 | 74 | 141 |
| Deployments | 54 | 57 | 39 | 247 |
| Templates | 61 | 74 | 144 | 455 |
| Audit Log | 425 | 696 | 1081 | 3046 |
| Config audit | 25 | 27 | 26 | 33 |
| Site Calls | 41 | 47 | 51 | 61 |
| Notifications | 358 | 365 | 962 | 1627 |
| Alarms | 25 | 28 | 26 | 27 |
| Event Logs | 27 | 29 | 27 | 35 |
| Sites | 28 | 33 | 38 | 59 |
| Flow Debugger | 33 | 89 | 31 | 38 |
| **all pages** | P50 40, P95 696 | max 5048 | P50 46, P95 1177 | max 3046 |
Reading the numbers:
- **Every page except Health is usable in ≤ 0.7 s idle**; most in 25–60 ms on loopback.
- **Health is the outlier: 3.4 s P50, up to 5.05 s idle, but 38 ms under load.** The
Notification Outbox KPI tile exceeds the page's 5 s `TileTimeout`. On this rig the outbox
holds 944,597 Parked rows, and counting them is a 374,043-read clustered scan (1.3 s per
query, warm). A timed-out snapshot is not cached, and the tiles load inside prerender, so
a lone viewer waits the full timeout on every load. Under load, another session's
successful refresh keeps the cache warm, which is why the number drops. Filed as **#122**
(p2).
- **Audit Log** (1.1 s P50 / 3.0 s max under load) and **Notifications** (1.0 s / 1.6 s)
are the slowest pages under load. Both read the rig's largest tables (10.9 M audit rows,
4.35 M notifications) and stay inside the 3 s budget.
- The inbound API kept up throughout: 652/652 HTTP 200 at 20 calls/s, P95 0.98 s,
including the `Route.To()` round trip to site-a.
---
## 7. Findings and follow-ups
| # | Finding | Severity | Issue |
|---|---|---|---|
| 1 | Health dashboard waits up to 5 s for a timed-out Notification Outbox KPI tile when the outbox holds ~1 M Parked rows (uncached timeout, prerender blocks) | p2 bug | **#122** |
| 2 | Event-log `severity` / `event_type` filters read and sort every matching row (2.3 s cold, ~0.1–0.15 s warm at 1 GB) | p3 | **#123** |
| 3 | Concurrent `AuditLog` set-based inserts deadlock (1205); transient-classified, but production has more than one writer | p3 | **#124** |
| 4 | 30-day site event retention holds only below ~0.91 events/s per site; above that the 1 GB cap governs | operational note | — (documented here and in §3.1; raise `MaxStorageMb` per site if needed) |
| 5 | A burst larger than the 10,000-event write queue, arriving faster than the writer drains, loses its oldest events (counted, surfaced on the health report) | by design | — |
Phase-8 WP-4 is now covered for all of `[xc-1]`–`[xc-8]`: `[xc-1]`, `[xc-2]`, `[xc-6]` and
`[xc-7]` by the 2026-08-15 run, and the four residuals by this one.
### 7.1 Follow-up fixes (same day)
The three issues were fixed after the measurement run; the verdicts above stand, and the numbers
in §3, §5 and §6 are the pre-fix measurements.
- **#122.** The real global outbox KPI cost was 0.7–2.6 s, not the 1.3 s quoted in §6: the earlier
probe ran under `sqlcmd` without `-I`, which disables filtered indexes. The OR'd pre-filter
forced a clustered scan; the snapshot now runs three status-equality legs (live, parked,
delivered) that each seek their own index, ~0.12 s on the rig.
- **#123.** The `event_type` and `severity` indexes are now composites with `timestamp`.
`ResidualBench eventlog` re-run: `severity=Error, 30 d` 2,287 → 15 ms cold and 115 → 1.6 ms
warm; `event_type=alarm, 24 h` 216 → 1.2 ms cold. The cost: 454 → 530 B/row on disk, so the
1 GB cap holds 2.03 M rows instead of 2.36 M and 30 days fit only below 0.78 events/s per site
(was 0.91); the CDC-on writer drains 8,760 events/s instead of 10,535.
- **#124.** The set-based ingest's `NOT EXISTS` probe is forced to seek. `ResidualBench
audit-contention`: 4 writers 775 rows/s with 76 deadlock victims in 30 s → 5,214 rows/s with
none; 8 writers 8,607 rows/s with none.
## 8. What this does not prove
- **The rig has few instances.** `[xc-8]` ran against the docker rig: 14 instances and 36
templates, though its audit and notification tables are large (10.9 M / 4.35 M rows). Page
cost that grows with fleet size (Topology, Instances, pending updates) is not exercised at
10 sites × 500 instances here. The audit and flattening benches cover the two biggest
central data-volume costs separately.
- **Emulated SQL Server.** `[xc-4]` absolute numbers come from an amd64 SQL Server under
emulation. Treat them as a pessimistic lower bound on throughput, not a production sizing.
- **No WAN.** As in the 2026-08-15 run, site↔central hops are loopback.
## 9. Reproducing
```bash
dotnet run -c Release --project tests/ZB.MOM.WW.ScadaBridge.ResidualBench -- eventlog # ~4 min, ~1.1 GB temp disk
dotnet run -c Release --project tests/ZB.MOM.WW.ScadaBridge.ResidualBench -- flatten # ~20 s
dotnet run -c Release --project tests/ZB.MOM.WW.ScadaBridge.ResidualBench -- audit # needs MS SQL (default: local scadabridge-mssql sa)
bash docker/measure-ui-responsiveness.sh # needs the rig + seed-mes-alarm-demo.sh
```
Options: `eventlog --data-dir --calibration-rows --write-events --skip-full`;
`flatten --instances --repeats`; `audit --connection-string --seed-rows --phase-seconds --keep`;
`audit-contention --writers --seconds --seed-rows` (#124); UI `--operators --api-rps --repeats`.
Unknown options are rejected.
+2
View File
@@ -43,6 +43,8 @@ so the evidence can be regenerated rather than bit-rotting.
browser concerns): `[xc-3]` site event logging volume within 30-day/1 GB limits,
`[xc-4]` audit logging not degrading central, `[xc-5]` template
flattening/validation for large templates, `[xc-8]` UI workflow responsiveness.
**Covered 2026-11-10 (#49):** all four measured and passed — results
`docs/plans/2026-11-10-wp4-residual-scope-results.md` (follow-ups #122, #123, #124).
See `phase-8-production-readiness.md:152-170` (WP-4) and `:314-320`
(test protocol) for the original scope.