Profiled the remaining lmxopcua#789 misses on windev, a VMware VM, using per-thread CPU and context-switch accounting
plus ETW CPU sampling.
- One blocking hand-off costs ~26 us of latency and ~18 us of CPU there, about 10x macOS.
- An idle evaluation makes four hand-offs in a row: host writer -> worker reader -> evaluation thread -> host reader
-> dispatcher.
- 48% of host CPU at 10k/s is in the kernel: the per-RunAsync NtWriteFile, thread-pool wakes, reads and waits.
Spin-before-block was measured at every hand-off and is not kept. It meets 150 us idle p50 (118 us) only by keeping
about two host cores and four worker cores busy for one stream. At 10k/s it reads +250 points.
Harness: new "paced 10,000/s, batched" row. It uses the same rate and keys, with each 1 ms tick submitted as one
RunBatch call, which is the production seams' shape. It runs after the original four phases, so their rows stay
comparable. On windev it halves host CPU, to +36..+45 points against +71..+84 unbatched. That is still above 25.
Design doc:
- 12.8: the record.
- 14 #15: the owner's decision on the Windows budgets. Recommended: measure on bare-metal Windows, then state the two
budgets per platform, with the batched row as the gate. The alternative is a shared-memory transport.
Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi
- Host reader: the frame read and its handling are caught separately. Only the
read's I/O exceptions mean the pipe ended; anything HandleFrame's inline
completion work throws now kills that worker as ProtocolFault (outstanding
runs -> worker restarted / BadResourceUnavailable) instead of escaping a
dedicated thread (process crash) or being swallowed as a clean end (an
InvalidOperationException used to be, leaving the worker unread until a Crash
2 s later).
- Worker reader: the same catch-all around HandleFrame (exit ProtocolFault).
- Worker: Cancel() runs on the pool, so a script's blocking
ctx.CancellationToken callback cannot stop the worker reading its pipe.
- Host write-stall check: ScriptWorkerFrameWriter.WriteInProgressFor; the
heartbeat monitor kills a worker whose pipe write has been blocked longer than
max(10 s, silence limit) as KilledUnresponsive, which fails the write and
releases the producer (seam submit, deploy load, Cancel). Fixes the wrong
'heartbeat monitor ends it' comment on the pipe buffer quota.
- StopAsync sends Shutdown off the caller so its 1 s budget holds on a full pipe.
- WindowsBlockingPipeStream refuses the async surface (Stream's base versions
serialise a write behind a waiting read).
- Tests: PipeFaultTests (throwing completion callback -> ProtocolFault and a
BadResourceUnavailable sibling, shard serves again; a worker that stops reading
but heartbeats is killed within the bound and the blocked producer returns,
via the Hello.test_stall_reader_on_diag seam); BlockingPipeStreamTests dispose
with a write blocked on a full pipe, and with a read and a write both pending;
Category=ScriptWorker on the protocol, handshake and pipe test classes.
Mutation checks: no stall kill -> stall test red; catch-all without the fault
-> callback test red (Crash).
Claude-Session: https://claude.ai/code/session_01GT67AD99zQQqpLCVm3p7xk
The owner revised the per-shard worker idle RSS budget from 80 MB to 200 MB
+ scripts on 2026-11-11: compiles run in the worker, so Roslyn's code and
metadata stay resident (measured 159-187 MB) and no GC setting moves it.
The perf harness now reports both RSS rows against the 200 MB constant with
a PASS/MISS mark; A-3 records what the measurement showed.
Claude-Session: https://claude.ai/code/session_01GT67AD99zQQqpLCVm3p7xk
Reproduced 10/10 under 28 CPU burners (load 100-250): every run killed for
157-309 ms of silence with every compile on its dedicated thread - the OS
scheduler, not the pool. A 1 s limit still failed 1/10 at load ~300
(1,012 ms). The limit is now production's (3 x the default 1 s heartbeat):
10/10 at load 360-430. The failure message now carries the burst length,
the limit and the kill line.
Also corrects the doc: its mutation check (compile on the pool again =>
killed for silence) no longer holds - re-checked on a 14-core Mac, the
mutated worker passed at both 150 ms and 1 s, because the host's silence
clock counts any frame and since #789 each compile writes its own
LoadStarted/LoadResult frames inline.
Co-Authored-By: Claude <noreply@anthropic.com>
The proto comment, VirtualTags.md and CLAUDE.md said the soft deadline
measures the script's own execution and that starvation never counts. Only
the time before the run STARTS is excluded; from the start it is wall-clock
time, as in process, so a GC pause or a starved / suspended worker during
the run still counts. A mid-run freeze test is not added: it races the
script's own return against the watchdog's notice; documented as not covered.
Also documents F2 (late notice cancels and counts), F3 (progress ceiling,
killed_unresponsive) and F5 (answer = stalled | retrigger).
otopcua.script.ipc.timeouts gains the tag answer = stalled | retrigger: a
later trigger refused while the key's stalled run is still unanswered was
counted nowhere (not a script refusal, so not ScriptRunGuard's counter).
KeyState carries its Kind for the tag. Test: the stalled-worker test listens
for the instrument and sees one stalled and one retrigger (before: only
stalled).
With the worker soft clock the host's per-run timer is only the transport
deadline and the kill G is armed by the worker's soft notice, so a worker
whose watchdog never sends one (the design treats the worker as untrusted)
held the run, the key's slot and the tag's BadResourceUnavailable forever;
a deferred run had no host clock at all.
WorkerConnection now tracks evaluation progress (any Results frame, or the
submit that made the worker busy again). The heartbeat monitor kills the
worker when evaluations are outstanding and nothing progressed for
3 x the largest outstanding T + G plus the silence limit:
WorkerExitReason.KilledUnresponsive (metric reason killed_unresponsive), no
culprit, attributed like a heartbeat kill (suspects, no strike on a shard).
A legitimate run has answered or been killed by T + G.
Test seams: ProgressCeilingOverride, DropSoftNoticesForTest. Tests: a worker
whose notices are dropped (G = 60 s, so its own fail-fast cannot end it) is
killed KilledUnresponsive after the 1.5 s ceiling and the run is released
(with the check disabled the test times out); positive control: 20 queued
150 ms runs behind one thread under a 1 s ceiling are all answered.
F1: PendingEval.SoftExpired runs on the pipe reader and completed the
caller's outcome inline (production outcomes have no async continuations, by
design, because results resume on the ResultDispatcher). The caller's code
(the runner's Cancel write, the seam's publish) therefore ran on the reader,
which could hold up heartbeats (a false silence kill) and, with blocking I/O,
write to the pipe from the reader. The soft outcome is now posted to the
dispatcher like a result. Test: a 1.5 s continuation on a soft timeout with a
300 ms silence limit resumes on ScriptWorker[t].Results and the worker lives
(before: it resumed on the Reader).
F2: after a transport timeout ("worker unresponsive"), a late soft notice
armed G but nobody sent Cancel, so a polling script could not end itself and
the whole worker was killed at notice + G with a kill strike. PendingEval now
exposes LateSoftExpiry (asynchronous continuations, cancelled when the run
answers); the runner sends the Cancel and counts the timeout
(NoteTimeout) from it. A genuinely slow script whose notice is delayed past
T + G is thus still a timeout. Test: stall past T + G, thaw, a polling
script overruns T: the worker survives G and the key is quarantined for
timeouts, not a hard deadline (before: the worker was killed).
A_burst_of_cold_compiles_does_not_starve_the_heartbeat (50 ms heartbeat) and
A_caller_that_blocks_after_its_result_does_not_starve_the_reader (100 ms)
launched their worker under the tight silence kill, so its cold start (launch,
first compile, Roslyn JIT) had to stay within 150/300 ms of silence. Under 28
busy processes on 14 cores that failed 2 in 10 runs in the WARM-UP, killed
for ~165 ms of silence, and replacement workers were killed the same way.
New test seam: WorkerLaunchSpec.HeartbeatSilenceLimit (runner internal ctor
heartbeatSilenceLimit) and WorkerConnection.SilenceLimit. The tests launch
with a 30 s limit, warm, then tighten to three intervals for the phase they
are about; the assertions on that phase are unchanged.
The soft deadline T was armed on the host at submit, so the pipe round trip
and the time a starved worker waits to be scheduled counted against the
script: under load a trivial script reported 'script timed out', in Shadow
mode that was a script mismatch, and at T + G the host killed the worker and
struck the key.
- Protocol (additive, negotiated): Hello/Ready.worker_soft_clock and
EvalResults.soft_expired_eval_ids. protocol_version stays 1; a worker that
does not echo the flag keeps the pre-#827 host clock.
- Worker: the watchdog runs each run's soft clock from the moment an
evaluation thread starts it and reports the crossing (woken early for
budgets shorter than its 50 ms poll). It still never cancels by itself;
its fail-fast is anchored at the soft notice + G + margin.
- Host (PendingEval): the soft notice answers the caller and arms the kill G
later. The host's own timer becomes a transport deadline, T + G from submit
(restarted at a deferred run's start); passing it with no result and no
notice yields TransportTimedOut -> Unavailable 'script worker unresponsive'
(BadResourceUnavailable, recovery = the run's completion), no strike, no
kill, no Cancel. A re-trigger refused by that still-unanswered run is
Unavailable too, not 'previous run still running'. Counted as
otopcua.script.ipc.timeouts{kind}.
- Frame writer: coalescing now carries soft_expired_eval_ids (it silently
dropped them); the host processes soft notices before results in a frame.
- Shadow: unresponsive is shadow_unavailable (Unavailable), never a mismatch.
Tests: WorkerSoftClockTests suspends the real worker (SIGSTOP via libc kill /
NtSuspendProcess) - a stall past T still returns 7; a stall past T + G is a
runner fault with nothing struck; a late-starting runaway is still timed out
at T from its start and killed G after; Shadow stays match /
shadow_unavailable; both clocks enforce T and G; PendingEval state machine.
A wrong published value now reports its Success/Value/Reason/StatusCode, the
publish's wall time against the run budget, the run guard's in-flight /
refused / quarantined counters, thread-pool and GC state around the call,
the shadow stats, and the tails of the script and runner logs.
Reproduced under heavy load (32 `yes`, test at nice 20, load avg 300+):
3 of 8 runs failed, every one because the SIBLING's shadow run missed the
300 ms soft deadline in the starved worker ("shadow Failed [budget] script
timed out after 0.3s") and was rightly recorded as a sibling mismatch. No
published value was ever wrong. The out-of-process soft deadline is armed at
submit, so it covers the pipe round trip and worker scheduling too.
The run budget (which is also the worker's soft deadline) goes to the 2 s
production default; no assertion changes. The runaway still runs away and is
killed at T + HardGrace, so nothing the test proves depends on T being short.
ShadowModeTests' runaway case asserted "slowest < 250 ms" around evaluations
whose timing included cold Roslyn compile/JIT of new script text, so it failed
on a healthy published path (540-880 ms measured, both SDK baselines).
The test now puts a test-owned barrier runner (GatedShadow) between the real
ShadowScriptRunner and the real worker pool. The runaway's first shadow run is
held before it reaches the pool, then (after it runs away in the worker, the
pool answers T and the worker is KilledDeadline with the runaway as culprit)
its outcome is held before comparison. Published evaluations made while a
barrier is closed must return the in-process values; a Mirror that waited for
its shadow hangs into a 30 s liveness failure (mutation-checked). Output
correctness, pool kill/quarantine, published-side never quarantined, the single
runaway mismatch (sibling is a victim, not compared) and key_busy drops are kept.
The wall-clock number moves to an opt-in Category=Perf case
(Shadow_published_path_latency_while_the_shadow_runs_away, OTOPCUA_SCRIPT_PERF=1)
on warmed evaluators, reporting hardware and load average.
Sibling: ContainmentTests' hard-deadline case timed the runaway's first
(cold-compile) run; it now compiles the runaway's source first with an input
that does not spin.
Owner decisions §14 #5/#6 as built (design §12.5):
- Scripting:Worker:Identity (default unset, Windows only, fail-closed validation): each worker
starts under a restricted token derived from the host's. Every privilege but SeChangeNotify is
removed; the restricting SIDs are NT SERVICE\OtOpcUaScriptWorker's SID + Everyone + Users +
RESTRICTED; the token and default DACLs are host + SYSTEM + identity + RESTRICTED. The worker
is created suspended, put in its Job Object before it runs, inherits only its stdio pipes, gets
an ACL'd work dir as TEMP, and runs with DOTNET_EnableDiagnostics=0. The identity is granted on
the host's window station and desktop, because USER32 init made coreclr.dll fail with
ERROR_DLL_INIT_FAILED on windev. The logon SID is not used because the host's process DACL
gives it PROCESS_VM_READ.
- The worker pipe on Windows always has an explicit protected DACL: host account + identity
only. There is no owner ACE, so an elevated host's Administrators gets no access.
- The worker treats access denied on its parent-pid poll as alive; the Job Object covers that case.
- scripts/install/Install-ScriptWorkerIsolation.ps1 + ScriptWorkerIsolation.psm1 are idempotent
and support -WhatIf, -Uninstall and -PlanOnly. They create the disabled anchor service, the
PeCacheDir ACL (protected, no Users, key and markers host-only, pe\ Modify for the identity),
read+execute on script-worker\, a ReadData deny on the install root, the outbound firewall
block on the worker exe, and optionally the host-service env.
- Tests: the dry-run harness scripts/install/tests/Test-ScriptWorkerIsolation.ps1 (46
assertions, mutation-checked); ScriptWorkerIdentityTests; WorkerIsolationTests, which cover
the pipe ACL, token access and a real restricted worker running a script, all green on windev.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
ForbiddenTypeAnalyzer now denies System.AppContext, System.Console, GCSettings, ProfileOptimization,
EncodingProvider/CodePagesEncodingProvider, TypeDescriptor and CryptoConfig as types, and the ambient
CultureInfo.{DefaultThreadCurrentCulture,DefaultThreadCurrentUICulture,CurrentCulture,CurrentUICulture}
and TimeZoneInfo.ClearCachedData members (member deny-list now covers properties and member-access reads).
Shadow-mode tests diverge via culture-sensitive string.Compare (worker is InvariantGlobalization) instead of
AppContext.BaseDirectory, with a premise test. Mutation-proved: 21 new cases fail with the analyzer reverted.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
- ShadowScriptRunner (Core.Scripting): IScriptShadow.Mirror copies the inputs and queues the shadow run on the
pool; compares value (structural), CLR type, status and failure class (compile / budget / threw+message /
unsupported_type); runner-fault shadow outcomes (Unavailable, worker busy) are not compared. Bounded:
Scripting:Shadow:MaxInFlight (256) and one per script; drops counted (behind | key_busy).
- Metrics otopcua.script.shadow.{compared,mismatch{script},dropped,inflight}; one rate-limited Warning per
script and reason with a diff summary (Scripting:Shadow:MismatchLogsPerMinute, re-armed at the seam's deploy).
- The VirtualTag, Calculation and scripted-alarm seams recognise the shadow and keep their in-process path
byte-for-byte (no coalescer, one-at-a-time pump, in-process engine), mirroring after each compiled run.
- ScriptRunnerSelection builds the shadow over an OutOfProcessScriptRunner whose lines carry
ScriptRunnerRole=Shadow; Status() is null under Shadow so readiness never sees the shadow pool; the
script-runner health entry stays Healthy and reports the shadow counters as data.
- docker-dev/docker-compose.script-runner-shadow.yml; docs/VirtualTags.md "Shadow mode".
- Tests: comparison table, per-script metric + once-per-reason log, rate limit, hung/blocking/throwing shadow
never reaches the caller, MaxInFlight drop accounting, input copy; real-worker divergent + unsupported-type
scripts counted against exactly those scripts, a worker-only runaway killed/quarantined there with every
published value intact, alarm transitions identical to in process across a kill -9 of the shadow worker.
Mutation-proved (16 mutants, 15 red; the one survivor added an assertion).
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
- IScriptRunner.RunBatch: one EvalBatch frame per worker for every evaluation ready to run; per-item, streamed results.
The default (InProcessScriptRunner) is RunAsync per item. Used by the Calculation pump (dequeue all, split at a
repeated tag, publish in dequeue order), the VirtualTag seam (ScriptBatchCoalescer, no timer) and the scripted-alarm
engine (whole dirty set). In process the pump and the engine stay one at a time, unchanged.
- Exact per-item deadlines: the worker hands work to an idle evaluation thread or defers it (EvalResults
deferred_eval_ids); the host stops that run's clock and restarts T then G when it starts (started_eval_ids). A run
queued behind a runaway is neither timed out nor struck and is a victim, not the culprit, at the kill.
- Scripted-alarm seam behind Scripting:Runner:Seams; unset Seams now means VirtualTag + Calculation, so alarms run out of
process only when listed. Load still compiles each predicate (to PE bytes only) so a broken one fails the load; passes
batch and apply in the serial order under the gate. Script faults freeze the condition BadInternalError; runner faults
freeze it BadResourceUnavailable and re-evaluate on recovery; a dead worker never clears an alarm. IScriptRunnerProvider
carries the runner to DriverHostActor.
- Perf harness: batch throughput (RunBatch vs RunAsync x n) and alarm-pass latency (in process / batched / serial);
design §12.3 records macOS + windev. On windev the serial out-of-process alarm pass misses 250 ms from ~500 alarms;
batched p99 <= 53 ms at 1,000.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
#789 (partial, further tuning deferred): combining inline frame writer, buffered
frame reader, one timer per evaluation for T and T+G, slot release on the reader
before the caller resumes, a non-spinning per-connection result dispatcher, and
blocking pipe I/O on Unix (both ends) so the socket never enters the socket
engine; TerminateJobObject kill on Windows. macOS host CPU at 10k evals/s K=2:
228-240 % -> 79 % (InProcess 69 %, IPC share +10 vs budget 25); windev 153 % ->
123 % (+115, still a miss). Harness reports the "vs InProcess" share, warm-cache
worker RSS, and times kill latency from the soft-timeout answer.
#790: the worker sends LoadStarted; the compile timeout is armed then, so a load
queued behind other compiles is never killed or struck.
#788: one Error with stack per down period, rate-limited Warnings with attempt
count, one Information on recovery.
Design doc §8.2 notes + §12.2 record.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
- A self-contained Host publish (-r win-x64 --self-contained, the Windows installs) now publishes the
ScriptWorker self-contained for the same RID into script-worker/. The launcher starts its apphost
directly when runtimeconfig.json lists includedFrameworks. A framework-dependent worker (docker-dev)
keeps running through the dotnet muxer.
- docker-dev/docker-compose.script-runner.yml: OutOfProcess for the central pair's VT + Calc seams.
Live drill recorded in design §12.1 (runaway kill + quarantine, kill -9 recovery, open circuit
with /health/ready still 200, metrics).
- ScriptRunnerPerfTests (Category=Perf, opt-in via OTOPCUA_SCRIPT_PERF=1): InProcess vs OutOfProcess
at K=1/2/4. The accepted 5k evals/s/node gate passes on macOS and windev. The host-CPU, RSS and
Windows latency budget misses are tracked as #789.
- Fix: the single-flight slot is released before the awaiting caller resumes. Before, a caller that
started its next run right after the previous one returned could be refused with "previous
evaluation still running", which the seams publish as Bad.
- Fix: the worker compiles on dedicated threads, not the thread pool. A burst of cold loads starved
the heartbeat, and the host killed the shard (found on windev). Load-timeout queueing is #790.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
Second P1 slice of docs/plans/2026-11-09-out-of-process-script-runner-design.md; still opt-in behind
Scripting:Runner=OutOfProcess (InProcess unchanged).
- Compiled-PE cache (design §7, §14 #8): Scripting:Worker:PeCacheDir holds <dir>/pe/<id>.pe entries authenticated
with HMAC-SHA256 under a per-node random key (<dir>/pe-cache.key, created by the host, 0600/0700 on Unix), handed to
the worker in Hello. Entry id = SHA-256(compile fingerprint + kind + source); the fingerprint covers the Roslyn
version, the Core.Scripting build (analyzer, wrapper, stack guard), the sandbox reference set and the runtime. Edited,
truncated, other-key or renamed entries are rejected, deleted and recompiled; the worker never loads unverified bytes.
Pruned by recency at startup (30 d / 50 000). ScriptEvaluator splits into CompileToImage + FromImage. Measured on
40 scripts, restart to every first result: macOS 820 ms no cache / 840 ms empty / 85 ms warm;
windev (Windows) 9.5 s / 9.4 s / 1.0 s.
- Quarantine race: WorkerConnection runs exit attribution synchronously BEFORE completing the evaluations/loads it held
(and before Exited), and the shard passes it straight to the runner — a kill strike is in place before the killed
key's slot is released.
- Supervision: a dead worker restarts by itself after its backoff; Unavailable outcomes carry ScriptRunOutcome.Recovery
(-> VirtualTagEvalResult.RetryWhen) and the VT actor / Calculation driver re-evaluate once against current inputs when
it completes. Isolation worker stops after Scripting:Worker:IsolationIdleTimeout (10 min). Keys compiling when a
worker dies are suspects too (isolation finds a poison compile and quarantines it). Startup orphan sweep by launch
marker: kills only a process whose marker's host is gone and whose pid + start time + image match.
- Crash-loop circuit (Scripting:Worker:CircuitOpenAfter, 2 min): runner Unavailable, one Error, evaluations answered
at once while shards keep retrying at the cap.
- Observability (§10): otopcua.script.runner.state, worker.up/inflight/queue_depth/heap_bytes (shard),
ipc.roundtrip + eval.duration (kind), compile{cache}, isolation.suspects, exits reason=idle. `script-runner` health
check on the ready tier, at worst Degraded (§14 #12: degraded but still ready).
Left on #780: self-contained worker publish, installer (account, pipe ACL, firewall), docker-dev live drill,
scripted-alarm seam, the §4.5 per-seam batch submit, the §8 perf harness.
Tests: SupervisionTests, PeCacheStoreTests/PeCacheWorkerTests (real workers), ScriptRunnerHealthCheckTests, VT + Calc
recovery seam tests; 14 mutations each turned their test red.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
Joseph Doherty