Files
ScadaBridge/docs/plans/2026-08-15-target-scale-load-test-results.md
T
Joseph Doherty e9e44a9ef0 test(loadharness)+docs: wire-path stream probes — R2 batching benchmark-proven at target scale
The WP-4 runs measured the stream path only up to the bounded send channel;
the probe deliberately substituted the socket hop with a controllable reader,
which is exactly where the R2 SiteStreamEventBatcher lives — so batching had
never been in any benchmark's hot path. The harness now also attaches per-site
wire probes: a real Kestrel h2c listener hosting the production
SiteStreamGrpcServer, dialed by the production SiteStreamGrpcClient with
batching negotiated, batch sizes read from the production batch_size histogram
via a MeterListener (--wire-probes-per-site, default 10; 0 restores the old
shape). Full-scale run (10x500x75, 20-min window, results doc §8 + raw JSON):
899,807 events in 12,462 frames (mean 72.2 ev/frame, p50=p99=75), wire P99
43.4 ms vs the 250 ms budget — every batch pays the full 25 ms linger since a
75-event burst never hits the 100 cap — zero drops, zero faults, offered load
100.0% of nominal with fan-out doubled. CI smoke Fact now asserts the wire
path carries traffic and observes frames.
2026-08-18 10:32:46 -04:00

23 KiB
Raw Blame History

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 InstanceActors; 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 DataConnectionActors 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 InstanceActors (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.

SETTLED 2026-08-15 — the 1-hour protocol was run (register row 29): NOT a leak. Same harness, same scale, --sustain-minutes 60 (3,911 s total, 135,041,250 updates offered at 37,511/s = 100.0 % of nominal, on the same host, concurrent with the docker rig and a central failover drill). The decisive numbers over the 3,600 s steady-state window (361 samples): working set 2,722 → 1,757 MB, slope −28.89 MB/min (peak 3,258 MB), one gen-2 collection observed, threads flat at 59. A working set that falls by ~1 GB across a full sustained hour is incompatible with a slow leak; the managed-heap least-squares slope (+16.26 MB/min, end 3,352 MB, peak 3,726 MB) remains an artifact of measuring across sawtooth segments between rare gen-2 collects, exactly as F1 hypothesised. Every other metric held or improved on the 20-minute run: tag latency P50 0.92 ms / P99 4.01 ms / max 92.18 ms across 2.9 M samples, 0 events dropped on live subscribers, health-report ingest P99 0.05 ms (1,240/1,240, 10 sites), debug snapshots 744/744 with 0 timeouts, S&F 20,000 msgs buffered at 16,837 msg/s and drained at 3,418 msg/s to depth 0 (same one-DefaultRetryInterval pre-drain wait, 29.0 s — F2 unchanged), slow-subscriber isolation structural and total (4 healthy peers at 100.00 % while the stalled probe lost 98.81 % entirely in its own channel — F3 unchanged). CPU 2.9 % of the box.

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 ActorSystems (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). Partially superseded by §8 (2026-08-18): the site→central stream hop now also runs over a real loopback HTTP/2 socket with the R2 batcher, protobuf serialization and Kestrel in the measured path. TLS and WAN latency remain out of frame.
  • 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):

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:

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:

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, --wire-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.

Since 2026-08-18 the default protocol also attaches 10 wire stream subscribers per site (real Kestrel + real SiteStreamGrpcClient, §8); --wire-probes-per-site 0 reproduces the original in-process-only shape.


8. Wire-path run — R2 stream batching in the hot path (2026-08-18)

Raw metrics: docs/plans/2026-08-18-loadharness-results-wire.json

8.1 Why this run exists

Both prior runs (§2 and the §4 F1 1-hour sustain) measured the stream path only up to the bounded send channel: StreamSubscriberProbe deliberately substitutes the final socket hop with a controllable reader (deviation D4 — required by the row-50 slow-subscriber measurement). The R2 gRPC event batcher (SiteStreamEventBatcher, merged c75c79f8 on 2026-08-15, about an hour after the §2 run) lives exactly in that substituted hop — so no benchmark run had ever exercised it, only R2's own component-level measurement (worst-case P99 25.4 ms) and trickle-rate live traffic on the rig (register row 48).

