diff --git a/docs/plans/2026-11-09-out-of-process-script-runner-design.md b/docs/plans/2026-11-09-out-of-process-script-runner-design.md index 3b2daa901..7d4f928eb 100644 --- a/docs/plans/2026-11-09-out-of-process-script-runner-design.md +++ b/docs/plans/2026-11-09-out-of-process-script-runner-design.md @@ -1485,6 +1485,110 @@ What is left after this slice: the reader's own wake per frame and the syscalls this VM against about 13 µs on macOS, §12.6), and the worker side of the round trip (its reader, the dedicated evaluation threads and its writer), which this slice did not touch. A non-VM Windows box is still unmeasured. +### 12.8 lmxopcua#789: where the Windows cost goes, spin-before-block measured, nothing kept (2026-11-12) + +**Question.** Which §8.2 budgets still miss on windev, what dominates each, and does any targeted change move them? +`master` = `a28adba2` (runner code identical to `31be927f`). Same VM as §12.6–§12.7 (VMware20,1, Xeon E5-2697 v4, +36 vCPUs, Windows 10 19045, .NET 10.0.8), idle apart from other agents' builds (machine CPU 4–11 % around each run). +The mxaccessgw service on the box was not touched. + +**Where each budget stands** (`Throughput_and_latency_against_the_accepted_gate`, Release, 10 s phases, four runs; and +`Restart_rss_and_kill_latency`, two runs): + +| Budget (§8.2) | windev | Verdict | +|---|---|---| +| Idle p50 ≤ 150 µs, K = 2 | 382 / 386 / 388 / 355 µs (InProcess 132–143 µs) | MISS | +| Host CPU vs InProcess ≤ 25 at paced 10k/s, K = 2 | +71 / +76 / +84 / +82 (raw 77–89 %, InProcess 4–7 %) | MISS | +| p99 at paced 10k/s ≤ 2 ms | 818 / 901 / 1,348 / 841 µs | PASS | +| Closed loop ×64, gate ≥ 5k/s | 58k / 50k / 49k / 56k evals/s, 0 not ok | PASS | +| Worker RSS ≤ 200 MB + scripts (compiled / warm PE cache) | 161 / 160 MB; 36 / 36 MB | PASS | +| Kill latency after T + G ≤ 100 ms | 10–19 ms | PASS | +| Warm restart, 1,000 cached ≤ 2 s | 1,804 / 1,778 ms | PASS | +| Kill both shards → every next result ≤ 2 s | 1,949 / 2,100 ms | borderline (as in §12.1) | + +At paced 5k/s (the accepted planning envelope, [A-14]) the out-of-process host CPU is 22–43 % raw, below InProcess's +61–70 % in the same phase. The 10k/s phase is where it misses. + +**The floor on this VM.** A scratch microbenchmark (not committed) timed the primitives the runner is built from, +20,000 round trips each: + +| Round trip (2 wake-ups) | windev p50 | windev CPU / round trip | macOS (M-series, loaded) p50 / CPU | +|---|---:|---:|---:| +| Two threads, `AutoResetEvent` | 52 µs | 37 µs | 5.5 µs / 6.3 µs | +| Two threads, `Monitor.Wait`/`Pulse` | 55 µs | 38 µs | 5.7 µs / 6.7 µs | +| Two processes, 8-byte ping-pong over `WindowsBlockingPipeStream` | 84–91 µs | host 35–56 µs, peer 41–50 µs | — | +| … same, both ends spin 20 µs before blocking | 28 µs | host 31 µs, peer 34 µs | — | + +So one blocking hand-off costs ~26 µs of latency and ~18 µs of CPU on this VM, about ten times macOS. An idle +evaluation makes four of them in a row (thread accounting below): host writer → worker reader, worker reader → +evaluation thread, evaluation thread → host reader, host reader → result dispatcher. The bare cross-process round trip +alone (84–91 µs) plus the one in-worker hand-off that pre-emption needs (§3.2) is ~115 µs before any protocol work, +and InProcess on this VM is already 132–143 µs. **150 µs is not reachable here without spinning.** + +**Where the host CPU goes at 10k/s.** Two scratch tools (not committed): per-thread CPU and context switches from +`NtQuerySystemInformation` around one phase, and an ETW CPU-sampling trace (kernel profile at 0.5 ms with stacks, CLR +rundown; analysed with TraceEvent). +- Per thread, K = 2, paced 10k/s, host 78.8 µs per evaluation: pool threads 42.9 µs (the harness's pacing loop, which + submits, plus its per-result `ContinueWith` hop; 0.57 context switches per evaluation), the two readers 20.2 µs (0.35), + the two dispatchers 11.4 µs (0.36). One reader wake costs ~57 µs of reader CPU including the frame's handling. +- ETW, host process: 48 % of samples in `ntoskrnl`. By syscall: `NtWriteFile` 14.6 % (one submission frame per + `RunAsync`), thread-pool wake `NtSetIoCompletion` 7.8 % plus pool idling (`NtRemoveIoCompletion`, `NtDelayExecution`) + 5.2 %, `NtSetEvent` 5.2 %, `NtReadFile` 4.4 %, blocking waits 5.7 %, `TimerQueue.SetTimer` 1.0 %. Inclusive: + `RunAsync` 36.7 % (of which `Submit` 24.4 %, the pipe write 15.7 %, the deadline timer 1.6 %), the reader loop 22.8 %, + the dispatcher 13.6 %. Managed code that is not a syscall or a wake is a few percent per frame. +- Idle sequential: exactly 2.01 context switches per evaluation on the host (reader 1.00, dispatcher 1.00) and 2.07 in the + worker (reader 1.00, evaluation thread 1.00) — the four hand-offs above. + +What is left is syscalls and wake-ups, each several times dearer on this VM than on macOS. The issue's candidates +are all in place (§12.6), and the dispatcher hop was measured in §12.7. + +**Spin before block, measured, not kept.** A temporary environment switch (not committed) made each hand-off spin +before it blocked: the pipe reads (on the `OVERLAPPED` status, no syscall per poll), the result dispatcher, and one +evaluation thread per worker. Per-thread accounting, one run each, same method: + +| Spin (µs): host pipe / worker pipe / dispatcher / eval | idle p50 | host µs/eval idle | host µs/eval at 10k/s | +|---|---:|---:|---:| +| none | 358 | 128 | 78.8 | +| – / 50 / – / – | 357 | 122 | 70.3 | +| 50 / 50 / – / – | 343 | 175 | 85.6 | +| 50 / 50 / 50 / – | 341 | 225 | 99.7 | +| 50 / 50 / 50 / 50 | 328 | 216 | 87.8 | +| 400 everywhere | **118** | 253 (host 191 % of a core while idle-sequential) | **260** | +| – / 400 / – / 400 (worker only) | 221 | 106 | 82.8 (worker ~390 % of a core) | + +- A spin shorter than the ~330 µs cycle never catches anything in the sequential phase: each hand-off waits for the + whole rest of the round trip. +- Spinning longer than the cycle meets 150 µs (118 µs), but at about two host cores and four worker cores busy for a + single stream, and +250 points at 10k/s. That trades one budget for a much worse miss of the other. +- Worker-only spinning cuts idle p50 to 221 µs and does nothing for host CPU. +- The one cheap host gain, a worker-side pipe spin of 50 µs (−8 µs/eval), sits inside run-to-run noise. + +**The production submission shape.** The paced phase calls `RunAsync` once per evaluation on purpose. The seams do not: +the Calculation pump and the alarm engine call `RunBatch` per pass, and the VirtualTag coalescer batches whatever became +due together (§12.3). The harness now has a row for that shape, `paced 10,000/s, batched`: the same rate, keys and +per-result continuation, with each 1 ms tick's evaluations submitted in one `RunBatch` call. It runs after the original +four phases, so their rows stay comparable with every earlier record. +- windev, three runs: host CPU **+36 / +41 / +45** (raw 44–52 %, against 83–89 % unbatched). One submission frame + (one `NtWriteFile`) per tick and shard instead of per evaluation halves the host cost. Still above 25. +- Its latency is measured from the batch's submit, so it includes queueing behind siblings: p50 678–741 µs, p99 + 3.9–6.1 ms. InProcess through the same phase has a p99 of 1.2–4.9 ms on this VM, so most of that comes from the + harness shape, not the transport. This row has no §8.2 latency budget. +- macOS, one run (load 6–9): +40 batched against +32 unbatched, so no gain there. The Unix path has no per-write + completion cost to save. + +**Worker-side findings** (not budgeted; for the record): +- `BlockingCollection.Take` (its `SemaphoreSlim` spin, yield and wait) is 35 % of worker CPU at 10k/s, and + `SemaphoreSlim.Release` → `NtSetEvent` is 8 % (the reader waking an evaluation thread). Evaluating the script is 7 %. +- A worker's `.NET Tiered Compilation Worker` runs at ~100 % of a core for tens of seconds after the harness warms 2,000 + keys, because every key's script is its own assembly and tiers up on its own. It is transient and costs worker CPU, + not host CPU, but it competes for cores on a busy node right after a deploy. + +**Kept:** the harness row only (`ScriptRunnerPerfTests.PacedAsync(…, batched: true)`). No runner change: nothing +measured moved a budget without making another one much worse. + +**Still missed on windev:** idle p50 (355–388 µs against 150) and host CPU at 10k/s (+71 to +84 unbatched, +36 to +45 +batched, against 25). macOS still meets both (§12.6–§12.7). The owner's decision is §14 #15. + --- ## 13. Test plan @@ -1596,6 +1700,21 @@ Each has a recommendation, marked ★. 14. **Does this need a real-deployment scale target?** [A-14]'s 5k evals/s/node is a guess. The owner should supply the expected VT / Calc / alarm counts per node for the target sites, or accept the guess as the gate. +15. **Windows idle-latency and host-CPU budgets (lmxopcua#789, §12.8).** On the windev VM one blocking hand-off costs + ~26 µs of latency and ~18 µs of CPU, ten times macOS, and an evaluation needs four of them. Idle p50 is 355–388 µs + (InProcess alone 132–143 µs). Host CPU at 10k/s is +71 to +84 points one evaluation at a time and +36 to +45 + batched, against ≤ 150 µs and ≤ 25. + - ★ **Measure on bare-metal Windows, then state the two budgets per platform.** Keep 150 µs / 25 points where + they are met (Linux and macOS; Windows hardware if it meets them). If a VM is the target, set the Windows + figures from that box, measured with the batched row as the gate. For example, idle p50 ≤ 500 µs (0.2 % of the + 250 ms alarm budget) and ≤ 50 points batched at 10k/s, with 5k/s, the planning envelope [A-14], already below + InProcess. No code change. + - A shared-memory ring transport: frames in a mapped section, with an event signalled only when the peer is + asleep, and a bounded spin. It would remove most `NtWriteFile`/`NtReadFile` calls and wakes under load. Idle + latency still needs ≥ 2 cross-process wakes unless a thread spins, and §12.8 measured spinning at about two host + cores for one stream. It is a new transport, with a new ACL'd kernel object, new fault modes and new tests. + Worth it only if the target load from #14 makes ~0.4–0.9 of a host core at 10k/s matter. + - Spin before blocking (§12.8): rejected. It meets 150 µs only by keeping cores busy. --- diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs index f78053f6b..14ce7e90c 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs @@ -154,7 +154,15 @@ public sealed class ScriptRunnerPerfTests /// the keys, skipping a key still in flight), and latency is measured per call. This is the "p99 at N evals/s" of /// the §8.2 table. /// - private static async Task PacedAsync(IScriptRunner runner, int ratePerSecond) + /// The runner. + /// The offered rate. + /// + /// Submit each tick's evaluations as ONE call instead of one + /// each — the shape of the production seams, whose Calculation pump, alarm + /// engine and virtual-tag coalescer hand everything that became due together to the runner at once (§4.5, + /// lmxopcua#789). Same offered rate, keys, per-result continuation and measurement as the unbatched phase. + /// + private static async Task PacedAsync(IScriptRunner runner, int ratePerSecond, bool batched = false) { var samples = new List(ratePerSecond * (int)Phase.TotalSeconds + 1024); var gate = new object(); @@ -168,14 +176,32 @@ public sealed class ScriptRunnerPerfTests while (wall.Elapsed < Phase) { var due = (long)(wall.Elapsed.TotalSeconds * ratePerSecond); + List<(int Key, int X)>? tick = batched ? [] : null; while (issued < due) { var key = next++ % Keys; if (Volatile.Read(ref inFlight[key])) continue; Volatile.Write(ref inFlight[key], true); var x = (int)issued++; + if (tick is not null) tick.Add((key, x)); + else Track(key, x, Stopwatch.GetTimestamp(), runner.RunAsync(Invocation(key, x), Ct)); + } + if (tick is { Count: > 0 }) + { var t0 = Stopwatch.GetTimestamp(); - pending.Add(runner.RunAsync(Invocation(key, x), Ct).ContinueWith(t => + var outcomes = runner.RunBatch(tick.Select(i => Invocation(i.Key, i.X)).ToArray(), Ct); + for (var i = 0; i < tick.Count; i++) Track(tick[i].Key, tick[i].X, t0, outcomes[i]); + } + await Task.Delay(1, Ct); + } + await Task.WhenAll(pending); + var elapsed = wall.Elapsed; + var cpu = (Process.GetCurrentProcess().TotalProcessorTime - cpu0).TotalMilliseconds / elapsed.TotalMilliseconds * 100; + samples.Sort(); + return new PhaseResult(issued / elapsed.TotalSeconds, Percentile(samples, 0.50), Percentile(samples, 0.99), cpu, ok, notOk, firstFailure); + + void Track(int key, int x, long t0, Task run) + => pending.Add(run.ContinueWith(t => { var us = Stopwatch.GetElapsedTime(t0).TotalMicroseconds; Volatile.Write(ref inFlight[key], false); @@ -188,14 +214,6 @@ public sealed class ScriptRunnerPerfTests Interlocked.CompareExchange(ref firstFailure, $"{o.Status}: {o.Reason}", null); } }, TaskScheduler.Default)); - } - await Task.Delay(1, Ct); - } - await Task.WhenAll(pending); - var elapsed = wall.Elapsed; - var cpu = (Process.GetCurrentProcess().TotalProcessorTime - cpu0).TotalMilliseconds / elapsed.TotalMilliseconds * 100; - samples.Sort(); - return new PhaseResult(issued / elapsed.TotalSeconds, Percentile(samples, 0.50), Percentile(samples, 0.99), cpu, ok, notOk, firstFailure); } private static string Row(string runner, string phase, PhaseResult r, PhaseResult? inProcess = null) @@ -245,6 +263,8 @@ public sealed class ScriptRunnerPerfTests Add("paced 10,000/s", await PacedAsync(runner, 10_000)); var closed = await ClosedLoopAsync(runner, concurrency: 64); Add("closed loop ×64", closed); + // After the original four phases, so their rows stay comparable with every earlier record (lmxopcua#789). + Add("paced 10,000/s, batched", await PacedAsync(runner, 10_000, batched: true)); if (name == "OutOfProcess K=2") k2Closed = closed; } finally @@ -260,6 +280,7 @@ public sealed class ScriptRunnerPerfTests report.AppendLine() .AppendLine("§8.2 budgets: added latency p50 ≤ 150 µs (idle), p99 ≤ 2 ms at 10k/s, ≥ 10,000 evals/s at K=2, " + "host CPU for IPC (the \"vs InProcess\" column) ≤ 25 % of one core at 10k/s. " + + "\"batched\": each 1 ms tick's evaluations go in one RunBatch call, as the production seams submit. " + "Accepted gate (owner, §14): ≥ 5,000 evals/s/node."); Report(report);