test(script-worker): prove Shadow non-blocking causally, not by stopwatch (#798)

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.
2026-11-10 21:15:12 -05:00
parent b36e688f0a
commit 304d1f1e6c
3 changed files with 214 additions and 17 deletions
@@ -571,4 +571,95 @@ public sealed class ScriptRunnerPerfTests
            .AppendLine($"| kill latency after T+G (5 runs, ms) | {string.Join(" / ", killLatencies.Select(l => l.ToString("N0")))} | ≤ 100 ms |");
        Report(report);
    }
+
+    /// <summary>
+    ///     lmxopcua#798: the wall-clock half of the Shadow non-blocking contract, moved out of the default
+    ///     <see cref="ShadowModeTests"/> run (which now proves it causally with barriers). Published-path latency of a
+    ///     WARMED Calculation evaluator under <c>Scripting:Runner=Shadow</c> while its shadow keeps running away in the
+    ///     worker and being killed, against the same evaluator with no shadow. Compile/JIT is excluded by a warm-up
+    ///     pass. The 250 ms per-evaluation ceiling the default test used to assert is asserted here, opt-in only; the
+    ///     report records hardware and (where the OS exposes it) load average, so a MISS on a loaded box reads as such.
+    /// </summary>
+    [Fact]
+    public async Task Shadow_published_path_latency_while_the_shadow_runs_away()
+    {
+        RequireOptIn();
+        const string inWorker = "(string.Compare(\"a\", \"B\") > 0)"; // see ShadowModeTests.InWorker
+        const string runaway = $"if ({inWorker}) {{ while (true) {{ }} }} return (int)ctx.GetTag(\"x\").Value * 2;";
+        const string sibling = "return (int)ctx.GetTag(\"x\").Value + 100;";
+        const int count = 2_000;
+        var options = Scripts.Options(hardGrace: TimeSpan.FromMilliseconds(400), quarantineAfterKills: 1_000_000);
+        options.Runner = ScriptRunnerMode.Shadow;
+        await using var pool = Scripts.Runner(options, _runnerLog.CreateLogger());
+        using var shadow = new ShadowScriptRunner(pool, options, _runnerLog.CreateLogger());
+
+        Driver.Calculation.CalculationEvaluator Calc(IScriptRunner? runner)
+            => new(Microsoft.Extensions.Logging.Abstractions.NullLogger.Instance,
+                new ScriptRootLogger(new Serilog.LoggerConfiguration().CreateLogger()), TimeSpan.FromMilliseconds(300), scriptRunner: runner);
+
+        async Task<List<double>> Measure(Driver.Calculation.CalculationEvaluator evaluator)
+        {
+            for (var w = 0; w < 50; w++) // warm-up: compile + JIT both scripts in process
+            {
+                (await evaluator.EvaluateAsync("runaway", runaway, Scripts.Input("x", w), Ct)).Value.ShouldBe(w * 2);
+                (await evaluator.EvaluateAsync("sibling", sibling, Scripts.Input("x", w), Ct)).Value.ShouldBe(w + 100);
+            }
+            // A 5 ms trigger cadence for the phase, so shadow runs complete, run away and are killed DURING the
+            // measurement (back-to-back evaluations would all land behind the first shadow run, key_busy).
+            var samples = new List<double>(count);
+            var phaseEnd = Stopwatch.GetTimestamp() + (long)(Phase.TotalSeconds * Stopwatch.Frequency);
+            for (var n = 0; Stopwatch.GetTimestamp() < phaseEnd; n++)
+            {
+                await Task.Delay(5, Ct);
+                var key = n % 2 == 0 ? "runaway" : "sibling";
+                var t0 = Stopwatch.GetTimestamp();
+                var r = await evaluator.EvaluateAsync(key, n % 2 == 0 ? runaway : sibling, Scripts.Input("x", n), Ct);
+                samples.Add(Stopwatch.GetElapsedTime(t0).TotalMilliseconds);
+                r.Value.ShouldBe(n % 2 == 0 ? n * 2 : n + 100);
+            }
+            samples.Sort();
+            return samples;
+        }
+
+        List<double> reference, shadowed;
+        using (var plain = Calc(null)) reference = await Measure(plain);
+        using (var mirrored = Calc(shadow)) shadowed = await Measure(mirrored);
+        await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30));
+        var stats = shadow.Stats();
+        var load = LoadAverage();
+
+        var ceiling = TimeSpan.FromMilliseconds(250).TotalMilliseconds;
+        var report = new StringBuilder()
+            .AppendLine($"### Shadow published-path latency ({Env()}; load {load})").AppendLine()
+            .AppendLine("| Evaluator (warmed) | p50 ms | p99 ms | max ms |")
+            .AppendLine("|---|---:|---:|---:|")
+            .AppendLine($"| InProcess (no shadow) | {Percentile(reference, 0.50):F3} | {Percentile(reference, 0.99):F3} | {reference[^1]:F3} |")
+            .AppendLine($"| Shadow, runaway killed in the worker | {Percentile(shadowed, 0.50):F3} | {Percentile(shadowed, 0.99):F3} | {shadowed[^1]:F3} |")
+            .AppendLine().AppendLine($"shadow: compared {stats.Compared}, mismatched {stats.Mismatched}, unavailable {stats.ShadowUnavailable}, " +
+                                     $"dropped key_busy {stats.DroppedKeyBusy}, dropped behind {stats.DroppedBehind}; ceiling {ceiling:F0} ms per evaluation");
+        Report(report);
+        stats.Mismatched.ShouldBeGreaterThan(0, "precondition: the shadow really ran the runaway away (Failed [budget] vs published Ok)");
+        shadowed[^1].ShouldBeLessThan(ceiling, "a warmed published evaluation never waits for its shadow");
+    }
+
+    /// <summary>The host's 1/5/15-minute load average for the report: <c>/proc/loadavg</c> on Linux, <c>sysctl</c> on macOS.</summary>
+    private static string LoadAverage()
+    {
+        try
+        {
+            if (File.Exists("/proc/loadavg")) return File.ReadAllText("/proc/loadavg").Trim();
+            if (OperatingSystem.IsMacOS())
+            {
+                using var p = Process.Start(new ProcessStartInfo("/usr/sbin/sysctl", "-n vm.loadavg") { RedirectStandardOutput = true });
+                var text = p!.StandardOutput.ReadToEnd().Trim();
+                p.WaitForExit(2_000);
+                return text;
+            }
+        }
+        catch (Exception ex) when (ex is IOException or System.ComponentModel.Win32Exception or InvalidOperationException)
+        {
+            return "n/a (" + ex.GetType().Name + ")";
+        }
+        return "n/a";
+    }
 }