From 2b80a6defa064b11053009d20f8588b5cb31fffb Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 10 Nov 2026 16:46:42 -0500 Subject: [PATCH] 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). --- ZB.MOM.WW.ScadaBridge.slnx | 1 + docker/measure-ui-responsiveness.sh | 186 +++++++++ .../2026-07-08-deferred-work-register.md | 2 +- ...26-08-15-target-scale-load-test-results.md | 3 +- .../2026-11-10-wp4-residual-scope-results.md | 339 ++++++++++++++++ docs/plans/phase-8-checklist.md | 2 + .../AuditBench.cs | 221 ++++++++++ .../AuditContentionBench.cs | 105 +++++ .../BenchSupport.cs | 74 ++++ .../EventLogBench.cs | 377 ++++++++++++++++++ .../FlattenBench.cs | 236 +++++++++++ .../Program.cs | 34 ++ ...ZB.MOM.WW.ScadaBridge.ResidualBench.csproj | 41 ++ 13 files changed, 1619 insertions(+), 2 deletions(-) create mode 100755 docker/measure-ui-responsiveness.sh create mode 100644 docs/plans/2026-11-10-wp4-residual-scope-results.md create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditBench.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditContentionBench.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/BenchSupport.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/EventLogBench.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/FlattenBench.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/Program.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.ResidualBench/ZB.MOM.WW.ScadaBridge.ResidualBench.csproj diff --git a/ZB.MOM.WW.ScadaBridge.slnx b/ZB.MOM.WW.ScadaBridge.slnx index 5d773be3..35b53e6c 100644 --- a/ZB.MOM.WW.ScadaBridge.slnx +++ b/ZB.MOM.WW.ScadaBridge.slnx @@ -54,6 +54,7 @@ + diff --git a/docker/measure-ui-responsiveness.sh b/docker/measure-ui-responsiveness.sh new file mode 100755 index 00000000..eaec9d1c --- /dev/null +++ b/docker/measure-ui-responsiveness.sh @@ -0,0 +1,186 @@ +#!/usr/bin/env bash +# measure-ui-responsiveness.sh — Phase-8 WP-4 [xc-8] "UI workflows remain responsive" (ScadaBridge#49). +# +# Times Central UI page loads on the docker rig, first idle and then under load, with a real +# Chromium (host python Playwright). A "load" is a full navigation measured until the page is +# usable: the Blazor circuit is up and no loading indicator (spinner / "Loading…") remains. +# +# Load phase, all concurrent with the measuring browser: +# * OPERATORS extra browser sessions (default 6), each looping the same page list; +# * an inbound-API client calling SimpleAlarmStatus on MesAlarmDemo01 at API_RPS (default 20) +# — central method script + Route.To() to site-a + audit rows for every call. +# +# Prereqs: rig up; docker/seed-mes-alarm-demo.sh applied (SimpleAlarmStatus + MesAlarmDemo01); +# python3 playwright with chromium; the CLI built. A temporary API key `zztest-ui-load-` +# is created for the run and deleted afterwards. +# +# Usage: bash docker/measure-ui-responsiveness.sh [--operators N] [--api-rps N] [--repeats N] +set -euo pipefail + +cd "$(dirname "$0")/.." +URL="${SCADABRIDGE_URL:-http://localhost:9000}" +OPERATORS=6; API_RPS=20; REPEATS=5 +while [ $# -gt 0 ]; do + case "$1" in + --operators) OPERATORS="$2"; shift 2 ;; + --api-rps) API_RPS="$2"; shift 2 ;; + --repeats) REPEATS="$2"; shift 2 ;; + *) echo "unknown option $1" >&2; exit 2 ;; + esac +done + +CLI=(dotnet run --project src/ZB.MOM.WW.ScadaBridge.CLI --no-build -- --url "$URL" + --username "${SCADABRIDGE_USERNAME:-multi-role}" --password "${SCADABRIDGE_PASSWORD:-password}" --format json) +python3 -c 'import playwright.sync_api' 2>/dev/null || { echo "python3 playwright missing (pip install playwright && playwright install chromium)"; exit 1; } + +KEY_NAME="zztest-ui-load-$(date +%s)" +# `api-key create` prints text, not JSON: "API key created. KeyId: ", then the token alone on a line +# (the "save this token" banner goes to stderr). +KEY_OUT=$("${CLI[@]}" security api-key create --name "$KEY_NAME" --methods SimpleAlarmStatus 2>/dev/null) +KEY_ID=$(echo "$KEY_OUT" | sed -n 's/.*KeyId: *\([A-Za-z0-9]*\).*/\1/p' | head -1) +TOKEN=$(echo "$KEY_OUT" | awk 'NF==1 && length($1) > 20 {print $1; exit}') +[ -n "$TOKEN" ] && [ -n "$KEY_ID" ] || { echo "could not parse api-key create output; delete key '$KEY_NAME' by hand" >&2; exit 1; } +cleanup() { "${CLI[@]}" security api-key delete --key-id "$KEY_ID" >/dev/null 2>&1 || echo "WARN: delete API key $KEY_NAME ($KEY_ID) by hand"; } +trap cleanup EXIT +echo "# temporary API key $KEY_NAME ($KEY_ID)" + +# multiprocessing "spawn" re-imports the main module from a file, so the helper cannot run from stdin. +HELPER=$(mktemp "${TMPDIR:-/tmp}/sb-ui-responsiveness.XXXXXX.py") +trap 'rm -f "$HELPER"; cleanup' EXIT +cat >"$HELPER" <<'PY' +import json, multiprocessing as mp, os, statistics, threading, time, urllib.request + +URL = os.environ["URL"]; TOKEN = os.environ["TOKEN"] +OPERATORS = int(os.environ["OPERATORS"]); API_RPS = int(os.environ["API_RPS"]); REPEATS = int(os.environ["REPEATS"]) + +PAGES = [ + ("Dashboard", "/"), + ("Health", "/monitoring/health"), + ("Topology", "/deployment/topology"), + ("Instances", "/deployment/instances"), + ("Deployments", "/deployment/deployments"), + ("Templates", "/design/templates"), + ("Audit Log", "/audit/log"), + ("Config audit", "/audit/configuration"), + ("Site Calls", "/site-calls/report"), + ("Notifications", "/notifications/report"), + ("Alarms", "/monitoring/alarms"), + ("Event Logs", "/monitoring/event-logs"), + ("Sites", "/admin/sites"), + ("Flow Debugger", "/deployment/flow-debugger"), +] + +READY_JS = """() => { + if (window.Blazor === undefined) return false; + const busy = document.querySelector('.spinner-border, .spinner-grow, .placeholder-glow, [aria-busy="true"]'); + if (busy && busy.offsetParent !== null) return false; + const main = document.querySelector('main') || document.body; + return !/Loading\\u2026|Loading\\.\\.\\./.test(main.innerText); +}""" + +def load(page, path): + """Navigate and return ms until the page is usable: the Blazor circuit's websocket has + received a frame, and the page then shows no loading indicator for 200 ms straight + (an interactive re-render can briefly bring a spinner back after the prerendered HTML).""" + t = time.perf_counter() + with page.expect_websocket(lambda ws: "_blazor" in ws.url, timeout=60000) as ws_info: + page.goto(URL + path, wait_until="domcontentloaded", timeout=60000) + ws_info.value.wait_for_event("framereceived", timeout=60000) + deadline = t + 60 + ready_since = None + while time.perf_counter() < deadline: + now = time.perf_counter() + if page.evaluate(READY_JS): + ready_since = ready_since or now + if now - ready_since >= 0.2: + return (ready_since - t) * 1000 + else: + ready_since = None + time.sleep(0.03) + raise TimeoutError(f"{path} not ready within 60 s") + +def measure(label, repeats): + from playwright.sync_api import sync_playwright + res = {} + with sync_playwright() as p: + b = p.chromium.launch() + pg = b.new_page() + load(pg, "/") # warm the browser + the circuit path once + for name, path in PAGES: + res[name] = [load(pg, path) for _ in range(repeats)] + b.close() + return res + +def operator(stop, idx, counter): + from playwright.sync_api import sync_playwright + with sync_playwright() as p: + b = p.chromium.launch() + pg = b.new_page() + i = idx + while not stop.is_set(): + name, path = PAGES[i % len(PAGES)] + try: + load(pg, path) + with counter.get_lock(): counter.value += 1 + except Exception: + pass + i += 1 + b.close() + +def api_client(stop, stats): + body = json.dumps({"MachineCode": "MesAlarmDemo01"}).encode() + interval = 1.0 / API_RPS + def one(): + req = urllib.request.Request(URL + "/api/SimpleAlarmStatus", data=body, method="POST", + headers={"Content-Type": "application/json", "X-API-Key": TOKEN}) + t = time.perf_counter() + try: + with urllib.request.urlopen(req, timeout=60) as r: + r.read(); ok = r.status == 200 + except Exception: + ok = False + stats.append(((time.perf_counter() - t) * 1000, ok)) + nxt = time.perf_counter() + while not stop.is_set(): + threading.Thread(target=one, daemon=True).start() + nxt += interval + time.sleep(max(0, nxt - time.perf_counter())) + +def pct(xs, p): + xs = sorted(xs); return xs[min(len(xs) - 1, max(0, int(round(p / 100 * len(xs) + 0.5)) - 1))] + +def report(idle, loaded): + print("| page | idle P50 ms | idle max ms | load P50 ms | load max ms |") + print("|---|---|---|---|---|") + for name, _ in PAGES: + a, b = idle[name], loaded[name] + print(f"| {name} | {statistics.median(a):.0f} | {max(a):.0f} | {statistics.median(b):.0f} | {max(b):.0f} |") + allA = [x for v in idle.values() for x in v]; allB = [x for v in loaded.values() for x in v] + print(f"| **all pages** | P50 {statistics.median(allA):.0f}, P95 {pct(allA, 95):.0f} | max {max(allA):.0f} | " + f"P50 {statistics.median(allB):.0f}, P95 {pct(allB, 95):.0f} | max {max(allB):.0f} |") + +if __name__ == "__main__": + mp.set_start_method("spawn") + print(f"## idle ({REPEATS} loads per page)") + idle = measure("idle", REPEATS) + + stop = mp.Event(); counter = mp.Value("i", 0) + ops = [mp.Process(target=operator, args=(stop, i * 3, counter)) for i in range(OPERATORS)] + for o in ops: o.start() + api_stats = []; tstop = threading.Event() + api = threading.Thread(target=api_client, args=(tstop, api_stats), daemon=True); api.start() + time.sleep(15) # let the background load reach steady state + t0 = time.perf_counter(); c0 = counter.value; n0 = len(api_stats) + loaded = measure("load", REPEATS) + secs = time.perf_counter() - t0 + tstop.set(); stop.set() + for o in ops: o.join(timeout=60) + window = api_stats[n0:] + lat = [l for l, ok in window]; oks = sum(1 for _, ok in window if ok) + print(f"\n## under load: {OPERATORS} operator sessions ({(counter.value - c0) / secs:.1f} page loads/s), " + f"inbound API {len(window) / secs:.1f} calls/s offered, {oks}/{len(window)} HTTP 200, " + f"API latency P50 {statistics.median(lat):.0f} ms / P95 {pct(lat, 95):.0f} ms / max {max(lat):.0f} ms") + print() + report(idle, loaded) +PY +URL="$URL" TOKEN="$TOKEN" OPERATORS="$OPERATORS" API_RPS="$API_RPS" REPEATS="$REPEATS" python3 "$HELPER" diff --git a/docs/plans/2026-07-08-deferred-work-register.md b/docs/plans/2026-07-08-deferred-work-register.md index 0935a2a0..75368115 100644 --- a/docs/plans/2026-07-08-deferred-work-register.md +++ b/docs/plans/2026-07-08-deferred-work-register.md @@ -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. | — | diff --git a/docs/plans/2026-08-15-target-scale-load-test-results.md b/docs/plans/2026-08-15-target-scale-load-test-results.md index 0da69533..2c142e3a 100644 --- a/docs/plans/2026-08-15-target-scale-load-test-results.md +++ b/docs/plans/2026-08-15-target-scale-load-test-results.md @@ -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 diff --git a/docs/plans/2026-11-10-wp4-residual-scope-results.md b/docs/plans/2026-11-10-wp4-residual-scope-results.md new file mode 100644 index 00000000..324d158c --- /dev/null +++ b/docs/plans/2026-11-10-wp4-residual-scope-results.md @@ -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. diff --git a/docs/plans/phase-8-checklist.md b/docs/plans/phase-8-checklist.md index f9a81727..6291e924 100644 --- a/docs/plans/phase-8-checklist.md +++ b/docs/plans/phase-8-checklist.md @@ -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. diff --git a/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditBench.cs b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditBench.cs new file mode 100644 index 00000000..bef4f44f --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditBench.cs @@ -0,0 +1,221 @@ +using System.Diagnostics; +using Microsoft.Data.SqlClient; +using Microsoft.EntityFrameworkCore; +using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; +using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase; +using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase.Repositories; + +namespace ZB.MOM.WW.ScadaBridge.ResidualBench; + +/// +/// [xc-4] Audit logging does not degrade central performance. Creates a throwaway, fully +/// migrated configuration database (the production schema: partitioned AuditLog, +/// clustered (OccurredAtUtc, EventId), every NC index), seeds it through the real +/// ingest path, then runs a fixed +/// central read mix while site-shaped ingest packets arrive at increasing offered rates. +/// +internal static class AuditBench +{ + internal const string DefaultAdmin = + "Server=localhost,1433;User Id=sa;Password=ScadaBridge_Dev1#;TrustServerCertificate=true;Encrypt=false"; + + private const int PacketSize = 256; // rows per site ingest packet + + public static async Task RunAsync(BenchArgs args) + { + var admin = args.Get("connection-string", DefaultAdmin); + var seedRows = args.GetInt("seed-rows", 1_000_000); + var phaseSeconds = args.GetInt("phase-seconds", 60); + var keep = args.Get("keep", "false") == "true"; + args.RejectUnknown(); + + var dbName = $"ScadaBridgeResidualBench_{Guid.NewGuid():N}"[..40]; + var cs = new SqlConnectionStringBuilder(admin) { InitialCatalog = dbName }.ConnectionString; + await ExecAsync(admin, $"CREATE DATABASE [{dbName}]; ALTER DATABASE [{dbName}] SET RECOVERY SIMPLE;"); + Console.WriteLine($"# database {dbName}"); + try + { + var options = new DbContextOptionsBuilder() + .UseSqlServer(cs, sql => sql.CommandTimeout(1800)).Options; + var sw = Stopwatch.StartNew(); + await using (var ctx = new ScadaBridgeDbContext(options)) await ctx.Database.MigrateAsync(); + Console.WriteLine($"migrated in {sw.Elapsed.TotalSeconds:F0} s"); + + // ---- seed: also the unthrottled ingest ceiling on a growing table ---------------- + var now = DateTime.UtcNow; + sw.Restart(); + var seeded = 0L; + // ONE writer: production ingest is the AuditLogIngestActor cluster singleton, which + // awaits each packet inside ReceiveAsync, so central never runs two site-ingest + // inserts at once. (Four concurrent writers here deadlock — error 1205 — see results doc.) + var packets = (seedRows + PacketSize - 1) / PacketSize; + for (var packet = 0; packet < packets; packet++) + { + var rows = Enumerable.Range(0, PacketSize) + .Select(i => Row((long)packet * PacketSize + i, now.AddDays(-45).AddSeconds(45.0 * 86_400 * ((long)packet * PacketSize + i) / seedRows))) + .ToList(); + seeded += await InsertAsync(options, rows); + } + Console.WriteLine($"seeded {seeded:N0} rows (45 days) in {sw.Elapsed.TotalSeconds:F0} s = {seeded / sw.Elapsed.TotalSeconds:N0} rows/s (1 serial writer, {PacketSize}-row packets)"); + Console.WriteLine($"AuditLog size {await ScalarAsync(cs, "SELECT SUM(used_page_count) * 8 / 1024 FROM sys.dm_db_partition_stats WHERE object_id = OBJECT_ID('dbo.AuditLog')")} MB"); + + // ---- phases ------------------------------------------------------------------ + Console.WriteLine(); + var phases = new (string Name, int RowsPerSec)[] { ("no ingest", 0), ("ingest 100 rows/s", 100), ("ingest 500 rows/s", 500), ("ingest 2,000 rows/s", 2_000), ("ingest unthrottled (1 serial writer)", -1) }; + foreach (var (name, rate) in phases) + await RunPhaseAsync(options, name, rate, TimeSpan.FromSeconds(phaseSeconds)); + } + finally + { + SqlConnection.ClearAllPools(); + if (!keep) + await ExecAsync(admin, $"ALTER DATABASE [{dbName}] SET SINGLE_USER WITH ROLLBACK IMMEDIATE; DROP DATABASE [{dbName}];"); + } + return 0; + } + + private static readonly (string Name, Func Run)[] Reads = + [ + ("Audit Log page 1 (newest 50, no filter)", ctx => new AuditLogRepository(ctx).QueryAsync(new AuditLogQueryFilter(), new AuditLogPaging(50))), + ("channel=ApiOutbound, last 24 h, 50", ctx => new AuditLogRepository(ctx).QueryAsync( + new AuditLogQueryFilter(Channels: [AuditChannel.ApiOutbound], FromUtc: DateTime.UtcNow.AddDays(-1)), new AuditLogPaging(50))), + ("site=site-07, last 7 d, 100", ctx => new AuditLogRepository(ctx).QueryAsync( + new AuditLogQueryFilter(SourceSiteIds: ["site-07"], FromUtc: DateTime.UtcNow.AddDays(-7)), new AuditLogPaging(100))), + ("status=Failed, last 24 h, 50", ctx => new AuditLogRepository(ctx).QueryAsync( + new AuditLogQueryFilter(Statuses: [AuditStatus.Failed], FromUtc: DateTime.UtcNow.AddDays(-1)), new AuditLogPaging(50))), + ("KPI snapshot, 1 h window", ctx => new AuditLogRepository(ctx).GetKpiSnapshotAsync(TimeSpan.FromHours(1))), + ("non-audit: templates + sites list", async ctx => + { + await ctx.Templates.AsNoTracking().Take(100).ToListAsync(); + await ctx.Sites.AsNoTracking().ToListAsync(); + }), + ]; + + private static async Task RunPhaseAsync(DbContextOptions options, string name, int rowsPerSec, TimeSpan duration) + { + using var cts = new CancellationTokenSource(duration); + var ingested = 0L; + var packetLatency = new Samples(); + var next = 10_000_000L + Random.Shared.Next(1_000_000) * 100L; + + async Task Writer(int writers, int index) + { + var sw = Stopwatch.StartNew(); + var sent = 0L; + while (!cts.IsCancellationRequested) + { + if (rowsPerSec > 0) + { + // Paced: one packet whenever this writer falls behind its share of the offered rate. + var due = (long)(sw.Elapsed.TotalSeconds * rowsPerSec / writers); + if (sent + PacketSize > due) { await Task.Delay(2); continue; } + } + var baseId = Interlocked.Add(ref next, PacketSize); + var rows = Enumerable.Range(0, PacketSize).Select(i => Row(baseId + i, DateTime.UtcNow.AddSeconds(-Random.Shared.Next(0, 30)))).ToList(); + var t = Stopwatch.GetTimestamp(); + Interlocked.Add(ref ingested, await InsertAsync(options, rows)); + packetLatency.Add(Stopwatch.GetElapsedTime(t).TotalMilliseconds); + sent += PacketSize; + } + } + + var writerCount = rowsPerSec == 0 ? 0 : 1; + var writers = Enumerable.Range(0, writerCount).Select(i => Task.Run(() => Writer(writerCount, i))).ToList(); + + // One reader looping the read mix back to back — a busy operator's UI plus the health poll. + var latencies = Reads.ToDictionary(r => r.Name, _ => new Samples()); + var started = Stopwatch.StartNew(); + while (!cts.IsCancellationRequested) + { + foreach (var (readName, run) in Reads) + { + var t = Stopwatch.GetTimestamp(); + await using var ctx = new ScadaBridgeDbContext(options); + await run(ctx); + latencies[readName].Add(Stopwatch.GetElapsedTime(t).TotalMilliseconds); + } + } + await Task.WhenAll(writers); + var seconds = started.Elapsed.TotalSeconds; + + Console.WriteLine($"### {name}: achieved ingest {ingested / seconds:N0} rows/s, deadlock retries so far {Interlocked.Read(ref _deadlocks)}" + + (packetLatency.Count > 0 ? $"; {PacketSize}-row packet {packetLatency.Summary()}" : "")); + Console.WriteLine("| read | P50 ms | P95 ms | P99 ms | max ms | n |"); + Console.WriteLine("|---|---|---|---|---|---|"); + foreach (var (readName, s) in latencies) + Console.WriteLine($"| {readName} | {s.Percentile(50):F1} | {s.Percentile(95):F1} | {s.Percentile(99):F1} | {s.Max:F1} | {s.Count} |"); + Console.WriteLine(); + } + + private static readonly string[] Targets = ["MES.MoveIn", "MES.MoveOut", "Historian.Write", "ERP.Order", "Delmia.Recipe"]; + + /// Site-shaped row: ~1.5 KB of request/response summary + extra, 10 sites × 500 instances. + internal static AuditEvent Row(long i, DateTime occurredAtUtc) + { + var channel = (i % 10) switch { < 5 => AuditChannel.ApiOutbound, < 8 => AuditChannel.DbOutbound, < 9 => AuditChannel.Notification, _ => AuditChannel.ApiInbound }; + var kind = channel switch + { + AuditChannel.ApiOutbound => i % 3 == 0 ? AuditKind.ApiCallCached : AuditKind.ApiCall, + AuditChannel.DbOutbound => i % 3 == 0 ? AuditKind.DbWriteCached : AuditKind.DbWrite, + AuditChannel.Notification => AuditKind.NotifySend, + _ => AuditKind.InboundRequest, + }; + var failed = i % 25 == 0; + var site = $"site-{i % 10:D2}"; + return ScadaBridgeAuditEventFactory.Create( + channel, kind, failed ? AuditStatus.Failed : AuditStatus.Delivered, + occurredAtUtc: occurredAtUtc, + actor: $"script:Machine-{i % 500:D4}", + target: Targets[i % Targets.Length], + sourceNode: i % 2 == 0 ? "node-a" : "node-b", + correlationId: kind is AuditKind.ApiCallCached or AuditKind.DbWriteCached ? Guid.NewGuid() : null, + executionId: Guid.NewGuid(), + sourceSiteId: site, + sourceInstanceId: $"Machine-{i % 500:D4}", + sourceScript: $"Recipe{i % 11}", + httpStatus: channel is AuditChannel.ApiOutbound or AuditChannel.ApiInbound ? (failed ? 503 : 200) : null, + durationMs: (int)(i % 400), + errorMessage: failed ? "Service Unavailable: upstream timeout after 30000 ms" : null, + requestSummary: "{\"workOrder\":\"WO-" + i + "\",\"machine\":\"Machine-" + (i % 500).ToString("D4") + "\",\"items\":[" + + string.Join(",", Enumerable.Range(0, 8).Select(k => "{\"sku\":\"SKU-" + k + "\",\"qty\":" + (k * 3) + "}")) + "]}", + responseSummary: failed ? null : "{\"accepted\":true,\"reference\":\"" + Guid.NewGuid() + "\",\"message\":\"Recorded\"}", + extra: "{\"retry\":0,\"bufferDepth\":" + (i % 50) + "}"); + } + + private static long _deadlocks; + + /// One ingest packet through the production repository; a deadlock victim (1205) is retried, as the site would re-send it. + private static async Task InsertAsync(DbContextOptions options, IReadOnlyList rows) + { + for (var attempt = 1; ; attempt++) + { + try + { + await using var ctx = new ScadaBridgeDbContext(options); + return await new AuditLogRepository(ctx).InsertManyIfNotExistsAsync(rows); + } + catch (SqlException ex) when (ex.Number == 1205 && attempt < 5) + { + Interlocked.Increment(ref _deadlocks); + } + } + } + + internal static async Task ExecAsync(string cs, string sql) + { + await using var c = new SqlConnection(cs); + await c.OpenAsync(); + await using var cmd = new SqlCommand(sql, c) { CommandTimeout = 300 }; + await cmd.ExecuteNonQueryAsync(); + } + + internal static async Task ScalarAsync(string cs, string sql) + { + await using var c = new SqlConnection(cs); + await c.OpenAsync(); + await using var cmd = new SqlCommand(sql, c) { CommandTimeout = 300 }; + return await cmd.ExecuteScalarAsync(); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditContentionBench.cs b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditContentionBench.cs new file mode 100644 index 00000000..e53d45a5 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/AuditContentionBench.cs @@ -0,0 +1,105 @@ +using System.Diagnostics; +using Microsoft.Data.SqlClient; +using Microsoft.EntityFrameworkCore; +using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase; +using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase.Repositories; + +namespace ZB.MOM.WW.ScadaBridge.ResidualBench; + +/// +/// ScadaBridge#124: concurrent callers of +/// — the shape the ingest singleton, the reconciliation singleton and the cached-telemetry +/// dual-write produce when they overlap. Runs N writers against a throwaway migrated database +/// for a fixed time and reports throughput and the deadlock victims (error 1205) that reached +/// the caller. One writer in N re-sends a packet another writer already inserted, the way a +/// reconciliation pull overlaps live telemetry. +/// +internal static class AuditContentionBench +{ + private const int PacketSize = 256; + + public static async Task RunAsync(BenchArgs args) + { + var admin = args.Get("connection-string", AuditBench.DefaultAdmin); + var writerCount = args.GetInt("writers", 4); + var seconds = args.GetInt("seconds", 30); + var seedRows = args.GetInt("seed-rows", 50_000); + args.RejectUnknown(); + + var dbName = $"ScadaBridgeResidualBench_{Guid.NewGuid():N}"[..40]; + var cs = new SqlConnectionStringBuilder(admin) { InitialCatalog = dbName }.ConnectionString; + await AuditBench.ExecAsync(admin, $"CREATE DATABASE [{dbName}]; ALTER DATABASE [{dbName}] SET RECOVERY SIMPLE;"); + Console.WriteLine($"# database {dbName}, {writerCount} writers, {seconds} s, {seedRows:N0} seed rows"); + try + { + var options = new DbContextOptionsBuilder() + .UseSqlServer(cs, sql => sql.CommandTimeout(600)).Options; + await using (var ctx = new ScadaBridgeDbContext(options)) await ctx.Database.MigrateAsync(); + + var now = DateTime.UtcNow; + for (var p = 0; p < seedRows / PacketSize; p++) + { + var rows = Enumerable.Range(0, PacketSize) + .Select(i => AuditBench.Row((long)p * PacketSize + i, now.AddHours(-2).AddMilliseconds((p * PacketSize) + i))) + .ToList(); + await using var ctx = new ScadaBridgeDbContext(options); + await new AuditLogRepository(ctx).InsertManyIfNotExistsAsync(rows); + } + + long inserted = 0, packets = 0, deadlocks = 0, otherFaults = 0, seq = 1_000_000_000; + var recent = new System.Collections.Concurrent.ConcurrentQueue>(); + using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(seconds)); + var sw = Stopwatch.StartNew(); + + async Task Writer(int index) + { + while (!cts.IsCancellationRequested) + { + IReadOnlyList rows; + // Writer 0 replays an already-sent packet now and then (reconciliation overlap). + if (index == 0 && writerCount > 1 && Interlocked.Read(ref packets) % 4 == 3 && recent.TryDequeue(out var replay)) + { + rows = replay; + } + else + { + var start = Interlocked.Add(ref seq, PacketSize) - PacketSize; + var t = DateTime.UtcNow; + rows = Enumerable.Range(0, PacketSize) + .Select(i => AuditBench.Row(start + i, t.AddMilliseconds(-i))) + .ToList(); + recent.Enqueue(rows); + while (recent.Count > 64) recent.TryDequeue(out _); + } + + try + { + await using var ctx = new ScadaBridgeDbContext(options); + Interlocked.Add(ref inserted, await new AuditLogRepository(ctx).InsertManyIfNotExistsAsync(rows)); + Interlocked.Increment(ref packets); + } + catch (SqlException ex) when (ex.Number == 1205) + { + Interlocked.Increment(ref deadlocks); + } + catch (Exception ex) + { + if (Interlocked.Increment(ref otherFaults) <= 3) Console.WriteLine($"fault: {ex.GetBaseException().Message}"); + } + } + } + + await Task.WhenAll(Enumerable.Range(0, writerCount).Select(i => Task.Run(() => Writer(i)))); + Console.WriteLine( + $"{writerCount} writers: {packets:N0} packets, {inserted:N0} rows in {sw.Elapsed.TotalSeconds:F0} s = " + + $"{inserted / sw.Elapsed.TotalSeconds:N0} rows/s; deadlock victims reaching the caller {deadlocks:N0}; other faults {otherFaults:N0}"); + } + finally + { + SqlConnection.ClearAllPools(); + await AuditBench.ExecAsync(admin, $"ALTER DATABASE [{dbName}] SET SINGLE_USER WITH ROLLBACK IMMEDIATE; DROP DATABASE [{dbName}];"); + } + return 0; + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/BenchSupport.cs b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/BenchSupport.cs new file mode 100644 index 00000000..165b2098 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/BenchSupport.cs @@ -0,0 +1,74 @@ +using System.Diagnostics; + +namespace ZB.MOM.WW.ScadaBridge.ResidualBench; + +/// --key value options. An unknown key is rejected by the consuming mode, not silently ignored. +internal sealed class BenchArgs +{ + private readonly Dictionary _values = new(StringComparer.Ordinal); + private readonly HashSet _read = new(StringComparer.Ordinal); + + public static BenchArgs Parse(IEnumerable args) + { + var result = new BenchArgs(); + var list = args.ToList(); + for (var i = 0; i < list.Count; i++) + { + if (!list[i].StartsWith("--", StringComparison.Ordinal)) + throw new ArgumentException($"unexpected argument '{list[i]}'"); + var key = list[i][2..]; + var value = i + 1 < list.Count && !list[i + 1].StartsWith("--", StringComparison.Ordinal) ? list[++i] : "true"; + result._values[key] = value; + } + return result; + } + + public string Get(string key, string fallback) + { + _read.Add(key); + return _values.TryGetValue(key, out var v) ? v : fallback; + } + + public int GetInt(string key, int fallback) => int.Parse(Get(key, fallback.ToString())); + + /// Throws if any supplied key was never read — a typo must not silently change the run. + public void RejectUnknown() + { + var unknown = _values.Keys.Where(k => !_read.Contains(k)).ToList(); + if (unknown.Count > 0) + throw new ArgumentException($"unknown option(s): {string.Join(", ", unknown.Select(k => "--" + k))}"); + } +} + +/// Latency sample set with nearest-rank percentiles. +internal sealed class Samples +{ + private readonly List _ms = new(); + + public int Count => _ms.Count; + + public void Add(double ms) { lock (_ms) _ms.Add(ms); } + + public double Percentile(double p) + { + lock (_ms) + { + if (_ms.Count == 0) return double.NaN; + var sorted = _ms.OrderBy(x => x).ToList(); + var rank = (int)Math.Ceiling(p / 100.0 * sorted.Count) - 1; + return sorted[Math.Clamp(rank, 0, sorted.Count - 1)]; + } + } + + public double Max { get { lock (_ms) return _ms.Count == 0 ? double.NaN : _ms.Max(); } } + + public string Summary() => + $"n={Count} P50 {Percentile(50):F2} ms, P95 {Percentile(95):F2} ms, P99 {Percentile(99):F2} ms, max {Max:F2} ms"; + + public static double Time(Action action) + { + var sw = Stopwatch.StartNew(); + action(); + return sw.Elapsed.TotalMilliseconds; + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/EventLogBench.cs b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/EventLogBench.cs new file mode 100644 index 00000000..4ab6c272 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/EventLogBench.cs @@ -0,0 +1,377 @@ +using System.Diagnostics; +using System.Reflection; +using Microsoft.Data.Sqlite; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; +using ZB.MOM.WW.LocalDb; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.RemoteQuery; +using ZB.MOM.WW.ScadaBridge.SiteEventLogging; + +namespace ZB.MOM.WW.ScadaBridge.ResidualBench; + +/// +/// [xc-3] Site event logging handles high event volume within the 30-day / 1 GB limits. +/// Everything runs over a real ZB.MOM.WW.LocalDb file with the production +/// , and +/// . +/// +/// +/// Phases: +/// +/// calibrate — bytes per row on disk for the representative event mix, so +/// rows-at-cap and the sustained event rate that fits 30 days inside 1 GB. +/// write — writer drain rate and enqueue→durable latency, with and without +/// the LocalDb CDC capture triggers (RegisterReplicated), plus storm bursts against +/// the bounded write queue. +/// full — a table filled to the 1 GB cap with 30 days of history: query +/// shapes through the real query service, and writer latency while queries run. +/// purge — one real purge tick over a table 10% over the cap. +/// +/// +internal static class EventLogBench +{ + private const int Instances = 500; + private const long CapBytes = 1024L * 1024 * 1024; + + public static async Task RunAsync(BenchArgs args) + { + var dataDir = args.Get("data-dir", Path.Combine(Path.GetTempPath(), "sb-residual-eventlog")); + var calibrationRows = args.GetInt("calibration-rows", 200_000); + var writeEvents = args.GetInt("write-events", 200_000); + var skipFull = args.Get("skip-full", "false") == "true"; + args.RejectUnknown(); + + Directory.CreateDirectory(dataDir); + Console.WriteLine($"# data dir {dataDir}"); + + // ---- 1. calibrate ------------------------------------------------------------ + double bytesPerRow; + { + var db = Open(Path.Combine(dataDir, "calibrate.db"), out var path); + using var logger = NewLogger(db, new SiteEventLogOptions()); + var before = UsedBytes(db); + Seed(db, calibrationRows, DateTimeOffset.UtcNow.AddDays(-30), DateTimeOffset.UtcNow); + var after = UsedBytes(db); + bytesPerRow = (after - before) / (double)calibrationRows; + var rowsAtCap = (long)(CapBytes / bytesPerRow); + var ratePerSec = rowsAtCap / (30.0 * 86_400); + Console.WriteLine(); + Console.WriteLine("## calibrate"); + Console.WriteLine($"rows seeded {calibrationRows:N0}"); + Console.WriteLine($"bytes per row (on disk) {bytesPerRow:F1}"); + Console.WriteLine($"rows at the 1 GB cap {rowsAtCap:N0}"); + Console.WriteLine($"30 days fit in 1 GB at <= {ratePerSec:F3} events/s sustained per site " + + $"({ratePerSec * 86_400:N0}/day, {ratePerSec * 86_400 / Instances:F1}/instance/day at {Instances} instances)"); + Console.WriteLine($"days retained at 5 ev/s {rowsAtCap / (5.0 * 86_400):F1}"); + Console.WriteLine($"days retained at 20 ev/s {rowsAtCap / (20.0 * 86_400):F1}"); + logger.Dispose(); + Cleanup(db, path); + } + + // ---- 2. write throughput ----------------------------------------------------- + Console.WriteLine(); + Console.WriteLine("## write"); + foreach (var replicated in new[] { false, true }) + { + var db = Open(Path.Combine(dataDir, $"write-{replicated}.db"), out var path); + using var logger = NewLogger(db, new SiteEventLogOptions()); + if (replicated) db.RegisterReplicated("site_events"); + await MeasureDrainAsync(logger, writeEvents, replicated ? "CDC on " : "CDC off"); + foreach (var burst in new[] { 5_000, 10_000, 25_000 }) + await MeasureBurstAsync(logger, burst, replicated ? "CDC on " : "CDC off"); + logger.Dispose(); + Cleanup(db, path); + } + + if (skipFull) return 0; + + // ---- 3. a table at the cap --------------------------------------------------- + Console.WriteLine(); + Console.WriteLine("## full (1 GB, 30 days)"); + var fullRows = (long)(CapBytes / bytesPerRow); + { + var db = Open(Path.Combine(dataDir, "full.db"), out var path); + var options = new SiteEventLogOptions(); + using var logger = NewLogger(db, options); + var now = DateTimeOffset.UtcNow; + var sw = Stopwatch.StartNew(); + Seed(db, fullRows, now.AddDays(-30), now); + Console.WriteLine($"seeded {fullRows:N0} rows in {sw.Elapsed.TotalSeconds:F0} s; used {UsedBytes(db) / 1048576.0:F0} MiB, file {new FileInfo(path).Length / 1048576.0:F0} MiB"); + + var query = new EventLogQueryService(logger, Options.Create(options), NullLogger.Instance); + RunQueries(query, now); + await MeasureWriterUnderQueriesAsync(logger, query, now); + + // ---- 4. purge tick over the cap -------------------------------------------- + Console.WriteLine(); + Console.WriteLine("## purge (cap trim, 10% over)"); + Seed(db, fullRows / 10, now.AddDays(-29), now); + var purge = new EventLogPurgeService(logger, Options.Create(options), NullLogger.Instance); + var runPurge = typeof(EventLogPurgeService).GetMethod("RunPurge", BindingFlags.Instance | BindingFlags.NonPublic) + ?? throw new MissingMethodException("EventLogPurgeService.RunPurge"); + var countBefore = Count(db); + sw.Restart(); + runPurge.Invoke(purge, null); + var purgeMs = sw.Elapsed.TotalMilliseconds; + Console.WriteLine($"rows {countBefore:N0} -> {Count(db):N0} in {purgeMs / 1000:F1} s (ceiling {options.MaxPurgedRowsPerTick:N0}/tick)"); + logger.Dispose(); + Cleanup(db, path); + } + return 0; + } + + private static async Task MeasureDrainAsync(SiteEventLogger logger, int total, string label) + { + // Windows below the queue capacity, so nothing is dropped: measures the writer's drain rate. + const int window = 5_000; + var latency = new Samples(); + var sw = Stopwatch.StartNew(); + var failedBefore = logger.FailedWriteCount; + for (var offset = 0; offset < total; offset += window) + { + var tasks = new Task[window]; + for (var i = 0; i < window; i++) + { + var start = Stopwatch.GetTimestamp(); + var e = RowFor(offset + i); + tasks[i] = logger.LogEventAsync(e.Type, e.Severity, e.Instance, e.Source, e.Message, e.Details) + .ContinueWith(_ => latency.Add(Stopwatch.GetElapsedTime(start).TotalMilliseconds), TaskScheduler.Default); + } + await Task.WhenAll(tasks); + } + var seconds = sw.Elapsed.TotalSeconds; + Console.WriteLine($"{label} drain: {total:N0} events in {seconds:F2} s = {total / seconds:N0} events/s; " + + $"failed {logger.FailedWriteCount - failedBefore}; enqueue->durable {latency.Summary()}"); + } + + private static async Task MeasureBurstAsync(SiteEventLogger logger, int burst, string label) + { + // A storm offered all at once (e.g. every alarm on a site flipping on one data-connection drop). + var failedBefore = logger.FailedWriteCount; + var sw = Stopwatch.StartNew(); + var tasks = new Task[burst]; + for (var i = 0; i < burst; i++) + { + var e = RowFor(i); + tasks[i] = logger.LogEventAsync(e.Type, e.Severity, e.Instance, e.Source, e.Message, e.Details); + } + try { await Task.WhenAll(tasks); } catch { /* dropped events fault their task; counted below */ } + Console.WriteLine($"{label} burst {burst,6:N0} at once: all settled in {sw.Elapsed.TotalMilliseconds:F0} ms, " + + $"dropped {logger.FailedWriteCount - failedBefore:N0} (queue capacity {new SiteEventLogOptions().WriteQueueCapacity:N0})"); + } + + private static void RunQueries(EventLogQueryService query, DateTimeOffset now) + { + var shapes = new (string Name, Func Build)[] + { + ("no filter, page 1 (oldest first)", t => Req(null, null, null, null, null, null, t)), + ("last 1 h", t => Req(now.AddHours(-1), null, null, null, null, null, t)), + ("last 24 h", t => Req(now.AddDays(-1), null, null, null, null, null, t)), + ("severity=Error, 30 d", t => Req(null, null, null, "Error", null, null, t)), + ("severity=Error, last 24 h", t => Req(now.AddDays(-1), null, null, "Error", null, null, t)), + ("event_type=alarm, last 24 h", t => Req(now.AddDays(-1), null, "alarm", null, null, null, t)), + ("instance=Machine-0042, 30 d", t => Req(null, null, null, null, "Machine-0042", null, t)), + ("keyword 'timeout' (clamped to 7 d)", t => Req(null, null, null, null, null, "timeout", t)), + ("keyword with no match (full 7 d window scan)", t => Req(null, null, null, null, null, "no-such-text", t)), + ("keyword 'Machine-0042', last 24 h", t => Req(now.AddDays(-1), null, null, null, null, "Machine-0042", t)), + }; + + Console.WriteLine(); + Console.WriteLine("| query (page size 500) | first ms | warm P50 ms | warm max ms | rows | has more |"); + Console.WriteLine("|---|---|---|---|---|---|"); + foreach (var (name, build) in shapes) + { + EventLogQueryResponse? response = null; + var first = Samples.Time(() => response = query.ExecuteQuery(build(null))); + var warm = new Samples(); + for (var i = 0; i < 5; i++) warm.Add(Samples.Time(() => query.ExecuteQuery(build(null)))); + if (response is { Success: false }) throw new InvalidOperationException($"{name}: {response.ErrorMessage}"); + Console.WriteLine($"| {name} | {first:F1} | {warm.Percentile(50):F1} | {warm.Max:F1} | {response!.Entries.Count} | {response.HasMore} |"); + } + + // Paging through: 20 consecutive pages of the last 24 h. + string? token = null; + var pages = new Samples(); + for (var i = 0; i < 20; i++) + { + EventLogQueryResponse? r = null; + pages.Add(Samples.Time(() => r = query.ExecuteQuery(Req(now.AddDays(-1), null, null, null, null, null, token)))); + token = r!.ContinuationToken; + if (token is null) break; + } + Console.WriteLine($"| 20 keyset pages, last 24 h | | {pages.Percentile(50):F1} | {pages.Max:F1} | 500/page | |"); + } + + private static async Task MeasureWriterUnderQueriesAsync(SiteEventLogger logger, EventLogQueryService query, DateTimeOffset now) + { + // Offered 200 events/s (≈ 190x the rate that fits 30 days in 1 GB) for 20 s, first idle, + // then with a back-to-back worst-case keyword query loop on another thread. + Console.WriteLine(); + foreach (var withQueries in new[] { false, true }) + { + using var cts = new CancellationTokenSource(); + var queriesRun = 0; + var queryLoop = withQueries + ? Task.Run(() => + { + while (!cts.IsCancellationRequested) + { + query.ExecuteQuery(Req(null, null, null, null, null, "no-such-text", null)); + queriesRun++; + } + }) + : Task.CompletedTask; + + var latency = new Samples(); + var tasks = new List(); + var failedBefore = logger.FailedWriteCount; + var sw = Stopwatch.StartNew(); + var sent = 0; + while (sw.Elapsed < TimeSpan.FromSeconds(20)) + { + var due = (int)(sw.Elapsed.TotalSeconds * 200); + for (; sent < due; sent++) + { + var start = Stopwatch.GetTimestamp(); + var e = RowFor(sent); + tasks.Add(logger.LogEventAsync(e.Type, e.Severity, e.Instance, e.Source, e.Message, e.Details) + .ContinueWith(_ => latency.Add(Stopwatch.GetElapsedTime(start).TotalMilliseconds), TaskScheduler.Default)); + } + await Task.Delay(5); + } + await Task.WhenAll(tasks); + cts.Cancel(); + await queryLoop; + Console.WriteLine($"writer at 200 ev/s, {(withQueries ? $"with a back-to-back no-match keyword scan loop ({queriesRun} scans)" : "idle")}: " + + $"enqueue->durable {latency.Summary()}; failed {logger.FailedWriteCount - failedBefore}"); + } + } + + private static EventLogQueryRequest Req( + DateTimeOffset? from, DateTimeOffset? to, string? type, string? severity, string? instance, string? keyword, string? token) => + new("bench", "site-bench", from, to, type, severity, instance, keyword, token, 500, DateTimeOffset.UtcNow); + + // ---- representative event mix -------------------------------------------------------- + + internal readonly record struct Row(string Type, string Severity, string? Instance, string Source, string Message, string? Details); + + private static readonly string StackDetails = + "System.TimeoutException: The operation has timed out.\n" + + string.Concat(Enumerable.Range(0, 8).Select(i => + $" at ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts.ScriptRuntimeContext.Step{i}Async(String path, CancellationToken ct)\n")); + + /// + /// Deterministic mix modelled on the post-WP3.2 event stream (per-run script events off, an + /// interval summary instead): alarm transitions dominate, then script errors, connection + /// changes, S&F and lifecycle. 2-in-3 rows carry an instance; 1-in-10 carry a details payload. + /// + internal static Row RowFor(long i) + { + var instance = i % 3 == 2 ? null : $"Machine-{i % Instances:D4}"; + var details = i % 10 == 0 ? StackDetails : null; + return (i % 20) switch + { + < 9 => new Row("alarm", i % 9 == 0 ? "Warning" : "Info", instance, $"AlarmActor:HighTemp{i % 7}", + $"Alarm 'HighTemp{i % 7}' on '{instance ?? "site"}' changed to {(i % 2 == 0 ? "Active" : "Normal")}", details), + < 14 => new Row("script", i % 5 == 0 ? "Error" : "Warning", instance, $"ScriptActor:Recipe{i % 11}", + $"Script 'Recipe{i % 11}' failed: timeout waiting for attribute 'Done' after 30000 ms", details), + < 17 => new Row("connection", i % 3 == 0 ? "Warning" : "Info", null, $"DataConnectionActor:PLC-{i % 40:D2}", + $"Connection 'PLC-{i % 40:D2}' quality changed to {(i % 2 == 0 ? "Bad" : "Good")}", details), + < 19 => new Row("store_and_forward", "Warning", instance, "StoreAndForwardService", + $"Message parked after 50 retries to target 'MES-{i % 4}'", details), + _ => new Row("instance_lifecycle", "Info", instance, "DeploymentManagerActor", + $"Instance '{instance ?? "Machine-0000"}' started", null), + }; + } + + // ---- LocalDb plumbing ---------------------------------------------------------------- + + private static ILocalDb Open(string path, out string resolvedPath) + { + foreach (var suffix in new[] { "", "-wal", "-shm" }) File.Delete(path + suffix); + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["LocalDb:Path"] = path }) + .Build(); + var provider = new ServiceCollection().AddZbLocalDb(configuration).BuildServiceProvider(); + resolvedPath = path; + Providers[path] = provider; + return provider.GetRequiredService(); + } + + private static readonly Dictionary Providers = new(); + + private static void Cleanup(ILocalDb db, string path) + { + if (Providers.Remove(path, out var provider)) provider.Dispose(); + foreach (var suffix in new[] { "", "-wal", "-shm" }) + { + try { File.Delete(path + suffix); } catch { /* best effort */ } + } + } + + private static SiteEventLogger NewLogger(ILocalDb db, SiteEventLogOptions options) => + new(Options.Create(options), NullLogger.Instance, db); + + private static long UsedBytes(ILocalDb db) + { + using var c = db.CreateConnection(); + long Scalar(string sql) { using var cmd = c.CreateCommand(); cmd.CommandText = sql; return (long)cmd.ExecuteScalar()!; } + using (var cp = c.CreateCommand()) { cp.CommandText = "PRAGMA wal_checkpoint(TRUNCATE)"; cp.ExecuteNonQuery(); } + return (Scalar("PRAGMA page_count") - Scalar("PRAGMA freelist_count")) * Scalar("PRAGMA page_size"); + } + + private static long Count(ILocalDb db) + { + using var c = db.CreateConnection(); + using var cmd = c.CreateCommand(); + cmd.CommandText = "SELECT COUNT(*) FROM site_events"; + return (long)cmd.ExecuteScalar()!; + } + + /// + /// Bulk-seeds rows with timestamps spread evenly over [from, to] — the logger always stamps + /// "now", so history has to be written directly. Same columns and formats as the logger. + /// + private static void Seed(ILocalDb db, long rows, DateTimeOffset from, DateTimeOffset to) + { + using var c = db.CreateConnection(); + var span = (to - from).Ticks; + const int batch = 20_000; + for (long offset = 0; offset < rows; offset += batch) + { + using var tx = c.BeginTransaction(); + using var cmd = c.CreateCommand(); + cmd.Transaction = tx; + cmd.CommandText = """ + INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details) + VALUES ($id, $ts, $type, $sev, $inst, $src, $msg, $det) + """; + var pId = cmd.Parameters.Add("$id", SqliteType.Text); + var pTs = cmd.Parameters.Add("$ts", SqliteType.Text); + var pType = cmd.Parameters.Add("$type", SqliteType.Text); + var pSev = cmd.Parameters.Add("$sev", SqliteType.Text); + var pInst = cmd.Parameters.Add("$inst", SqliteType.Text); + var pSrc = cmd.Parameters.Add("$src", SqliteType.Text); + var pMsg = cmd.Parameters.Add("$msg", SqliteType.Text); + var pDet = cmd.Parameters.Add("$det", SqliteType.Text); + cmd.Prepare(); + var end = Math.Min(rows, offset + batch); + for (var i = offset; i < end; i++) + { + var r = RowFor(i); + pId.Value = Guid.NewGuid().ToString("N"); + pTs.Value = from.AddTicks(span / rows * i).ToUniversalTime().ToString("o"); + pType.Value = r.Type; + pSev.Value = r.Severity; + pInst.Value = (object?)r.Instance ?? DBNull.Value; + pSrc.Value = r.Source; + pMsg.Value = r.Message; + pDet.Value = (object?)r.Details ?? DBNull.Value; + cmd.ExecuteNonQuery(); + } + tx.Commit(); + } + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/FlattenBench.cs b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/FlattenBench.cs new file mode 100644 index 00000000..84028470 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.ResidualBench/FlattenBench.cs @@ -0,0 +1,236 @@ +using System.Diagnostics; +using ZB.MOM.WW.ScadaBridge.Commons.Entities.Instances; +using ZB.MOM.WW.ScadaBridge.Commons.Entities.Sites; +using ZB.MOM.WW.ScadaBridge.Commons.Entities.Templates; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Flattening; +using ZB.MOM.WW.ScadaBridge.TemplateEngine.Flattening; +using ZB.MOM.WW.ScadaBridge.TemplateEngine.Validation; + +namespace ZB.MOM.WW.ScadaBridge.ResidualBench; + +/// +/// [xc-5] Template flattening and validation complete within acceptable time for large +/// templates. Runs the production , +/// (the deploy gate, including the Roslyn trust check + compile of every script) and +/// in-process over synthetic template graphs of three sizes. +/// The configuration-database read that FlatteningPipeline does first is not in frame. +/// +internal static class FlattenBench +{ + private sealed record Shape( + string Name, int Depth, int AttrsPerLevel, int AlarmsPerLevel, int ScriptsPerLevel, + int Modules, int ModuleAttrs, int ModuleAlarms, int ModuleScripts, int SubModuleAttrs); + + private static readonly Shape[] Shapes = + [ + new("typical", Depth: 2, AttrsPerLevel: 40, AlarmsPerLevel: 5, ScriptsPerLevel: 3, + Modules: 2, ModuleAttrs: 10, ModuleAlarms: 1, ModuleScripts: 1, SubModuleAttrs: 0), + new("large", Depth: 5, AttrsPerLevel: 100, AlarmsPerLevel: 10, ScriptsPerLevel: 6, + Modules: 10, ModuleAttrs: 50, ModuleAlarms: 5, ModuleScripts: 3, SubModuleAttrs: 10), + new("extra-large", Depth: 8, AttrsPerLevel: 250, AlarmsPerLevel: 25, ScriptsPerLevel: 15, + Modules: 20, ModuleAttrs: 100, ModuleAlarms: 10, ModuleScripts: 5, SubModuleAttrs: 20), + ]; + + public static int Run(BenchArgs args) + { + var instances = args.GetInt("instances", 500); + var repeats = args.GetInt("repeats", 20); + args.RejectUnknown(); + + var flattener = new FlatteningService(); + var validator = new ValidationService(); + var hasher = new RevisionHashService(); + + // Warm the JIT and Roslyn once on a throwaway graph so the first shape doesn't pay it. + { + var warm = Build(Shapes[0], salt: "jit-warmup"); + var w = flattener.Flatten(warm.Instance, warm.Chain, warm.Compositions, warm.ComposedChains, warm.Connections).Value; + validator.Validate(w); + hasher.ComputeHash(w); + } + + Console.WriteLine(); + Console.WriteLine("| 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 |"); + Console.WriteLine("|---|---|---|---|---|---|---|---|---|"); + foreach (var shape in Shapes) + { + var g = Build(shape, salt: shape.Name); + FlattenedConfiguration config = null!; + var flatten = new Samples(); + for (var i = 0; i < repeats; i++) + flatten.Add(Samples.Time(() => config = Flatten(flattener, g))); + + ScriptCompileVerdictCache.Clear(); + ValidationResult result = null!; + var cold = Samples.Time(() => result = validator.Validate(config)); + + var warm = new Samples(); + for (var i = 0; i < repeats; i++) warm.Add(Samples.Time(() => validator.Validate(config))); + var noCompile = new Samples(); + for (var i = 0; i < repeats; i++) noCompile.Add(Samples.Time(() => validator.Validate(config, validateScriptCompilation: false))); + var hash = new Samples(); + for (var i = 0; i < repeats; i++) hash.Add(Samples.Time(() => hasher.ComputeHash(config))); + + Console.WriteLine($"| {shape.Name} | {shape.Depth} | {config.Attributes.Count:N0} / {config.Alarms.Count} / {config.Scripts.Count} | " + + $"{flatten.Percentile(50):F2} | {cold:F0} | {warm.Percentile(50):F2} | {noCompile.Percentile(50):F2} | {hash.Percentile(50):F2} | {result.Errors.Count} |"); + if (result.Errors.Count > 0) + Console.WriteLine($" first errors: {result.SummarizeErrors(3)}"); + } + + // Bulk-deploy CPU: N instances of one template (scripts shared, so after the first + // instance every compile is a verdict-cache hit — the production shape). + Console.WriteLine(); + foreach (var shape in Shapes.Skip(1)) + { + var graphs = Enumerable.Range(0, instances).Select(i => Build(shape, salt: "bulk", instanceIndex: i)).ToList(); + ScriptCompileVerdictCache.Clear(); + var per = new Samples(); + var sw = Stopwatch.StartNew(); + foreach (var g in graphs) + { + per.Add(Samples.Time(() => + { + var c = Flatten(flattener, g); + var v = validator.Validate(c); + if (!v.IsValid) throw new InvalidOperationException(v.SummarizeErrors(3)); + hasher.ComputeHash(c); + })); + } + Console.WriteLine($"{shape.Name}: flatten+validate+hash of {instances} instances sharing one template, serial: " + + $"{sw.Elapsed.TotalSeconds:F2} s total; per instance {per.Summary()}"); + } + return 0; + } + + private static FlattenedConfiguration Flatten(FlatteningService flattener, Graph g) + { + var r = flattener.Flatten(g.Instance, g.Chain, g.Compositions, g.ComposedChains, g.Connections); + return r.IsSuccess ? r.Value : throw new InvalidOperationException(r.Error); + } + + private sealed record Graph( + Instance Instance, + IReadOnlyList