Files
ScadaBridge/docs/plans/2026-08-15-target-scale-load-test-results.md
T
Joseph Doherty 94e8301e44 test(loadharness): retain raw resource samples; record findings F4 and the discarded run
HarnessRunResult now carries every ResourceSample, not just the window summaries.
Motivated by finding F1: the definitive run recorded ZERO gen-2 collections across
45M events, so a positive least-squares heap slope cannot be told apart from
gen-2 garbage that was simply never collected. The summary alone cannot settle
that; the series can. The reported run predates this field -- noted as such in the
results doc rather than implied otherwise.

Also records:
  - the second full-scale run was DISCARDED, not reported: a verification build
    overlapped the start of its measurement window, and a contaminated measurement
    is not evidence.
  - finding F4, a pre-existing test-isolation flake in
    QueueDepthGaugeTests.Gauge_TracksBufferedDepth_AcrossEnqueueDrainAndPark
    (fails in a full-suite run, passes in isolation -- shared static gauge carrying
    state across tests). It cannot originate here: this branch changes zero src/
    files vs its base 986e6e7a. Left unfixed deliberately; filed for separate triage.

Verified: full slnx build clean; SiteRuntime 604/604, Communication 691/691 pass;
TargetScaleHarnessSmokeTests passes (78s).
2026-08-15 03:01:17 -04:00