This run adds a wire path to the harness without touching the existing probes: each site hosts the production SiteStreamGrpcServer on a real Kestrel HTTP/2 (h2c) loopback listener (production CommunicationOptions defaults — batch cap 100, window 25 ms, channel capacity 1000), and the production SiteStreamGrpcClient dials in with BatchingSupported = true, one channel per site with 10 streams multiplexed on it — the exact production shape and the exact production code on both ends. Latency is recorded in the client callback, i.e. after protobuf deserialization, batch unpacking and domain mapping. The batch-size figures are the production scadabridge.site.stream.batch_size histogram itself, captured by a MeterListener. Deliberately not in the path: ControlPlaneAuthInterceptor (authenticates once per stream lifetime, nothing per-event) and TLS (production is h2c too).

The 100 wire subscribers are attached in addition to the 100 in-process probes, watching the same instances (same stride), so one run yields both distributions and their difference isolates the wire hop's cost. Total hub fan-out is therefore double that of the §2 run.

8.2 Environment

Identical posture to §1: same host (M4 Pro, 14 cores, 48 GB), .NET 10.0.5, server GC, Release; the 8-node docker/ rig stayed running throughout (D8); 20-minute window after a 2-minute settle; harness at the state committed with this section.

8.3 Measured

in-process probes (§2 path) wire probes (new)
Subscribers 100 100
Events delivered (window) 899,807 899,807
Events dropped / faults 0 / — 0 / 0
Latency mean 1.79 ms 28.00 ms
Latency P50 1.36 ms 26.97 ms
Latency P95 4.19 ms 32.07 ms
Latency P99 6.74 ms 43.44 ms
Latency P99.9 / max 25.83 / 32.17 ms 53.94 / 62.42 ms

Batching (production histogram, window deltas):

events 899,807  frames 12,462          → mean 72.20 events/frame  (72x frame reduction)
batch size p50/p95/p99/max = 75/75/75/75   batched frames 11,998   single-event frames 464
server channel drops 0    stream faults 0    graceful completions 0

Offered load held at 37,497/s = 100.0% of nominal with the doubled fan-out (driver overrun 0.0 s, skipped 0). Whole-run CPU mean 66% of one core (4.7% of the box) vs 41% in §2 — the added ~25% of one core buys 10 Kestrel listeners, 100 live HTTP/2 streams, protobuf serialization of ~900 k events and the client-side unpack. Working-set slope −116 MB/min (a large mid-window release; peak 3,413 MB), heap sawtooth with 5 gen-2 collects and endpoints 1,876→1,943 MB — consistent with the §4 F1 resolution (row 29: not a leak).

8.4 Reading the numbers

  • The batcher engaged exactly as designed, at its natural batch size. The driver emits each instance's 75 tags contiguously within a slice, so a subscriber receives one 75-event burst per 10 s period. 75 < the 100-event cap, so the size cap never closes a batch early — nearly every burst becomes exactly one 75-event frame (p50 = p99 = max = 75). The 464 single-event frames are burst stragglers that arrived after their batch's window closed.
  • The ~26 ms wire P50 is dominated by the deliberate linger, and that is the documented trade. Because bursts never hit the cap, every batch pays the full 25 ms GrpcStreamBatchWindow — this workload is the batcher's worst-case latency posture and best-case framing win simultaneously. Wire P50 26.97 ms ≈ in-process P50 1.36 ms + the 25 ms window + sub-millisecond socket/serialize cost. Against the 250 ms P99 threshold the wire path passes with a 5.8× margin (43.44 ms), and the CommunicationOptionsValidator bound (window strictly < 250 ms) is confirmed to compose: end-to-end latency stayed threshold-compliant with the window fully paid on every frame.
  • Framing efficiency at scale is now measured, not extrapolated: 899,807 events crossed the wire in 12,462 frames. Pre-R2, the same window would have cost 899,807 frames.
  • Nothing degraded elsewhere. The in-process path under doubled fan-out reads P99 6.74 ms vs 4.57 ms in §2 — same order, still a 37× margin — and every §2 pass criterion that this run re-exercises (offered load, zero drops at healthy subscribers, health reports, debug snapshots, S&F drain, slow-subscriber isolation) repeated its pass.

Verdict: PASS. R2's negotiated batching is now benchmark-proven at target scale over a real socket: 72× fewer frames, zero loss, zero faults, and worst-case-posture latency 5.8× inside the budget.