dohertj2/lmxopcua
1
0
Fork 0
Code Issues 24 Pull Requests Actions 2 Packages Projects Releases Wiki Activity

perf(scripting): cut out-of-process runner host CPU; compile timeout from compile start; quiet start-failure logs (lmxopcua#789, #790, #788)
v2-ci / unit-tests (push) Has been cancelled
Details

Browse Source 
#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
This commit is contained in:
Joseph Doherty
2026-11-10 04:25:08 -05:00
parent 963b0d66fc
commit 8582ce91bc
14 changed files with 1576 additions and 317 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs
+213 -2
View File
@@ -132,8 +132,11 @@ public sealed class SupervisionTests
/// 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.
/// running" — which the VirtualTag and Calculation seams publish as Bad. Since lmxopcua#789 the release runs in
/// the connection, on the reader, before the caller's resumption is handed to the result dispatcher; the second
/// phase makes every release slow (the test hook sleeps inside it) so the ordering, not luck, is what keeps the
/// caller from being refused. Mutation check: release after handing off the resumption and the second phase goes
/// red.
/// </summary>
[Fact]
public async Task A_caller_that_awaited_its_run_is_never_refused_by_it()
@@ -147,6 +150,15 @@ public sealed class SupervisionTests
if (outcome.Status != ScriptRunStatus.Ok || !Equals(outcome.Value, i + 7)) refused.Add($"#{i}: {outcome.Reason}");
}
refused.ShouldBeEmpty();
runner.SlotReleasingForTest = _ => Thread.Sleep(5);
for (var i = 0; i < 50; 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($"slow release #{i}: {outcome.Reason}");
}
refused.ShouldBeEmpty();
}
/// <summary>
@@ -487,4 +499,203 @@ public sealed class SupervisionTests
status.State.ShouldBe(ScriptRunnerState.Ready);
status.Shards.Single(s => s.Label == "0").Pid.ShouldBe(runner.Shards[0].Current!.Pid);
}
// ---------------------------------------------------------------- lmxopcua#789: who resumes the caller
/// <summary>
/// lmxopcua#789: callers resume on the connection's result dispatcher, never on the pipe reader — so a consumer
/// that blocks after its await (the Calculation pump publishes to OPC UA subscribers there) cannot stop the reader
/// from taking heartbeats and get a healthy worker killed for silence. Here a 100 ms heartbeat (kill after 300 ms
/// of silence) and a continuation that blocks for 1.5 s. Mutation check: resume callers inline on the reader (a
/// synchronous-continuation TaskCompletionSource completed by the reader, no dispatcher) and the worker is killed
/// (KilledHeartbeat).
/// </summary>
[Fact]
public async Task A_caller_that_blocks_after_its_result_does_not_starve_the_reader()
{
var sink = new CapturingSink();
await using var runner = new OutOfProcessScriptRunner(Scripts.Options(), sink.CreateLogger(), null,
heartbeatInterval: TimeSpan.FromMilliseconds(100), loadTimeout: TimeSpan.FromSeconds(60));
(await runner.RunAsync(Scripts.Vt("warm", Healthy), Ct)).Value.ShouldBe(7);
var worker = runner.Shards[0].Current.ShouldNotBeNull();
string? resumedOn = null;
await runner.RunAsync(Scripts.Vt("warm", Healthy), Ct).ContinueWith(t =>
{
// Runs wherever RunAsync's own continuation completed it: the thread that resumed the caller.
resumedOn = Thread.CurrentThread.Name;
t.Result.Value.ShouldBe(7);
Thread.Sleep(1_500);
}, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default);
// Behaviour first: the worker was not killed for silence while the caller blocked.
(await Task.WhenAny(worker.Exited, Task.Delay(1_000, Ct))).ShouldNotBe(worker.Exited,
string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal))));
var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)));
resumedOn.ShouldBe("ScriptWorker[0].Results", log);
(await runner.RunAsync(Scripts.Vt("warm", Healthy), Ct)).Value.ShouldBe(7);
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, log);
}
// ---------------------------------------------------------------- lmxopcua#788: start-failure logging
/// <summary>
/// lmxopcua#788: a shard that keeps failing to start logs ONE Error with the exception for the down period; its
/// retries are a Warning without a stack, carrying the attempt count, rate-limited (the rest at Debug); and the
/// start that ends the outage is one Information line naming how many attempts failed. The docker-dev drill logged
/// 28 Error+stack entries in two minutes on one node before this. Mutation check: log every failure at Error with
/// the exception again and the single-Error assertion goes red (3 Errors).
/// </summary>
[Theory]
[InlineData(0, 2, 0)]
[InlineData(3_600_000, 0, 2)]
public async Task A_shard_that_cannot_start_logs_one_error_then_concise_rate_limited_retries_then_its_recovery(
int warnEveryMs, int expectedWarnings, int expectedDebugs)
{
var sink = new CapturingSink();
var log = sink.CreateLogger();
var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(5), HeartbeatInterval: TimeSpan.FromSeconds(1),
HandshakeTimeout: TimeSpan.FromSeconds(15));
var attempts = 0;
await using var shard = new WorkerShard("t", isolation: false,
(onExiting, ct) => Interlocked.Increment(ref attempts) <= 3
? throw new InvalidOperationException("the worker exited (code 1) before connecting to its pipe")
: WorkerConnection.StartAsync(spec, log, _ => { }, onExiting, ct),
(_, _) => { }, log, startFailureWarningInterval: TimeSpan.FromMilliseconds(warnEveryMs));
// The background recovery retries at the backoff (250 ms, 500 ms, 1 s, ±20 %) until the 4th attempt starts.
await shard.WhenRecoveredAsync(null).WaitAsync(TimeSpan.FromSeconds(30), Ct);
shard.Current.ShouldNotBeNull();
attempts.ShouldBe(4);
var events = sink.Events.Where(e => e.MessageTemplate.Text.StartsWith("ScriptWorker[{Shard}]", StringComparison.Ordinal)).ToList();
string Dump() => string.Join(Environment.NewLine, events.Select(e => $"{e.Level} {e.RenderMessage()} {(e.Exception is null ? "" : "+exception")}"));
static int Attempts(Serilog.Events.LogEvent e) => int.Parse(e.Properties["Attempts"].ToString(), System.Globalization.CultureInfo.InvariantCulture);
var errors = events.Where(e => e.Level == Serilog.Events.LogEventLevel.Error).ToList();
errors.Count.ShouldBe(1, Dump());
errors[0].Exception.ShouldNotBeNull("the first failure of the outage carries the stack");
var warnings = events.Where(e => e.Level == Serilog.Events.LogEventLevel.Warning).ToList();
warnings.Count.ShouldBe(expectedWarnings, Dump());
warnings.ShouldAllBe(e => e.Exception == null);
warnings.Select(Attempts).ShouldBe(expectedWarnings == 0 ? [] : [2, 3]);
events.Count(e => e.Level == Serilog.Events.LogEventLevel.Debug && e.Properties.ContainsKey("Attempts")).ShouldBe(expectedDebugs, Dump());
var recovered = events.Single(e => e.Level == Serilog.Events.LogEventLevel.Information && e.Properties.ContainsKey("Attempts"));
Attempts(recovered).ShouldBe(3);
recovered.RenderMessage().ShouldContain("after 3 failed start attempt(s)");
}
// ---------------------------------------------------------------- lmxopcua#790: compile timeout from compile start
/// <summary>A script of <paramref name="lines"/> statements: Roslyn needs time roughly proportional to it.</summary>
private static string Lines(int lines, int salt)
{
var body = new StringBuilder("var a = ").Append(salt).Append(";\n");
for (var i = 0; i < lines; i++) body.Append("a += (int)ctx.GetTag(\"x\").Value * ").Append(i % 97).Append(";\n");
return body.Append("return a;").ToString();
}
private static int LinesValue(int lines, int salt) => salt + Enumerable.Range(0, lines).Sum(i => i % 97);
/// <summary>
/// lmxopcua#790: the compile timeout runs from when a compile thread STARTS a load, so a queue of compiles that
/// takes several load timeouts to drain kills nothing and strikes nobody. One compile thread; the compiler is
/// warmed under a generous timeout (a cold Roslyn start alone takes seconds on the Windows VM), then the live
/// connection's timeout drops to four times one measured compile (at least 3 s; a 500-statement script takes
/// ~0.1 s on an M-series Mac and ~1.5 s on the Windows VM) and a burst of such scripts, sized from that and grown
/// until it does, queues for over three timeouts — asserted, so the test cannot pass vacuously
/// — while each compile stays far inside the timeout. Mutation check: time the load from when the host SENT it
/// (the old <c>WaitAsync(LoadTimeout)</c> around the load) and the worker is killed and the queued keys are
/// struck.
/// </summary>
[Fact]
public async Task Compiles_queued_behind_others_longer_than_the_load_timeout_are_not_killed_or_struck()
{
const int lines = 500;
var sink = new CapturingSink();
await using var runner = new OutOfProcessScriptRunner(Scripts.Options(), sink.CreateLogger(), null,
heartbeatInterval: TimeSpan.FromSeconds(1), loadTimeout: TimeSpan.FromSeconds(120), compileThreads: 1);
(await runner.RunAsync(Scripts.Vt("first", Healthy), Ct)).Value.ShouldBe(7);
var worker = runner.Shards[0].Current.ShouldNotBeNull();
ScriptInvocation Script(string prefix, int i)
=> Scripts.Vt($"{prefix}-{i}", Lines(lines, i), TimeSpan.FromSeconds(300), Scripts.Input("x", 1));
// Warm the compiler, then calibrate: the compile time of one such script on this box.
for (var i = 0; i < 3; i++) (await runner.RunAsync(Script("warm", i), Ct)).Value.ShouldBe(LinesValue(lines, i));
var probe = Stopwatch.StartNew();
for (var i = 0; i < 3; i++) (await runner.RunAsync(Script("probe", i), Ct)).Value.ShouldBe(LinesValue(lines, i));
var perCompile = probe.Elapsed / 3;
var loadTimeout = TimeSpan.FromTicks(Math.Max(TimeSpan.FromSeconds(3).Ticks, perCompile.Ticks * 4));
worker.LoadTimeout = loadTimeout;
var count = (int)Math.Clamp(Math.Ceiling(7 * loadTimeout / perCompile), 10, 300);
// A burst compiles faster per script than the sequential probe (the compiler keeps warming up), so grow the burst
// until it really outlasts three load timeouts; each burst must pass the same no-kill checks.
ScriptRunOutcome[] outcomes = [];
var elapsed = TimeSpan.Zero;
for (var round = 0; round < 4; round++)
{
runner.Reset(ScriptContextKind.VirtualTag); // unload the previous round's scripts (worker heap)
var sw = Stopwatch.StartNew();
var prefix = "queued" + round;
outcomes = await Task.WhenAll(Enumerable.Range(0, count).Select(i => runner.RunAsync(Script(prefix, i), Ct)));
elapsed = sw.Elapsed;
for (var i = 0; i < count; i++) outcomes[i].Value.ShouldBe(LinesValue(lines, i), $"round {round}: {outcomes[i].Status} {outcomes[i].Reason}");
if (elapsed > loadTimeout * 3) break;
count = Math.Min(1_200, count * 2);
}
var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)).Take(5));
elapsed.ShouldBeGreaterThan(loadTimeout * 3,
$"precondition: {count} compiles (probe {perCompile.TotalMilliseconds:F0} ms each) must queue for several load timeouts, or this proves nothing");
worker.Exited.IsCompleted.ShouldBeFalse(log);
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, log);
runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty();
runner.SuspectKeys.ShouldBeEmpty();
sink.Rendered.ShouldNotContain(l => l.Contains("killing the worker", StringComparison.Ordinal));
}
/// <summary>
/// The positive control for the test above: a compile that is still running <c>LoadTimeout</c> after it STARTED is
/// the script's fault — the worker is killed (<c>KilledLoadTimeout</c>), the caller gets the compile-timeout
/// failure, the key takes a kill strike (the second quarantines it), and the healthy key on the same shard is
/// not blamed. The healthy key comes from a primed PE cache, so a fresh worker's cold Roslyn start never counts
/// against the short timeout. Mutation check: never arm the timer on <c>LoadStarted</c> and the huge compile
/// simply finishes (status Ok, red).
/// </summary>
[Fact]
public async Task A_compile_still_running_a_load_timeout_after_it_started_is_killed_and_struck()
{
using var dir = new Scripts.TempDir();
var cache = Path.Combine(dir.Path, "pe-cache");
await using (var primer = Scripts.Runner(Scripts.Options(peCacheDir: cache)))
(await primer.RunAsync(Scripts.Vt("first", Healthy), Ct)).Value.ShouldBe(7);
var sink = new CapturingSink();
await using var runner = new OutOfProcessScriptRunner(Scripts.Options(quarantineAfterKills: 2, peCacheDir: cache),
sink.CreateLogger(), null, heartbeatInterval: TimeSpan.FromSeconds(1), loadTimeout: TimeSpan.FromSeconds(2), compileThreads: 1);
(await runner.RunAsync(Scripts.Vt("first", Healthy), Ct)).Value.ShouldBe(7);
// 20,000 statements: about 4 s of Roslyn on an M-series Mac, longer elsewhere.
var huge = Scripts.Vt("huge", Lines(20_000, 0), TimeSpan.FromSeconds(30), Scripts.Input("x", 1));
for (var strike = 1; strike <= 2; strike++)
{
var before = runner.Shards[0].Current ?? await runner.Shards[0].GetReadyAsync(TimeSpan.FromSeconds(30), Ct);
var outcome = await runner.RunAsync(huge, Ct).WaitAsync(TimeSpan.FromSeconds(60), Ct);
outcome.Status.ShouldBe(ScriptRunStatus.Failed, $"strike {strike}");
outcome.Reason.ShouldNotBeNull().ShouldContain("compile did not finish");
var exit = await before.ShouldNotBeNull().Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct);
exit.Reason.ShouldBe(WorkerExitReason.KilledLoadTimeout);
exit.CulpritKey.ShouldBe(VtKey("huge"));
}
var third = await runner.RunAsync(huge, Ct);
third.Reason.ShouldNotBeNull().ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix);
runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBe(["huge"]);
(await runner.RunAsync(Scripts.Vt("first", Healthy), Ct)).Value.ShouldBe(7, "the healthy key on the same shard is not blamed");
}
}