311 lines
16 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# Target-Scale Load Test — Results (Phase-8 WP-4, deferred-work register #25 + row 50)
**Date:** 2026-08-15
**Design memo:** `docs/plans/2026-08-15-target-scale-load-test-design.md`
**Harness:** `tests/ZB.MOM.WW.ScadaBridge.LoadHarness/`
**Closes:** deferred-work register **#25** and **row 50**; residual **7** of
`docs/plans/2026-08-15-arch-review-remediation-execution-log.md`.
> Register row 25 recorded that WP-4 had been *claimed complete* on the strength of a
> 107-byte checklist stub with no per-work-package results and no linked run. This
> document is the run that stub never had.
---
## 1. Environment
| | |
|---|---|
| Host | `Josephs-MBP` — Apple M4 Pro, 14 logical cores, 48 GB RAM |
| OS | macOS 26.5.2 (Darwin) |
| Runtime | .NET 10.0.5, **server GC enabled**, Release build |
| Branch / commit | `target-scale-load-test` @ `20f6b0b9` (harness), `8abebdae` (design memo) |
| Concurrent load | The 8-node `docker/` rig (OrbStack) remained running throughout — the user's live development cluster. Measured baseline: **~86% of one core (~6% of the box)** and ~10-16 GB RSS. The harness figures below are therefore *pessimistic*, not idealised. |
| Scale executed | **10 sites × 500 instances × 75 tags = 375,000 live tag subscriptions** |
| Offered load | 37,500 tag updates/second nominal (one update per tag per 10 s) |
| Measurement window | 20 minutes steady state, after a 2-minute settle |
| Total wall time | 1,510 s (~25 min) |
**One clean full-scale run is the dataset reported here.** A second run was started to
add raw per-sample resource capture (sharpening finding F1), but a verification build
overlapped the start of its measurement window; it was **discarded rather than
reported**, per the rule that a measurement contaminated by concurrent load is not
evidence. The raw-sample capture it was meant to exercise is now in the harness
(`HarnessRunResult.ResourceSamples`) and will be present in any future run, including
the 1-hour run in §7 — the run reported below predates that field.
---
## 2. Verdict summary
| # | Criterion | Threshold | Measured | Verdict |
|---|---|---|---|---|
| 1 | `[2.5-1]` 10 sites simultaneously operational | all 10 built, ramped, tracked centrally | 10/10 sites tracked by `CentralHealthAggregator` | **PASS** |
| 2 | `[2.5-2]` 500 instances/site, active subscriptions | 5,000 actors; `SkippedNoCallback` = 0 | 5,000 `InstanceActor`s; skipped = **0** | **PASS** |
| 3 | `[2.5-3]` 75 tags/instance (375,000 total) | 375,000 subscribed via the real DCL | 375,000 tag paths across 50 `DataConnectionActor`s | **PASS** |
| 4 | Tag update latency | P99 < 250 ms, P50 < 50 ms | **P50 0.88 ms, P95 2.83 ms, P99 4.57 ms, P99.9 16.04 ms, max 37.41 ms** (1,100,675 samples) | **PASS** (55× margin at P99) |
| 5 | `[xc-1]` message patterns under load | ≥ 95% of nominal, no unexpected loss | **37,518/s achieved vs 37,500 nominal (100.0%)**; 45,021,375 updates offered; **0 events dropped** at healthy subscribers | **PASS** |
| 6 | `[xc-2]` health reports within expected intervals | collect+ingest P99 < 1,000 ms; all sites tracked | **P99 0.31 ms, max 4.60 ms** over 440 reports; 10/10 sites | **PASS** (3,200× margin) |
| 7 | `[xc-6]` debug view without impacting site performance | snapshot P99 < 2,000 ms, 0 timeouts | **P99 2.19 ms, max 2.72 ms**, 264 completed, **0 timeouts** | **PASS** |
| 8 | `[xc-7]` S&F concurrent buffering from many instances | 20,000 messages, 25 origins, drains to 0 | 20,000 buffered at **15,368 msg/s**; residual depth **0** | **PASS** |
| 9 | Row 50 — S&F drain rate | > 500 msg/s | **3,533 msg/s** (20,000 messages in 5.66 s of active drain) | **PASS** (7× margin) |
| 10 | Row 50 — slow-subscriber backpressure | healthy = 100%; stalled loss confined to its own channel | **healthy 100.00% (4/4, zero drops)**; stalled 1.18%, all 197,028 losses in its own bounded channel | **PASS** |
| 11 | Deploy 500 instances to a site | slowest site < 120 s | **2.6 s** | **PASS** (46× margin) |
| 12 | Memory within acceptable bounds | WS slope < 20 MB/min; no monotonic heap climb | WS **+8.83 MB/min**; heap sawtooths (peak 3,625 MB vs 2,313→2,523 MB endpoints) with a **+19.52 MB/min** drift — see finding **F1** | **PASS with a caveat** |
| 13 | CPU within acceptable bounds | mean < 50% of the box | **41% of one core = 2.9% of the box** (peak 55% of one core) | **PASS** (17× margin) |
**11 clean passes, 1 pass with a documented caveat, 0 failures.** Four WP-4
sub-criteria were out of this harness's scope — see §6.
---
## 3. Measured detail
### 3.1 Deployment / ramp
```
site fixtures built 0.2s
all 5,000 instance actors 2.7s (10 sites in parallel)
slowest single site 2.6s (500 instances, production staggering)
```
The ramp used the production `StartupBatchSize` (20) / `StartupBatchDelayMs` (100)
pacing, i.e. 25 batches × 100 ms = 2.5 s of *deliberate* delay per site. So the 2.6 s
figure is almost entirely the configured stagger; actual construction of 500
`InstanceActor`s (each deserializing a 75-attribute `FlattenedConfiguration`, loading
static overrides from SQLite and issuing a DCL subscribe) costs ~0.1 s. Against a
120 s budget this criterion is not close to binding.
### 3.2 Tag update latency (DCL boundary → stream subscriber)
```
samples 1,100,675 mean 1.17ms
p50 0.88ms p95 2.83ms p99 4.57ms p99.9 16.04ms max 37.41ms
```
This is a true end-to-end path measurement, not a synthetic timer: the emit instant is
stamped on the `TagValue` handed to the adapter callback and travels verbatim through
`DataConnectionActor``TagValueUpdate.Timestamp``AttributeValueChanged.Timestamp`
→ the site stream → `StreamRelayActor` → the proto `SiteStreamEvent`, where the
subscriber subtracts it. Every hop is production code.
Sub-millisecond median under 37,500 updates/s across 5,000 actors means the actor
hierarchy is nowhere near its ceiling at target scale.
### 3.3 Stream delivery
```
events delivered 900,675
events dropped 0
```
Zero evictions at the 100 live subscribers across a 20-minute window at full rate.
The site stream's `DropHead` buffering exists for pathological cases; at nominal
target-scale load it never engaged.
### 3.4 Health reporting at scale
```
samples 440 mean 0.03ms p50 0.01ms p95 0.04ms p99 0.31ms max 4.60ms
reports ingested 440 sites tracked centrally 10
```
`SiteHealthCollector.CollectReport` for a site carrying 37,500 subscriptions plus
`CentralHealthAggregator.ProcessReport` costs well under a millisecond. Against the
30-second report interval there is no plausible queueing risk.
### 3.5 Debug view under load
```
samples 264 mean 0.14ms p50 0.08ms p99 2.19ms max 2.72ms
completed 264 timed out 0
```
Each sample is an `Ask<DebugViewSnapshot>` landing in the mailbox of an
`InstanceActor` concurrently ingesting tag updates, so the figure includes real
queueing behind production traffic. `[xc-6]`'s "without impacting site performance"
also holds in the other direction: tag latency percentiles were measured with these
snapshots running throughout, and show no degradation.
### 3.6 Resources
```
window 1200s over 121 samples
working set 2665 -> 3261 MB (peak 3261) slope +8.83 MB/min
managed heap 2313 -> 2523 MB (peak 3625) slope +19.52 MB/min
cpu mean/peak 41% / 55% of one core (2.9% of the box)
threads 58 gen2 GCs in window: 0
```
CPU is the headline: **375,000 subscriptions at 37,500 updates/s consumed under half
of one core of fourteen.** Thread count stayed flat at 58 for ten actor systems.
---
## 4. Findings
### F1 — Memory: 20 minutes with zero gen-2 collections cannot fully settle the leak question (Low)
The working-set slope (+8.83 MB/min) is inside the threshold, and the managed heap
clearly *sawtooths* — its peak (3,625 MB) sits well above both endpoints (2,313 MB →
2,523 MB), so the collector is demonstrably reclaiming. But **`GC.CollectionCount(2)`
recorded zero gen-2 collections across the entire 25-minute run**, at 45 million
events. Gen-2 was therefore never compacted, and a positive least-squares drift on an
uncompacted heap cannot be distinguished from a genuine slow leak by this run alone.
This is a limitation of the shortened window (deviation D1), not an observed defect:
no metric degraded, no drop appeared, and latency percentiles were flat from the first
minute to the twentieth. Recorded honestly rather than reported as "no leak".
**To settle it**, run the full 1-hour protocol (§7) and check whether the heap slope
flattens once gen-2 collections begin, or issue an explicit
`GC.Collect(2, Forced, blocking: true)` at window start and end and compare.
Deliberately *not* attempted here — the brief was to measure, not to tune.
### F2 — Store-and-forward waits one full `DefaultRetryInterval` before draining a deferred backlog (informational, by design)
The drain measurement initially read as **33 msg/s**, which would have been alarming.
The progress series showed why: **nothing drained for 29-30 seconds, then the entire
backlog cleared in a fraction of a second.**
Cause, confirmed in source: `StoreAndForwardService.EnqueueAsync` with
`attemptImmediateDelivery: false` stamps `message.LastAttemptAt = UtcNow`
(`StoreAndForwardService.cs:754-757`). `GetMessagesForRetryAsync`'s due-predicate is
`last_attempt_at_ms IS NULL OR retry_interval_ms = 0 OR (now - last_attempt) >= retry_interval`,
so such a row is not due for one `DefaultRetryInterval` (30 s). Explicit
`TriggerSweep()` calls find nothing due and correctly do nothing.
This is **correct, intended behaviour** — the caller declared delivery was not
attempted, so the row waits one retry interval — but it is easy to misread as slow
drainage. The harness therefore reports the two numbers separately:
```
retry wait before drain 28.9s (DefaultRetryInterval)
drain throughput 3,533 msg/s (active drain 5.66s)
```
Worth knowing operationally: a site that buffers a backlog this way will appear
completely stalled for the first 30 seconds. Note the `Notify.Send` path
(`deferToSweep: true`) deliberately leaves `LastAttemptAt` null so its rows are due
immediately and skip this wait entirely.
### F3 — Slow-subscriber isolation is complete, and the mechanism is worth recording (positive result)
Register row 50 asked what a slow/stalled gRPC subscriber does to per-subscriber
buffering with several subscribers attached. With five subscribers on the *same*
instance (identical offered sequence) and one reader stalled at 50 ms/event:
| Subscriber | State | Received | Dropped | Delivery |
|---|---|---|---|---|
| slowprobe-00 | **STALLED** | 2,369 | 197,028 | 1.18% |
| slowprobe-01 | healthy | 200,000 | 0 | **100.00%** |
| slowprobe-02 | healthy | 200,000 | 0 | **100.00%** |
| slowprobe-03 | healthy | 200,000 | 0 | **100.00%** |
| slowprobe-04 | healthy | 200,000 | 0 | **100.00%** |
**Isolation is total** — not merely "good". The stalled subscriber lost 98.8% of its
own events and cost its peers exactly nothing. The reason is structural, and each link
matters:
1. The per-subscriber graph is `Where → Buffer(StreamBufferSize, DropHead) → Sink.ForEach(Tell)`.
A `DropHead` buffer *always* accepts, so it never backpressures the `BroadcastHub`
upstream — one subscriber cannot stall the hub for the others.
2. `Sink.ForEach` does an actor `Tell`, which never blocks.
3. `StreamRelayActor.WriteToChannel` uses `TryWrite` on a bounded `DropOldest`
channel, which never blocks either — so the relay actor's mailbox drains regardless
of reader speed, and loss is confined to that subscriber's own channel where it is
counted.
The consequence for operators: a slow WAN link or wedged central client degrades
**only its own feed**, and the loss is visible in the per-stream eviction counter and
the `RecordSiteStreamEventDropped` telemetry rather than being silent.
One caveat established while building the probe: publishing an unpaced burst makes
*every* subscriber lose events, because the publish source is a single
`Source.ActorRef(StreamBufferSize, DropHead)` **shared** by all attribute subscribers,
upstream of the hub. That shared stage — not per-subscriber buffering — is the real
limit on burst absorption. The probe paces at 2,000 events/s to isolate the variable
under test; the shared stage's own capacity is separately covered by
`SiteStreamThroughputTests`.
### F4 — Pre-existing test-isolation flake in `QueueDepthGaugeTests` (Low, not introduced here)
Noticed during this work package's verification pass, recorded so it is not later
mistaken for a regression from the load-harness branch.
`StoreAndForward.Tests.QueueDepthGaugeTests.Gauge_TracksBufferedDepth_AcrossEnqueueDrainAndPark`
**fails in a full-suite run** (`Expected: 0, Actual: 2`, `QueueDepthGaugeTests.cs:116`)
but **passes when run in isolation** — the signature of a shared static gauge carrying
state across tests, i.e. an ordering dependency rather than a product defect.
It cannot originate from this branch: the branch changes **zero `src/` files** relative
to its base (`986e6e7a`), and both the StoreAndForward source and its test project are
byte-identical to that base. Left unfixed deliberately — out of scope for a measurement
work package, and the brief was explicitly not to attempt unrelated fixes. Worth a
separate triage alongside the pre-existing `SandboxTests` timing pin already recorded as
residual 6 of the arch-review remediation execution log.
---
## 5. What this does *not* prove
Stated plainly so the evidence is not over-read:
- **Not a clustered run.** Sites are single, non-clustered `ActorSystem`s (deviation
D2). Failover, singleton handover and split-brain behaviour are covered elsewhere
(`FailoverTimingTests`, `SbrFailoverTests`, `docker/failover-drill.sh`).
- **Not a real-network run.** The gRPC, health-transport and S&F-to-central hops are
in-process. Serialization cost, TLS, WAN latency and socket backpressure are out of
frame; the *stream* path's backpressure was measured deliberately by substituting a
controllable reader for the socket (D4).
- **Not a real OPC UA run.** 375,000 monitored items were simulated at the adapter
callback (D3). The DCL above that callback is real and fully exercised.
- **Not 1 hour.** 20 minutes (D1). See finding F1 for the one question this leaves
genuinely open.
## 6. WP-4 criteria not covered by this harness
Recorded rather than silently dropped (deviation D7):
| Criterion | Why not covered |
|---|---|
| `[xc-3]` site event logging within 30-day / 1 GB limits | Needs a long-horizon retention run, not a load run |
| `[xc-4]` audit logging does not degrade central | Needs a central MS SQL fixture; this harness builds site runtimes only |
| `[xc-5]` template flattening/validation for large templates | Template Engine is a central-cluster concern; unrelated to the site-runtime load path |
| `[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.
## 7. Reproducing
Full protocol as executed (20-minute window):
```bash
dotnet run -c Release --project tests/ZB.MOM.WW.ScadaBridge.LoadHarness -- \
--results loadharness-results.json
```
The full **1-hour** version required by the WP-4 test protocol — identical in every
other respect, and the run that would settle finding F1:
```bash
dotnet run -c Release --project tests/ZB.MOM.WW.ScadaBridge.LoadHarness -- \
--sustain-minutes 60 --results loadharness-results-1h.json
```
CI-scale smoke (~80 s), which asserts the harness still produces coherent
measurements end to end:
```bash
dotnet test tests/ZB.MOM.WW.ScadaBridge.PerformanceTests \
--filter "FullyQualifiedName~TargetScaleHarnessSmoke"
```
`--help`-style knobs: `--sites`, `--instances-per-site`, `--tags-per-instance`,
`--tag-update-period-seconds`, `--settle-minutes`, `--sustain-minutes`,
`--sample-seconds`, `--health-interval-seconds`, `--debug-probe-interval-seconds`,
`--subscribe-settle-seconds`, `--stream-probes-per-site`, `--sf-drain-messages`,
`--slow-subscriber-events`, `--data-dir`, `--results`. An unknown key is rejected
rather than ignored, so a typo cannot silently change the measured scale.