diff --git a/CLAUDE.md b/CLAUDE.md index 6cef1de7..90a8fe1a 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -392,8 +392,9 @@ See `docs/ScriptEditor.md` for the full guide. Scripts may use the `{{equip}}` t **Out-of-process script runner (lmxopcua#780, opt-in).** `Scripting:Runner` = `InProcess` (default, unchanged) | `OutOfProcess` | `Shadow` (not yet). `OutOfProcess` runs the VirtualTag + Calculation seams' compiled scripts in `ZB.MOM.WW.OtOpcUa.ScriptWorker` processes (`src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess`, protocol in `Core.Scripting.Protocol`), shipped in `script-worker/` -beside the host; a runner-side failure publishes `BadResourceUnavailable` (ScadaBridge-visible, ScadaBridge#112) and the seam re-evaluates +beside the host (self-contained + started via its apphost on a `-r win-x64 --self-contained` publish, through the muxer otherwise); a runner-side failure publishes `BadResourceUnavailable` (ScadaBridge-visible, ScadaBridge#112) and the seam re-evaluates when the worker is back. Optional `Scripting:Worker:PeCacheDir` = HMAC'd compiled-PE cache (restart without Roslyn); the `script-runner` readiness check is at worst Degraded (never fails ready). The worker tests -are `tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests` (`Category=ScriptWorker`, real processes). See `docs/VirtualTags.md` +are `tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests` (`Category=ScriptWorker`, real processes; `Category=Perf` harness opt-in via +`OTOPCUA_SCRIPT_PERF=1`). docker-dev overlay: `docker-dev/docker-compose.script-runner.yml`. See `docs/VirtualTags.md` §"Out-of-process runner". diff --git a/docker-dev/README.md b/docker-dev/README.md index fc2e8957..54b022f4 100644 --- a/docker-dev/README.md +++ b/docker-dev/README.md @@ -160,6 +160,17 @@ and the script fails loudly saying so. A plain `docker compose up -d` also hides rig without the gate helping: `up -d` blocks on the `depends_on: service_healthy` conditions and returns ~30 s *after* Traefik starts, by which time the router table is long loaded. +## Out-of-process script runner overlay + +`docker-compose.script-runner.yml` is an **optional overlay** (lmxopcua#780). It sets `Scripting:Runner=OutOfProcess` for the +VirtualTag and Calculation seams on `central-1`/`central-2`, with a container-local `PeCacheDir`. The image must come from a branch +that has the runner. Bring it up with +`docker compose -f docker-dev/docker-compose.yml -f docker-dev/docker-compose.script-runner.yml up -d --no-deps central-1 central-2`. +To go back to InProcess, run the same `up` with the base file alone. + +Note that `deploy.sh` reads its body from stdin whenever stdin is not a terminal. Run it as `./deploy.sh < /dev/null` from a +script or a background job; otherwise curl waits on stdin forever. + ## QuestDB historian overlay `docker-compose.questdb.yml` is an **optional overlay** (not part of the default rig) that adds one service, `questdb` diff --git a/docker-dev/docker-compose.script-runner.yml b/docker-dev/docker-compose.script-runner.yml new file mode 100644 index 00000000..457c9cfa --- /dev/null +++ b/docker-dev/docker-compose.script-runner.yml @@ -0,0 +1,25 @@ +# docker-dev/docker-compose.script-runner.yml — optional overlay: run the central pair's VirtualTag + Calculation +# scripts OUT OF PROCESS (lmxopcua#780, Scripting:Runner=OutOfProcess). The scripted-alarm seam stays in process. +# +# Up (recreates only the two central nodes with the extra env; the image must be built from a branch that has the +# runner, i.e. `docker compose -f docker-dev/docker-compose.yml build central-1` first): +# docker compose -f docker-dev/docker-compose.yml -f docker-dev/docker-compose.script-runner.yml up -d --no-deps central-1 central-2 +# Back to InProcess (the default and the rollback): re-run `up -d --no-deps central-1 central-2` with the base file alone. +# +# Watch it: `docker exec ps -eo pid,args | grep ScriptWorker` lists the shard workers (they start on the first +# compiled evaluation, not at boot); `/metrics` on :9000 carries otopcua_script_* (runner state, worker up/inflight, +# eval duration, compile cache); `/health/ready` carries the `script-runner` entry (Degraded at worst, never 503). +# PeCacheDir is container-local (/tmp), so a container recreate starts with a cold cache. +x-script-runner-env: &script-runner-env + Scripting__Runner: "OutOfProcess" + Scripting__Runner__Seams__0: "VirtualTag" + Scripting__Runner__Seams__1: "Calculation" + Scripting__Worker__PeCacheDir: "/tmp/otopcua-pe-cache" + +services: + central-1: + environment: + <<: *script-runner-env + central-2: + environment: + <<: *script-runner-env diff --git a/docs/ServiceHosting.md b/docs/ServiceHosting.md index 899f8d55..06263ec5 100644 --- a/docs/ServiceHosting.md +++ b/docs/ServiceHosting.md @@ -98,7 +98,10 @@ At startup the host kills workers a dead predecessor of the same install left be (pid + start time + image, and only when the marker's host is gone). `Scripting:Worker:PeCacheDir`, when set, holds the compiled-PE cache, its HMAC key and the launch markers: put it outside the install folder (startup refuses a relative path or one inside the content root) on a directory only the service account can read. The `script-runner` readiness component -is at worst Degraded. The worker currently runs under the host's account through the dotnet muxer; the dedicated low-privilege account, +is at worst Degraded. A self-contained host publish (`dotnet publish … -r win-x64 --self-contained`, the Windows installs, which have no +.NET runtime) ships a **self-contained** worker in `script-worker/` (~97 MB: it carries its own runtime) and the host starts its +`ZB.MOM.WW.OtOpcUa.ScriptWorker.exe` apphost directly; a framework-dependent host (docker-dev) runs the worker's dll through the +dotnet muxer. The worker currently runs under the host's account; the dedicated low-privilege account, pipe ACL and firewall outbound rule (design §14 #5/#6) are installer work still open on lmxopcua#780. See `docs/VirtualTags.md` §"Out-of-process runner". diff --git a/docs/VirtualTags.md b/docs/VirtualTags.md index f4d0e602..e31943de 100644 --- a/docs/VirtualTags.md +++ b/docs/VirtualTags.md @@ -114,11 +114,24 @@ and Calculation evaluators hand each compiled run to `OutOfProcessScriptRunner` is on the **ready** tier and is at worst **Degraded** (still 200): a sick runner never fails readiness, so a pair does not move ServiceLevel to its peer over a script problem (design §14 #12). - **Deployment.** The Host build copies the worker into `script-worker/` beside `OtOpcUa.Host.dll` - (`ScriptWorker.Deploy.targets`, Build and Publish); `Scripting:Worker:ExecutablePath` overrides it. It is run through - the dotnet muxer, so it needs a framework-dependent host (the docker-dev image). Not yet done (lmxopcua#780): a - self-contained worker for the Windows installs, the low-privilege worker account, pipe ACL and firewall rule - (installer), the docker-dev live drill, the scripted-alarm seam, the per-seam batch submit (design §4.5) and the §8 - perf harness. + (`ScriptWorker.Deploy.targets`, Build and Publish); `Scripting:Worker:ExecutablePath` overrides it. A framework-dependent + host (the docker-dev image) gets the worker's framework-dependent build, run through the dotnet muxer. A **self-contained** + host publish (`-r win-x64 --self-contained`, the Windows installs, which have no .NET runtime) publishes the worker + self-contained for the same RID (~97 MB, its own runtime; not trimmed or single-file, because Roslyn compiles against the + runtime's reference assemblies on disk), and the launcher starts its apphost `ZB.MOM.WW.OtOpcUa.ScriptWorker.exe` + directly: `OutOfProcessScriptRunner.ResolveWorkerEntry` picks the apphost only when the worker's `runtimeconfig.json` lists + `includedFrameworks`. Gated on windev against a real `-r win-x64` publish (`OTOPCUA_SCRIPTWORKER_TEST_PATH` points the + worker suite at the published apphost). Not yet done (lmxopcua#780): the low-privilege worker account, pipe ACL, firewall + rule and PeCacheDir ACL (installer), the scripted-alarm seam and the per-seam batch submit (design §4.5). +- **docker-dev.** `docker-dev/docker-compose.script-runner.yml` turns `OutOfProcess` on for the central pair's + VirtualTag and Calculation seams. The 2026-11-10 live drill (runaway kill and quarantine, `kill -9` recovery, open circuit + with readiness still 200) is recorded in the design doc's rollout section. +- **Perf harness.** `ScriptRunnerPerfTests` (`Category=Perf`, skipped unless `OTOPCUA_SCRIPT_PERF=1`) measures InProcess + against OutOfProcess at K = 1/2/4 against the accepted 5,000 evals/s/node gate and the design §8.2 budgets. The numbers + are in the design doc's rollout section (§12.1). The gate passes; the host-CPU and RSS budgets miss (lmxopcua#789). +- **Compile threads.** A worker compiles on `min(8, max(1, CPUs/2))` dedicated threads, never on the thread pool, so a + burst of cold loads cannot starve its heartbeat or its pipe writer. The host load timeout still counts the time a load + spends in that queue (lmxopcua#790). Pinned by `tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests` (`Category=ScriptWorker`: real worker processes). 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 0548265d..763a521c 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 @@ -686,6 +686,12 @@ per-shard state, restarts in the last hour and the quarantine list. Quarantines §10 gauges and histograms, the degraded-but-ready `script-runner` health check (§14 #12), and the orphan sweep by launch marker (pid + start time + image, host gone). Still open: self-contained worker publish, installer (account, pipe ACL, firewall), docker-dev live drill, scripted-alarm seam, the §4.5 batch submit, the §8 perf harness. + - **Third P1 slice (lmxopcua#780, record in §12.1):** a self-contained worker publish for self-contained (Windows) + Host publishes, started through its apphost; the docker-dev live drill (`docker-dev/docker-compose.script-runner.yml`); + the §8 perf harness (`Category=Perf`, opt-in), which passes the accepted 5k evals/s/node gate; and two runner fixes + the harness found (a caller refused by its own finished run; heartbeat starvation under a compile burst). Still open: + installer (account, pipe ACL, firewall, PeCacheDir ACL), scripted-alarm seam, §4.5 batch submit, the §8.2 budget + misses (lmxopcua#789) and the load-timeout queue issue (lmxopcua#790). 3. **P2, shadow mode on docker-dev and QA.** - `Shadow` runs the **in-process** evaluation as the published result, and *also* submits to the worker. - It compares value, status class and failure kind per evaluation, and counts @@ -713,6 +719,160 @@ The PE cache directory can be deleted at any time. - `docs/Telemetry.md`; - the scadaproj index row, if the status-code decision changes the ScadaBridge-visible contract. +### 12.1 P1 record: self-contained publish, docker-dev live drill, §8 perf (2026-11-10) + +**Self-contained worker publish.** +- A `-r win-x64 --self-contained` Host publish now publishes the worker self-contained for the same RID into + `script-worker/`: 236 files, about 97 MB, with its own runtime. It is not trimmed and not single-file. +- The launcher starts the worker's apphost (`ZB.MOM.WW.OtOpcUa.ScriptWorker.exe`) directly. It does so only when the + worker's `runtimeconfig.json` lists `includedFrameworks`. Otherwise (framework-dependent) it keeps `dotnet exec `. +- A framework-dependent publish is unchanged: 51 files, no `includedFrameworks`, run through the muxer. +- Gate on windev: the Host was published win-x64 self-contained under `C:\build`, and the whole + `ScriptWorker.Tests` suite was run against the published apphost (`OTOPCUA_SCRIPTWORKER_TEST_PATH`). + - Result: **132/132**. + - It includes `A_published_self_contained_worker_runs_as_its_own_process`. That test checks that the worker + process's `MainModule` is the `.exe`, so no muxer is involved. + +**docker-dev live drill.** Image `otopcua-host:dev` was built from the branch at `f50b29ab` plus the self-contained +change. That build is from before the two runner fixes below. The drill ran with `docker-compose.script-runner.yml` on +`central-1`/`central-2`. + +| Step | Observed | +|---|---| +| Normal VT + Calc | Workers start on the first compiled evaluation (`dotnet exec /app/script-worker/…dll`). `okvt` (HR100+1) stays Good and tracks HR100. Writing HR5 = 21 on the fixture gives Calc `HR5x2` **42 Good** on both nodes, and the sibling VT `drillsib` (HR5×3) **63 Good**. | +| `while (true) { }` VT (1 s timer, T = 2 s) | Logged `exceeded its hard deadline (4000 ms); killing ScriptWorker[1]` twice, 5 s apart. After the second: `quarantined: "it exceeded its hard deadline and its worker was killed (2 time(s) in the last hour)…"`. Both nodes did the same. `okvt` and Calc share that shard and kept updating Good (26 Good samples, no Bad) because neither was in flight at the kills. `run_refused` then counts the quarantined trigger. | +| `kill -9` both workers on central-1 | A 1.5 s busy VT (`drillslow`) was in flight on shard 1. It published **BadResourceUnavailable** at 05:41:22.28, became a suspect and moved to isolation. It was Good again 30 ms later, re-evaluated in isolation. After HR5 = 22 it read 1022. Shards 0 and 1 restarted within about 250 ms. Isolation probation (20 clean runs) returned it to its shard. Calc gave 44 Good and the sibling 66 Good. | +| Circuit open (worker dll renamed, all workers killed) | `/health/ready` stayed **200**. The overall status went to `Degraded`, and `script-runner` showed `Degraded` → `Unavailable (circuit open)` after 2 min. Logged `Script runner circuit OPEN …` once. `otopcua_script_runner_state` = **2**, `worker_up` = 0 per shard. VTs and Calc (after an HR5 change) published **BadResourceUnavailable**. Driver tags (HR100) stayed Good, so OPC UA kept serving. | +| Recovery (dll restored) | The next backoff retry (cap 30 s) started the workers. Logged `circuit closed`. Calc **46** (HR5 = 23 × 2), sibling **69**, `drillslow` 1023, `okvt` Good, all without any input change. | +| Metrics on `:9000/metrics` | `otopcua_script_runner_state`, `worker_up`/`inflight`/`queue_depth`/`heap_bytes{shard}`, `worker_starts`/`exits{reason}`, `compile{cache}`, `ipc_roundtrip`/`eval_duration` histograms, `quarantined{reason}`, `isolation_suspects`. | + +On the wire, a Bad publish carries a null Value. This holds for every Bad status in this server, including +BadInternalError and BadOutOfRange. The seams keep the last value, but an OPC UA client does not see it. This was +noted for ScadaBridge#112. + +**Rig state afterwards.** +- Drill rows were deleted, HR5 was set back to 5, and the config was redeployed. The revision hash is `e221b179…`, + byte-identical to the pre-drill `gate-cleanup` deployment. +- `otopcua-host:dev` was re-tagged to the pre-drill image `24f9d7287ed2`. +- `central-1`/`central-2` were recreated from the base compose file: InProcess, no `Scripting__*` env. The four site + nodes, sql and traefik were never touched. +- The two central containers were recreated (twice), so their container-local secret stores and their PE cache dirs + under /tmp are gone. + +Two defects outside the runner were found and filed: +- lmxopcua#787: a disabled VirtualTag is still deployed and evaluated. +- lmxopcua#788: worker start failures log an Error with a stack trace on every retry. + +**§8 perf harness.** +- `ScriptRunnerPerfTests`, `Category=Perf`, opt-in with `OTOPCUA_SCRIPT_PERF=1`. +- The runners are driven directly: trivial one-input script, 2,000 keys over 50 sources. +- Phases: + - idle sequential; + - paced open loop at 5k/s and at 10k/s; + - 64-way closed loop. +- Host CPU is this process's CPU time as a share of one core, harness included. Under the same harness InProcess shows + 60–75 % at 5–10k/s, and that is the harness's own floor. + +macOS: + +**Script worker restart / RSS / kill latency (Unix Arm64, 14 logical CPUs, .NET 10.0.14, phase 10 s)** + +| Measure | Result | §8.2 budget | +|---|---:|---| +| 1000 scripts, empty cache, all first results (compile + write) | 1,633 ms | — | +| 1000 scripts, fresh runner on a warm cache, all first results | 217 ms | ≤ 2,000 ms | +| kill both shards → every script's next correct result | 482 ms | ≤ 2,000 ms | +| worker RSS after first eval (max of 2 shards) | 188 MB | ≤ 80 MB + scripts | +| worker RSS with 500 scripts loaded per shard (max) | 358 MB | — | +| kill latency after T+G (5 runs, ms) | 31 / 35 / 31 / 32 / 33 | ≤ 100 ms | + +**Script runner perf (Unix Arm64, 14 logical CPUs, .NET 10.0.14, phase 10 s)** + +| Runner | Phase | evals/s | p50 µs | p99 µs | host CPU | ok / not ok | +|---|---|---:|---:|---:|---:|---| +| InProcess | idle, sequential | 189,154 | 4 | 8 | 446 % | 5,000 / 0 | +| InProcess | paced 5,000/s | 4,998 | 32 | 223 | 60 % | 49,999 / 0 | +| InProcess | paced 10,000/s | 9,991 | 41 | 364 | 74 % | 99,986 / 0 | +| InProcess | closed loop ×64 | 789,533 | 4 | 15 | 409 % | 7,896,214 / 0 | +| OutOfProcess K=1 | idle, sequential | 21,641 | 45 | 64 | 264 % | 5,000 / 0 | +| OutOfProcess K=1 | paced 5,000/s | 4,999 | 149 | 860 | 108 % | 49,998 / 0 | +| OutOfProcess K=1 | paced 10,000/s | 9,995 | 205 | 1,763 | 159 % | 99,989 / 0 | +| OutOfProcess K=1 | closed loop ×64 | 206,862 | 258 | 1,368 | 526 % | 2,068,749 / 0 | +| OutOfProcess K=2 | idle, sequential | 22,642 | 41 | 70 | 267 % | 5,000 / 0 | +| OutOfProcess K=2 | paced 5,000/s | 4,999 | 182 | 722 | 125 % | 49,994 / 0 | +| OutOfProcess K=2 | paced 10,000/s | 9,996 | 232 | 720 | 237 % | 99,998 / 0 | +| OutOfProcess K=2 | closed loop ×64 | 336,519 | 150 | 993 | 544 % | 3,365,226 / 0 | +| OutOfProcess K=4 | idle, sequential | 18,461 | 50 | 97 | 303 % | 5,000 / 0 | +| OutOfProcess K=4 | paced 5,000/s | 4,999 | 201 | 455 | 197 % | 49,997 / 0 | +| OutOfProcess K=4 | paced 10,000/s | 9,997 | 126 | 732 | 176 % | 99,989 / 0 | +| OutOfProcess K=4 | closed loop ×64 | 297,094 | 178 | 1,015 | 507 % | 2,970,998 / 0 | + +windev (Windows VM; framework-dependent worker built beside the tests): + +**Script runner perf (Win32NT X64, 36 logical CPUs, .NET 10.0.8, phase 10 s)** + +| Runner | Phase | evals/s | p50 µs | p99 µs | host CPU | ok / not ok | +|---|---|---:|---:|---:|---:|---| +| InProcess | idle, sequential | 5,876 | 142 | 253 | 204 % | 5,000 / 0 | +| InProcess | paced 5,000/s | 4,997 | 136 | 335 | 55 % | 49,996 / 0 | +| InProcess | paced 10,000/s | 9,989 | 105 | 274 | 6 % | 99,984 / 0 | +| InProcess | closed loop ×64 | 177,782 | 26 | 10,062 | 543 % | 1,778,824 / 0 | +| OutOfProcess K=1 | idle, sequential | 1,276 | 750 | 1,263 | 74 % | 5,000 / 0 | +| OutOfProcess K=1 | paced 5,000/s | 4,997 | 1,073 | 3,028 | 68 % | 49,990 / 0 | +| OutOfProcess K=1 | paced 10,000/s | 9,992 | 1,139 | 2,840 | 102 % | 99,999 / 0 | +| OutOfProcess K=1 | closed loop ×64 | 38,464 | 1,514 | 6,547 | 350 % | 384,727 / 0 | +| OutOfProcess K=2 | idle, sequential | 1,207 | 795 | 1,376 | 80 % | 5,000 / 0 | +| OutOfProcess K=2 | paced 5,000/s | 4,998 | 956 | 1,856 | 111 % | 49,997 / 0 | +| OutOfProcess K=2 | paced 10,000/s | 9,962 | 942 | 1,916 | 153 % | 99,992 / 0 | +| OutOfProcess K=2 | closed loop ×64 | 51,241 | 1,129 | 5,894 | 594 % | 512,504 / 0 | +| OutOfProcess K=4 | idle, sequential | 1,163 | 828 | 1,366 | 61 % | 5,000 / 0 | +| OutOfProcess K=4 | paced 5,000/s | 4,997 | 804 | 1,472 | 172 % | 49,991 / 0 | +| OutOfProcess K=4 | paced 10,000/s | 9,992 | 757 | 1,591 | 233 % | 99,992 / 0 | +| OutOfProcess K=4 | closed loop ×64 | 69,503 | 774 | 6,321 | 1,051 % | 695,094 / 0 | + + +**Script worker restart / RSS / kill latency (Win32NT X64, 36 logical CPUs, .NET 10.0.8, phase 10 s)** + +| Measure | Result | §8.2 budget | +|---|---:|---| +| 1000 scripts, empty cache, all first results (compile + write) | 11,625 ms | — | +| 1000 scripts, fresh runner on a warm cache, all first results | 1,715 ms | ≤ 2,000 ms | +| kill both shards → every script's next correct result | 2,028 ms | ≤ 2,000 ms | +| worker RSS after first eval (max of 2 shards) | 158 MB | ≤ 80 MB + scripts | +| worker RSS with 500 scripts loaded per shard (max) | 232 MB | — | +| kill latency after T+G (5 runs, ms) | 257 / 210 / 200 / 217 / 209 | ≤ 100 ms | + +Verdict against §8.2 and the accepted gate: +- **Accepted gate (≥ 5,000 evals/s/node at K = 2): PASS** on both hosts (macOS 336k/s, windev 51k/s closed loop), with every result correct. +- Throughput ≥ 10k/s: PASS. +- Idle p50 ≤ 150 µs: PASS on macOS (41 µs), MISS on windev (795 µs; InProcess there is already 142 µs). +- p99 ≤ 2 ms at 10k/s: PASS (macOS 0.7 ms, windev 1.9 ms). +- Warm-cache restart of 1,000 scripts ≤ 2 s: PASS (0.2 s / 1.7 s). +- Kill latency ≤ 100 ms: PASS on macOS (about 32 ms), MISS on windev (about 210 ms). +- **Host CPU ≤ 25 % of a core at 10k/s: MISS.** windev runs K = 2 at about 153 %. On macOS, K = 2 runs about 240 % against InProcess's 74 % under the same + harness. A sequential probe measured 156 µs of host CPU per evaluation, and 63 µs with + `DOTNET_ThreadPool_UnfairSemaphoreSpinLimit=0`. Thread-pool spinning is therefore most of it. +- **Worker idle RSS ≤ 80 MB: MISS.** It is about 190 MB on macOS and 158 MB on windev, because Roslyn is resident since compiles run in the worker. + +Both misses → lmxopcua#789 (the §4.5 batching and per-eval allocation work). + +**Two runner defects found by the harness and fixed in this slice.** +1. **Refused own run.** The single-flight slot was freed by a continuation that was not ordered against the caller's + await. A caller that awaited one run and then started the next was sometimes refused with + `previous evaluation still running`: 32 of 200 back-to-back runs, and about 80 % in the perf idle phase. The VT and + Calc seams publish that as Bad. The slot is now freed before the caller resumes, idempotently. + - Pinned by `A_caller_that_awaited_its_run_is_never_refused_by_it` (1,000 runs). + - Mutation red. +2. **Heartbeat starvation under a compile burst.** Each load was compiled synchronously on its own thread-pool work item. + On windev, 500 cold loads starved the heartbeat timer and the pipe writer. The host killed the shard + (`KilledHeartbeat`), and all 500 keys became suspects. Compiles now run on `min(8, max(1, CPUs/2))` dedicated + `ScriptWorker.Compile` threads. + - Pinned by `A_burst_of_cold_compiles_does_not_starve_the_heartbeat` (1,500 cold scripts, 50 ms heartbeat). + - Red on macOS with the thread-pool version. Green 3/3 on macOS and windev; on windev 1,500 cold compiles take + about 18 s. + +The host load timeout still counts the time a load waits behind other compiles → lmxopcua#790. + --- ## 13. Test plan diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess/OutOfProcessScriptRunner.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess/OutOfProcessScriptRunner.cs index 3dcce7f1..776a619e 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess/OutOfProcessScriptRunner.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess/OutOfProcessScriptRunner.cs @@ -278,11 +278,61 @@ public sealed class OutOfProcessScriptRunner : IScriptRunner, IAsyncDisposable, /// The default worker path, or the configured one. /// The worker options. /// The absolute worker path. + /// + /// With no , the worker is looked up in script-worker/ + /// under the host's base directory by : a self-contained worker (the Windows + /// installs, which have no .NET runtime) is started through its apphost, a framework-dependent one (docker-dev) + /// through the dotnet muxer. + /// public static string ResolveWorkerPath(ScriptWorkerOptions worker) => string.IsNullOrWhiteSpace(worker.ExecutablePath) - ? Path.Combine(AppContext.BaseDirectory, WorkerFolderName, WorkerAssemblyFileName) + ? ResolveWorkerEntry(Path.Combine(AppContext.BaseDirectory, WorkerFolderName)) : Path.GetFullPath(worker.ExecutablePath); + /// The worker's apphost file name on this OS. + public static string WorkerAppHostFileName + => OperatingSystem.IsWindows() ? "ZB.MOM.WW.OtOpcUa.ScriptWorker.exe" : "ZB.MOM.WW.OtOpcUa.ScriptWorker"; + + /// + /// The entry a worker folder should be launched through: its apphost when the folder holds a + /// self-contained worker, otherwise the entry assembly (run through the dotnet muxer). + /// + /// The worker folder. + /// The absolute path of the apphost or of the entry assembly (which may not exist). + /// + /// A framework-dependent build also emits an apphost, but that apphost needs an installed runtime the + /// self-contained Windows hosts do not have, and the muxer path is what docker-dev and the tests have always + /// used, so the apphost is chosen only for a self-contained worker. Self-contained is read from the worker's + /// runtimeconfig.json: the SDK writes includedFrameworks for a self-contained app and + /// framework/frameworks for a framework-dependent one. + /// + public static string ResolveWorkerEntry(string folder) + { + var full = Path.GetFullPath(folder); + var appHost = Path.Combine(full, WorkerAppHostFileName); + return File.Exists(appHost) && IsSelfContainedWorker(full) ? appHost : Path.Combine(full, WorkerAssemblyFileName); + } + + /// Whether the worker in was published self-contained. + /// The worker folder. + /// True when its runtimeconfig.json lists includedFrameworks. + public static bool IsSelfContainedWorker(string folder) + { + var config = Path.Combine(folder, Path.GetFileNameWithoutExtension(WorkerAssemblyFileName) + ".runtimeconfig.json"); + if (!File.Exists(config)) return false; + try + { + using var doc = System.Text.Json.JsonDocument.Parse(File.ReadAllText(config), + new System.Text.Json.JsonDocumentOptions { CommentHandling = System.Text.Json.JsonCommentHandling.Skip, AllowTrailingCommas = true }); + return doc.RootElement.TryGetProperty("runtimeOptions", out var options) + && options.TryGetProperty("includedFrameworks", out _); + } + catch (Exception ex) when (ex is System.Text.Json.JsonException or IOException or UnauthorizedAccessException) + { + return false; + } + } + /// public async Task RunAsync(ScriptInvocation invocation, CancellationToken ct = default) { @@ -369,17 +419,26 @@ public sealed class OutOfProcessScriptRunner : IScriptRunner, IAsyncDisposable, // death, attribution (strike, quarantine, suspect) has already run when this continuation fires. handedOff = true; var heldGate = gate; - _ = pending.Completion.ContinueWith(_ => + var released = 0; + void ReleaseSlot() { + if (Interlocked.Exchange(ref released, 1) != 0) return; SlotReleasingForTest?.Invoke(key); Interlocked.Exchange(ref state.InFlight, 0); heldGate?.Release(); - }, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); + } + _ = pending.Completion.ContinueWith(_ => ReleaseSlot(), + CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); EvalResult? result; try { result = await pending.Completion.WaitAsync(invocation.Timeout, ct).ConfigureAwait(false); + // The worker has answered (or died, with attribution already run): free the slot HERE, before this + // caller resumes. The continuation above is not ordered against this await, so relying on it alone + // let a caller that awaited one run and then started the next see "previous evaluation still running" + // (found by the §8 perf harness: 32 of 200 sequential same-key runs refused). Idempotent. + ReleaseSlot(); } catch (TimeoutException) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/WorkerHost.cs b/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/WorkerHost.cs index 8efc0496..31d3734b 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/WorkerHost.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/WorkerHost.cs @@ -38,6 +38,17 @@ internal sealed class WorkerHost private readonly ConcurrentDictionary _scripts = new(StringComparer.Ordinal); private readonly ConcurrentDictionary _running = new(); private readonly BlockingCollection _queue = new(new ConcurrentQueue()); + + /// + /// Loads waiting for a compile thread. Compiles are long, synchronous and CPU-bound, so they run on + /// dedicated threads, never on the thread pool: a burst of cold loads (a node start + /// or a deploy with an empty PE cache) used to put one blocking pool item per load in front of the heartbeat + /// timer and the pipe writer, and the host killed the worker for silence (found on windev, lmxopcua#780 §8). + /// + private readonly BlockingCollection _loads = new(new ConcurrentQueue()); + + /// Dedicated compile threads: half the processors, at least 1, at most 8. + internal static int CompileThreads => Math.Clamp(Environment.ProcessorCount / 2, 1, 8); private readonly ForwardingLogSink _logSink; private readonly ILogger _scriptLogger; private int _maxFrameBytes = ScriptWorkerFrameCodec.DefaultMaxFrameBytes; @@ -116,6 +127,10 @@ internal sealed class WorkerHost { new Thread(EvalThreadLoop) { IsBackground = true, Name = $"ScriptWorker.Eval{i}" }.Start(); } + for (var i = 0; i < CompileThreads; i++) + { + new Thread(CompileThreadLoop) { IsBackground = true, Name = $"ScriptWorker.Compile{i}" }.Start(); + } new Thread(WatchdogLoop) { IsBackground = true, Name = "ScriptWorker.Watchdog" }.Start(); _ = Task.Run(HeartbeatLoopAsync); _ = Task.Run(LogFlushLoopAsync); @@ -146,9 +161,9 @@ internal sealed class WorkerHost { case Envelope.BodyOneofCase.Load: { - // Compile off the reader, so evaluations for already-loaded keys keep flowing during a load. - var load = frame.Load; - _ = Task.Run(() => Load(load)); + // Compile off the reader, so evaluations for already-loaded keys keep flowing during a load, and + // off the thread pool, so the heartbeat and the writer keep flowing during a burst of them. + _loads.Add(frame.Load); break; } case Envelope.BodyOneofCase.Unload: @@ -179,6 +194,11 @@ internal sealed class WorkerHost } } + private void CompileThreadLoop() + { + foreach (var load in _loads.GetConsumingEnumerable()) Load(load); + } + private void Load(LoadScripts load) { var result = new LoadResult { LoadId = load.LoadId }; diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/build/ScriptWorker.Deploy.targets b/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/build/ScriptWorker.Deploy.targets index 853fc5e9..4ded486a 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/build/ScriptWorker.Deploy.targets +++ b/src/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker/build/ScriptWorker.Deploy.targets @@ -5,9 +5,13 @@ the worker test project. The worker is its own app (own deps.json / runtimeconfig.json), so it lives in its own folder rather than beside the host's assemblies. - Publish note: the copy is the worker's framework-dependent BUILD output, run through the dotnet muxer. That suits the - docker-dev image (aspnet:10.0 runtime). A self-contained host publish (the Windows deploys) needs a self-contained - worker publish too; that is part of the installer work tracked on lmxopcua#780. + Publish: a framework-dependent host publish (docker-dev, aspnet:10.0 runtime) copies the worker's + framework-dependent BUILD output, which the launcher runs through the dotnet muxer. A self-contained host publish + (a self-contained `-r win-x64` publish: the Windows installs, which have no .NET runtime) instead PUBLISHES the worker + self-contained for the same RuntimeIdentifier into $(PublishDir)script-worker/, and the launcher starts its + apphost directly (OutOfProcessScriptRunner.ResolveWorkerEntry reads runtimeconfig.json `includedFrameworks`). + The worker then carries its own copy of the runtime (~70 MB); it is not trimmed or single-file, because Roslyn + compiles against the runtime's reference set on disk. --> <_OtScriptWorkerProject>$(MSBuildThisFileDirectory)../ZB.MOM.WW.OtOpcUa.ScriptWorker.csproj @@ -18,7 +22,12 @@ - + + <_OtScriptWorkerResolveProps>Configuration=$(Configuration) + + <_OtScriptWorkerResolveProps Condition="'$(RuntimeIdentifier)' != ''">$(_OtScriptWorkerResolveProps);RuntimeIdentifier=$(RuntimeIdentifier) + + @@ -35,9 +44,23 @@ SkipUnchangedFiles="true" /> - + + + + + + + <_OtScriptWorkerPublishDir>$([System.IO.Path]::GetFullPath('$(PublishDir)script-worker/')) + + + diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs new file mode 100644 index 00000000..cdc3ce6d --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ScriptRunnerPerfTests.cs @@ -0,0 +1,337 @@ +using System.Diagnostics; +using System.Text; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; +using ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess; + +namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests; + +/// +/// lmxopcua#780 design §8 perf harness (§13 "Performance"): a Stopwatch-based measurement of the in-process and +/// out-of-process runners against the accepted gate of 5,000 compiled evaluations per second per node and the +/// §8.2 budgets. Opt-in and never part of a default run: every case skips unless OTOPCUA_SCRIPT_PERF=1. +/// +/// +/// Run: OTOPCUA_SCRIPT_PERF=1 dotnet test tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests -c Release +/// --filter Category=Perf --logger "console;verbosity=detailed". OTOPCUA_SCRIPT_PERF_SECONDS sets each +/// load phase's length (default 10) and OTOPCUA_SCRIPT_PERF_OUT appends the report to a file. +/// What the numbers are: the runners are driven directly (no OPC UA, no actors), so they are the runner's own +/// cost — the "added latency" the design budgets. Host CPU is this test process's +/// over the phase, as a percentage of one core; for the in-process runner +/// that includes the scripts themselves, for the out-of-process one it is IPC + bookkeeping only (the scripts run in +/// the worker). The script is the trivial one-input script the budgets are written for. +/// Only the accepted gate (≥ 5,000 evals/s at K=2) is asserted; the other §8.2 budgets are reported +/// PASS/MISS so a run on a slow box still produces its whole table. +/// +[Collection(ScriptWorkerCollection.Name)] +[Trait("Category", "Perf")] +public sealed class ScriptRunnerPerfTests +{ + private const string OptInVariable = "OTOPCUA_SCRIPT_PERF"; + private const int AcceptedGateEvalsPerSecond = 5_000; + private const int Keys = 2_000; + private const int DistinctSources = 50; + + private static CancellationToken Ct => TestContext.Current.CancellationToken; + + /// The runners' own log (worker starts, exits and their reasons), quoted when a phase fails. + private readonly CapturingSink _runnerLog = new(); + + private string RunnerLog() => string.Join(Environment.NewLine, + _runnerLog.Events.Where(e => e.Level >= Serilog.Events.LogEventLevel.Warning).TakeLast(8).Select(e => e.RenderMessage())); + + private static TimeSpan Phase => TimeSpan.FromSeconds( + int.TryParse(Environment.GetEnvironmentVariable("OTOPCUA_SCRIPT_PERF_SECONDS"), out var s) && s > 0 ? s : 10); + + private static void RequireOptIn() + { + if (Environment.GetEnvironmentVariable(OptInVariable) != "1") + Assert.Skip($"perf harness: set {OptInVariable}=1 to run (design §8; not part of a default run)"); + } + + private static string Source(int i) => $"return (int)ctx.GetTag(\"x\").Value + {i % DistinctSources};"; + + private static ScriptInvocation Invocation(int key, int x) + => new("perf-" + key, ScriptContextKind.VirtualTag, Source(key), Scripts.Input("x", x), TimeSpan.FromSeconds(2)); + + private static void Report(StringBuilder report) + { + var text = report.ToString(); + TestContext.Current.TestOutputHelper?.WriteLine(text); + if (Environment.GetEnvironmentVariable("OTOPCUA_SCRIPT_PERF_OUT") is { Length: > 0 } path) + File.AppendAllText(path, text + Environment.NewLine); + } + + private static string Env() + => $"{Environment.OSVersion.Platform} {System.Runtime.InteropServices.RuntimeInformation.OSArchitecture}, " + + $"{Environment.ProcessorCount} logical CPUs, .NET {Environment.Version}, phase {Phase.TotalSeconds:F0} s"; + + private sealed record PhaseResult(double EvalsPerSecond, double P50Us, double P99Us, double HostCpuPercent, + long Ok, long NotOk, string? FirstFailure); + + private static double Percentile(List sorted, double p) + => sorted.Count == 0 ? double.NaN : sorted[Math.Min(sorted.Count - 1, (int)Math.Ceiling(p * sorted.Count) - 1)]; + + private async Task WarmAsync(IScriptRunner runner) + { + // Compile every distinct source and touch every key once, so the phases measure steady state. + var tasks = Enumerable.Range(0, Keys).Select(k => runner.RunAsync(Invocation(k, 1), Ct)).ToArray(); + var outcomes = await Task.WhenAll(tasks); + foreach (var o in outcomes) o.Status.ShouldBe(ScriptRunStatus.Ok, $"{o.Reason}{Environment.NewLine}{RunnerLog()}"); + } + + /// Sequential evaluations of one key on an idle runner: the per-call added latency. + private static async Task IdleLatencyAsync(IScriptRunner runner, int count = 5_000) + { + var samples = new List(count); + var cpu0 = Process.GetCurrentProcess().TotalProcessorTime; + var wall = Stopwatch.StartNew(); + long ok = 0; + string? firstFailure = null; + for (var i = 0; i < count; i++) + { + var t0 = Stopwatch.GetTimestamp(); + var o = await runner.RunAsync(Invocation(7, i), Ct); + samples.Add(Stopwatch.GetElapsedTime(t0).TotalMicroseconds); + if (o.Status == ScriptRunStatus.Ok && Equals(o.Value, i + 7)) ok++; + else firstFailure ??= $"#{i} {o.Status}: {o.Reason} (value {o.Value})"; + } + var cpu = (Process.GetCurrentProcess().TotalProcessorTime - cpu0).TotalMilliseconds / wall.Elapsed.TotalMilliseconds * 100; + samples.Sort(); + return new PhaseResult(count / wall.Elapsed.TotalSeconds, Percentile(samples, 0.50), Percentile(samples, 0.99), cpu, ok, count - ok, firstFailure); + } + + /// + /// Closed loop: submitters, each cycling over its own slice of the keys (so + /// single flight per key never serialises them), for one phase. Measures the maximum sustainable rate. + /// + private static async Task ClosedLoopAsync(IScriptRunner runner, int concurrency) + { + var deadline = Stopwatch.GetTimestamp() + (long)(Phase.TotalSeconds * Stopwatch.Frequency); + var perLoop = new List[concurrency]; + long ok = 0, notOk = 0; + string? firstFailure = null; + var cpu0 = Process.GetCurrentProcess().TotalProcessorTime; + var wall = Stopwatch.StartNew(); + await Task.WhenAll(Enumerable.Range(0, concurrency).Select(loop => Task.Run(async () => + { + var samples = perLoop[loop] = new List(200_000); + var keysPerLoop = Keys / concurrency; + var n = 0; + while (Stopwatch.GetTimestamp() < deadline) + { + var key = loop * keysPerLoop + n % keysPerLoop; + var t0 = Stopwatch.GetTimestamp(); + var o = await runner.RunAsync(Invocation(key, n), Ct); + samples.Add(Stopwatch.GetElapsedTime(t0).TotalMicroseconds); + if (o.Status == ScriptRunStatus.Ok && Equals(o.Value, n + key % DistinctSources)) Interlocked.Increment(ref ok); + else + { + Interlocked.Increment(ref notOk); + Interlocked.CompareExchange(ref firstFailure, $"{o.Status}: {o.Reason} (value {o.Value})", null); + } + n++; + } + }, Ct))); + var elapsed = wall.Elapsed; + var cpu = (Process.GetCurrentProcess().TotalProcessorTime - cpu0).TotalMilliseconds / elapsed.TotalMilliseconds * 100; + var all = perLoop.SelectMany(s => s).ToList(); + all.Sort(); + return new PhaseResult((ok + notOk) / elapsed.TotalSeconds, Percentile(all, 0.50), Percentile(all, 0.99), cpu, ok, notOk, firstFailure); + } + + /// + /// Open loop at a fixed offered rate: every millisecond tick issues the evaluations due by then (round robin over + /// 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) + { + var samples = new List(ratePerSecond * (int)Phase.TotalSeconds + 1024); + var gate = new object(); + var inFlight = new bool[Keys]; + long ok = 0, notOk = 0, issued = 0; + string? firstFailure = null; + var pending = new List(ratePerSecond * (int)Phase.TotalSeconds + 1024); + var cpu0 = Process.GetCurrentProcess().TotalProcessorTime; + var wall = Stopwatch.StartNew(); + var next = 0; + while (wall.Elapsed < Phase) + { + var due = (long)(wall.Elapsed.TotalSeconds * ratePerSecond); + while (issued < due) + { + var key = next++ % Keys; + if (Volatile.Read(ref inFlight[key])) continue; + Volatile.Write(ref inFlight[key], true); + var x = (int)issued++; + var t0 = Stopwatch.GetTimestamp(); + pending.Add(runner.RunAsync(Invocation(key, x), Ct).ContinueWith(t => + { + var us = Stopwatch.GetElapsedTime(t0).TotalMicroseconds; + Volatile.Write(ref inFlight[key], false); + var o = t.Result; + lock (gate) samples.Add(us); + if (o.Status == ScriptRunStatus.Ok && Equals(o.Value, x + key % DistinctSources)) Interlocked.Increment(ref ok); + else + { + Interlocked.Increment(ref notOk); + 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) + => $"| {runner} | {phase} | {r.EvalsPerSecond,9:N0} | {r.P50Us,8:N0} | {r.P99Us,9:N0} | {r.HostCpuPercent,6:N0} % | {r.Ok:N0} / {r.NotOk:N0} |" + + (r.FirstFailure is null ? "" : $" first failure: {r.FirstFailure}"); + + /// + /// Throughput and latency, InProcess vs OutOfProcess at K = 1 / 2 / 4. Asserts the accepted gate: the + /// out-of-process runner at K = 2 sustains ≥ 5,000 trivial evals/s with every result correct. + /// + [Fact] + public async Task Throughput_and_latency_against_the_accepted_gate() + { + RequireOptIn(); + var report = new StringBuilder() + .AppendLine($"### Script runner perf ({Env()})") + .AppendLine() + .AppendLine("| Runner | Phase | evals/s | p50 µs | p99 µs | host CPU | ok / not ok |") + .AppendLine("|---|---|---:|---:|---:|---:|---|"); + PhaseResult? k2Closed = null; + + var configs = new (string Name, Func Create)[] + { + ("InProcess", () => new InProcessScriptRunner(new ScriptingOptions())), + ("OutOfProcess K=1", () => Scripts.Runner(PerfOptions(1), _runnerLog.CreateLogger())), + ("OutOfProcess K=2", () => Scripts.Runner(PerfOptions(2), _runnerLog.CreateLogger())), + ("OutOfProcess K=4", () => Scripts.Runner(PerfOptions(4), _runnerLog.CreateLogger())), + }; + foreach (var (name, create) in configs) + { + var runner = create(); + try + { + await WarmAsync(runner); + report.AppendLine(Row(name, "idle, sequential", await IdleLatencyAsync(runner))); + report.AppendLine(Row(name, "paced 5,000/s", await PacedAsync(runner, 5_000))); + report.AppendLine(Row(name, "paced 10,000/s", await PacedAsync(runner, 10_000))); + var closed = await ClosedLoopAsync(runner, concurrency: 64); + report.AppendLine(Row(name, "closed loop ×64", closed)); + if (name == "OutOfProcess K=2") k2Closed = closed; + } + finally + { + switch (runner) + { + case IAsyncDisposable a: await a.DisposeAsync(); break; + case IDisposable d: d.Dispose(); break; + } + } + } + + 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 ≤ 25 % of one core at 10k/s. Accepted gate (owner, §14): ≥ 5,000 evals/s/node."); + Report(report); + + k2Closed.ShouldNotBeNull(); + k2Closed.NotOk.ShouldBe(0, k2Closed.FirstFailure); + k2Closed.EvalsPerSecond.ShouldBeGreaterThanOrEqualTo(AcceptedGateEvalsPerSecond, "the accepted 5k evals/s/node gate at K=2"); + } + + private static ScriptingOptions PerfOptions(int shards, string? peCacheDir = null) + { + var options = Scripts.Options(shards: shards, hardGrace: TimeSpan.FromSeconds(2), peCacheDir: peCacheDir, + heapLimit: 512L * 1024 * 1024); + return options; + } + + /// + /// §8.2 "Shard restart → first result, 1,000 cached scripts ≤ 2 s", "Worker idle RSS ≤ 80 MB + scripts" and + /// "Kill latency after T+G ≤ 100 ms". Report-only. + /// + [Fact] + public async Task Restart_rss_and_kill_latency() + { + RequireOptIn(); + const int scripts = 1_000; + using var dir = new Scripts.TempDir(); + var cacheDir = Path.Combine(dir.Path, "pe-cache"); + static string Distinct(int i) => $"return (int)ctx.GetTag(\"x\").Value * {i} + 1;"; + ScriptInvocation Inv(int i) => new("restart-" + i, ScriptContextKind.VirtualTag, Distinct(i), Scripts.Input("x", 2), TimeSpan.FromSeconds(30)); + + async Task AllFirstResults(OutOfProcessScriptRunner runner) + { + var sw = Stopwatch.StartNew(); + var outcomes = await Task.WhenAll(Enumerable.Range(0, scripts).Select(i => runner.RunAsync(Inv(i), Ct))); + var elapsed = sw.Elapsed; + for (var i = 0; i < scripts; i++) + { + outcomes[i].Status.ShouldBe(ScriptRunStatus.Ok, $"{outcomes[i].Reason}{Environment.NewLine}{RunnerLog()}"); + outcomes[i].Value.ShouldBe(2 * i + 1); + } + return elapsed; + } + + var report = new StringBuilder().AppendLine($"### Script worker restart / RSS / kill latency ({Env()})").AppendLine(); + TimeSpan cold, warmFresh, killRestart; + long rssIdle, rssLoaded; + await using (var runner = Scripts.Runner(PerfOptions(2, cacheDir), _runnerLog.CreateLogger())) + { + (await runner.RunAsync(Inv(0), Ct)).Status.ShouldBe(ScriptRunStatus.Ok); + await Task.Delay(500, Ct); + rssIdle = runner.Shards.Max(s => s.Current is { } c ? Process.GetProcessById(c.Pid).WorkingSet64 : 0); + cold = await AllFirstResults(runner); + rssLoaded = runner.Shards.Max(s => s.Current is { } c ? Process.GetProcessById(c.Pid).WorkingSet64 : 0); + } + await using (var runner = Scripts.Runner(PerfOptions(2, cacheDir), _runnerLog.CreateLogger())) + { + warmFresh = await AllFirstResults(runner); + // A kill of both shard workers: time from the kill to every script's next correct result (includes the + // 250 ms first restart backoff and the cache load). + foreach (var shard in runner.Shards) Process.GetProcessById(shard.Current!.Pid).Kill(); + var sw = Stopwatch.StartNew(); + await Scripts.Eventually(() => runner.Shards.All(s => s.Current is null || s.Current.Exited.IsCompleted) ? true : false, + TimeSpan.FromSeconds(5), "both kills observed"); + await Scripts.Eventually(() => runner.State == ScriptRunnerState.Ready, TimeSpan.FromSeconds(30), "both shards back"); + killRestart = sw.Elapsed + await AllFirstResults(runner); + } + + // Kill latency: soft T = 200 ms, G = 1 s; time from the soft-timeout answer to the worker's exit. + var killLatencies = new List(); + await using (var runner = Scripts.Runner(Scripts.Options(hardGrace: TimeSpan.FromSeconds(1), quarantineAfterKills: 100))) + { + for (var i = 0; i < 5; i++) + { + (await runner.RunAsync(Scripts.Vt("warm", "return 1;"), Ct)).Status.ShouldBe(ScriptRunStatus.Ok); + var worker = runner.Shards[0].Current!; + var sw = Stopwatch.StartNew(); + var outcome = await runner.RunAsync(Scripts.Vt("runaway-" + i, "while (true) { }", TimeSpan.FromMilliseconds(200)), Ct); + outcome.Status.ShouldBe(ScriptRunStatus.Failed); + await worker.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct); + killLatencies.Add((sw.Elapsed - TimeSpan.FromMilliseconds(1200)).TotalMilliseconds); + } + } + + report.AppendLine("| Measure | Result | §8.2 budget |") + .AppendLine("|---|---:|---|") + .AppendLine($"| {scripts} scripts, empty cache, all first results (compile + write) | {cold.TotalMilliseconds:N0} ms | — |") + .AppendLine($"| {scripts} scripts, fresh runner on a warm cache, all first results | {warmFresh.TotalMilliseconds:N0} ms | ≤ 2,000 ms |") + .AppendLine($"| kill both shards → every script's next correct result | {killRestart.TotalMilliseconds:N0} ms | ≤ 2,000 ms |") + .AppendLine($"| worker RSS after first eval (max of 2 shards) | {rssIdle / 1048576.0:N0} MB | ≤ 80 MB + scripts |") + .AppendLine($"| worker RSS with {scripts / 2} scripts loaded per shard (max) | {rssLoaded / 1048576.0:N0} MB | — |") + .AppendLine($"| kill latency after T+G (5 runs, ms) | {string.Join(" / ", killLatencies.Select(l => l.ToString("N0")))} | ≤ 100 ms |"); + Report(report); + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs index f2c5f047..fbfbd6e6 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs @@ -100,6 +100,55 @@ public sealed class SupervisionTests attributed.ShouldBeTrue("the runner's verdict is recorded before the callback returns"); } + /// + /// A burst of cold compiles must not starve the worker's heartbeat. Found on windev by the §8 perf harness: 500 + /// loads at once, each compiled synchronously on its own thread-pool work item, queued the heartbeat timer and + /// the pipe writer behind them; the host saw no frame for 3 s, killed the shard (KilledHeartbeat) and made all 500 + /// keys suspects. Here a 100 ms heartbeat (kill after 300 ms of silence) and 400 distinct cold scripts at once: + /// every script answers and the shard's worker is the one that started. Mutation check: compile on the thread + /// pool again and the worker is killed for silence. + /// + [Fact] + public async Task A_burst_of_cold_compiles_does_not_starve_the_heartbeat() + { + var sink = new CapturingSink(); + await using var runner = new OutOfProcessScriptRunner(Scripts.Options(), sink.CreateLogger(), null, + heartbeatInterval: TimeSpan.FromMilliseconds(50), loadTimeout: TimeSpan.FromSeconds(120)); + (await runner.RunAsync(Scripts.Vt("first", Healthy), Ct)).Value.ShouldBe(7); + var worker = runner.Shards[0].Current.ShouldNotBeNull(); + + const int count = 1500; + var outcomes = await Task.WhenAll(Enumerable.Range(0, count).Select(i => runner.RunAsync( + Scripts.Vt("burst-" + i, $"return (int)ctx.GetTag(\"x\").Value * {i} + 1;", TimeSpan.FromSeconds(60), + Scripts.Input("x", 2)), Ct))); + + var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)).Take(5)); + for (var i = 0; i < count; i++) outcomes[i].Value.ShouldBe(2 * i + 1, $"{outcomes[i].Status} {outcomes[i].Reason}\n{log}"); + runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, log); + worker.Exited.IsCompleted.ShouldBeFalse(log); + } + + /// + /// Single flight must not refuse a caller's NEXT run because of the run it already awaited: the slot is freed + /// before the awaiting caller resumes. The §8 perf harness found the slot freed by a continuation unordered + /// against the caller's await, so 32 of 200 back-to-back runs of one key came back "previous evaluation still + /// running" — which the VirtualTag and Calculation seams publish as Bad. Mutation check: drop the inline + /// release after the await and this goes red. + /// + [Fact] + public async Task A_caller_that_awaited_its_run_is_never_refused_by_it() + { + await using var runner = Scripts.Runner(Scripts.Options()); + var refused = new List(); + for (var i = 0; i < 1_000; i++) + { + var outcome = await runner.RunAsync( + Scripts.Vt("seq", "return (int)ctx.GetTag(\"x\").Value + 7;", inputs: Scripts.Input("x", i)), Ct); + if (outcome.Status != ScriptRunStatus.Ok || !Equals(outcome.Value, i + 7)) refused.Add($"#{i}: {outcome.Reason}"); + } + refused.ShouldBeEmpty(); + } + /// /// The race itself, end to end: with QuarantineAfterKills = 1, the moment the killed script's single-flight slot is /// released the quarantine is already in place — so no trigger can re-run it in the restart gap, and the next diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/TestSupport.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/TestSupport.cs index 6bf8086e..038c8c0f 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/TestSupport.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/TestSupport.cs @@ -35,6 +35,16 @@ internal static class Scripts IReadOnlyDictionary? inputs = null, ILogger? logger = null) => new(key, ScriptContextKind.VirtualTag, source, inputs ?? NoInputs, timeout ?? TimeSpan.FromSeconds(5), logger); + /// + /// Name of the environment variable that points the suite at a different worker entry than the one built beside + /// the tests — e.g. the apphost of a self-contained script-worker/ from a -r win-x64 Host publish. + /// + public const string WorkerUnderTestVariable = "OTOPCUA_SCRIPTWORKER_TEST_PATH"; + + /// The worker entry named by , or null for the built one. + public static string? WorkerUnderTest + => Environment.GetEnvironmentVariable(WorkerUnderTestVariable) is { Length: > 0 } path ? path : null; + /// Options for a single-shard runner with short budgets, so the containment tests run in seconds. public static ScriptingOptions Options(int shards = 1, TimeSpan? hardGrace = null, int quarantineAfterKills = 2, int probation = 20, TimeSpan? unavailableGrace = null, string? workerPath = null, long heapLimit = 256L * 1024 * 1024, @@ -50,7 +60,7 @@ internal static class Scripts QuarantineAfterKills = quarantineAfterKills, IsolationProbationRuns = probation, UnavailableGrace = unavailableGrace ?? TimeSpan.FromSeconds(30), - ExecutablePath = workerPath, + ExecutablePath = workerPath ?? WorkerUnderTest, HeapLimitBytes = heapLimit, PeCacheDir = peCacheDir, IsolationIdleTimeout = isolationIdle ?? ScriptWorkerOptions.DefaultIsolationIdleTimeout, diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/WorkerEntryTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/WorkerEntryTests.cs new file mode 100644 index 00000000..a74b086b --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/WorkerEntryTests.cs @@ -0,0 +1,105 @@ +using System.Diagnostics; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; +using ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess; + +namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests; + +/// +/// lmxopcua#780: the Windows installs have no .NET runtime, so a self-contained Host publish ships a self-contained +/// worker that the launcher must start through its apphost, while a framework-dependent worker (docker-dev, the +/// tests) keeps going through the dotnet muxer. +/// +[Collection(ScriptWorkerCollection.Name)] +[Trait("Category", "ScriptWorker")] +public sealed class WorkerEntryTests +{ + private static CancellationToken Ct => TestContext.Current.CancellationToken; + + private const string SelfContainedConfig = """ + { "runtimeOptions": { "tfm": "net10.0", "includedFrameworks": [ { "name": "Microsoft.NETCore.App", "version": "10.0.0" } ] } } + """; + + private const string FrameworkDependentConfig = """ + { "runtimeOptions": { "tfm": "net10.0", "framework": { "name": "Microsoft.NETCore.App", "version": "10.0.0" } } } + """; + + private static string ConfigPath(string folder) => Path.Combine(folder, "ZB.MOM.WW.OtOpcUa.ScriptWorker.runtimeconfig.json"); + + private static void Touch(string path) => File.WriteAllText(path, ""); + + [Fact] + public void A_self_contained_worker_is_started_through_its_apphost() + { + using var dir = new Scripts.TempDir(); + Touch(Path.Combine(dir.Path, OutOfProcessScriptRunner.WorkerAppHostFileName)); + Touch(Path.Combine(dir.Path, OutOfProcessScriptRunner.WorkerAssemblyFileName)); + File.WriteAllText(ConfigPath(dir.Path), SelfContainedConfig); + + OutOfProcessScriptRunner.IsSelfContainedWorker(dir.Path).ShouldBeTrue(); + OutOfProcessScriptRunner.ResolveWorkerEntry(dir.Path) + .ShouldBe(Path.Combine(Path.GetFullPath(dir.Path), OutOfProcessScriptRunner.WorkerAppHostFileName)); + } + + [Fact] + public void A_framework_dependent_worker_keeps_the_muxer_even_with_an_apphost() + { + using var dir = new Scripts.TempDir(); + Touch(Path.Combine(dir.Path, OutOfProcessScriptRunner.WorkerAppHostFileName)); + Touch(Path.Combine(dir.Path, OutOfProcessScriptRunner.WorkerAssemblyFileName)); + File.WriteAllText(ConfigPath(dir.Path), FrameworkDependentConfig); + + OutOfProcessScriptRunner.IsSelfContainedWorker(dir.Path).ShouldBeFalse(); + OutOfProcessScriptRunner.ResolveWorkerEntry(dir.Path).ShouldEndWith(OutOfProcessScriptRunner.WorkerAssemblyFileName); + } + + [Theory] + [InlineData(true, null)] // self-contained config but no apphost on disk + [InlineData(false, "{ broken")] // apphost present, unreadable config + [InlineData(false, null)] // apphost present, no config at all + public void Anything_short_of_a_self_contained_apphost_falls_back_to_the_entry_assembly(bool omitAppHost, string? config) + { + using var dir = new Scripts.TempDir(); + if (!omitAppHost) Touch(Path.Combine(dir.Path, OutOfProcessScriptRunner.WorkerAppHostFileName)); + if (omitAppHost) File.WriteAllText(ConfigPath(dir.Path), SelfContainedConfig); + else if (config is not null) File.WriteAllText(ConfigPath(dir.Path), config); + + OutOfProcessScriptRunner.ResolveWorkerEntry(dir.Path).ShouldEndWith(OutOfProcessScriptRunner.WorkerAssemblyFileName); + } + + [Fact] + public void An_explicit_executable_path_wins() + { + var path = Path.Combine(Path.GetTempPath(), "custom", "worker.exe"); + OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = path }).ShouldBe(Path.GetFullPath(path)); + } + + /// The worker built beside the tests is framework-dependent, so the default stays the muxer path. + [Fact] + public void The_built_worker_resolves_to_the_entry_assembly() + { + OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions()) + .ShouldEndWith(Path.Combine(OutOfProcessScriptRunner.WorkerFolderName, OutOfProcessScriptRunner.WorkerAssemblyFileName)); + } + + /// + /// Runs only when names a self-contained worker's apphost (the + /// windev gate over a -r win-x64 --self-contained Host publish): the worker process IS the apphost — no + /// dotnet muxer anywhere — and it evaluates. + /// + [Fact] + public async Task A_published_self_contained_worker_runs_as_its_own_process() + { + var path = Scripts.WorkerUnderTest; + if (path is null || !path.EndsWith(OutOfProcessScriptRunner.WorkerAppHostFileName, StringComparison.OrdinalIgnoreCase)) + Assert.Skip($"set {Scripts.WorkerUnderTestVariable} to a self-contained worker apphost to run this gate"); + OutOfProcessScriptRunner.IsSelfContainedWorker(Path.GetDirectoryName(path)!).ShouldBeTrue("the published folder is self-contained"); + OutOfProcessScriptRunner.ResolveWorkerEntry(Path.GetDirectoryName(path)!).ShouldBe(Path.GetFullPath(path)); + + await using var runner = Scripts.Runner(Scripts.Options(workerPath: path)); + (await runner.RunAsync(Scripts.Vt("vt", "return System.Math.Abs(-3);"), Ct)).Value.ShouldBe(3); + using var worker = Process.GetProcessById(runner.Shards[0].Current!.Pid); + Path.GetFullPath(worker.MainModule!.FileName).ShouldBe(Path.GetFullPath(path), StringCompareShould.IgnoreCase); + } +}