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 <noreply@anthropic.com>
This commit is contained in:
Joseph Doherty
2026-11-11 04:36:29 -05:00
parent c3cf11c5e4
commit 4cd648b029
@@ -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.
/// <para>⚠️ 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
/// <c>LoadStarted</c>/<c>LoadResult</c> 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.</para>
/// </summary>
[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);