From 4cd648b0299a1fab5294b8363bdf90aa8928c5a3 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 04:36:29 -0500 Subject: [PATCH] test(scriptworker): cold-burst heartbeat test kills at production's 3 s silence limit, self-diagnosing (#843) 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 --- .../SupervisionTests.cs | 29 ++++++++++++++++--- 1 file changed, 25 insertions(+), 4 deletions(-) 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 df214c4b6..1fdceb1d3 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs @@ -125,9 +125,14 @@ public sealed class SupervisionTests /// 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. + /// keys suspects. Here a 50 ms heartbeat (kill after 3 s of silence, production's limit) and 1,500 distinct cold scripts at once: + /// every script answers and the shard's worker is the one that started. + /// ⚠️ The old "mutation check: compile on the thread pool again and the worker is killed for silence" does + /// NOT hold any more (re-checked for lmxopcua#843 on a 14-core Mac: the mutated worker passed at both the 150 ms + /// and the 1 s limit). The host's silence clock counts ANY frame, and since lmxopcua#789 a compile writes its own + /// LoadStarted/LoadResult frames inline — so pool-queued compiles keep the pipe busy themselves (the 3 s silence + /// windev saw presumably also needed the pre-#789 pool-scheduled writer stuck behind them). What this still pins is the + /// behaviour: a cold burst under a tight heartbeat is answered without a kill. /// [Fact] public async Task A_burst_of_cold_compiles_does_not_starve_the_heartbeat() @@ -136,13 +141,29 @@ public sealed class SupervisionTests var heartbeat = TimeSpan.FromMilliseconds(50); await using var runner = TightHeartbeatRunner(heartbeat, TimeSpan.FromSeconds(120), sink); var worker = WarmTight(runner, await runner.RunAsync(Scripts.Vt("first", Healthy), Ct), heartbeat, sink); + // lmxopcua#843: three 50 ms intervals (150 ms) is a limit the OS scheduler alone breaks on an overloaded box — at + // load average 100–280 the worker or the host's reader waited 150–310 ms for a core (10/10 runs killed for silence + // under 28 CPU burners, every compile on its dedicated thread), and at ~300 even a 1 s limit was hit once in 10 + // (1,012 ms). The limit is now PRODUCTION's (3 × the default 1 s heartbeat): the test kills only where a real node + // would, and the windev defect (no frame for 3 s, the whole burst) is still the size it catches. The 50 ms + // heartbeat keeps frames flowing for the silence clock. + worker.SilenceLimit = TimeSpan.FromSeconds(3); const int count = 1500; + var burst = Stopwatch.StartNew(); 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))); + burst.Stop(); - var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)).Take(5)); + // The kill line ("sent nothing for N ms") against the burst's length is the diagnosis: N close to the burst is + // the pool-starvation defect, N just over the limit is a starved box. + var log = $"burst took {burst.ElapsedMilliseconds} ms, silence limit {worker.SilenceLimit.TotalMilliseconds} ms\n" + + string.Join(Environment.NewLine, sink.Rendered + .Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)) + .Where(l => l.Contains("sent nothing", StringComparison.Ordinal) || l.Contains("kill", StringComparison.OrdinalIgnoreCase) + || l.Contains("exit", StringComparison.OrdinalIgnoreCase)) + .Take(10)); 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);