feat(diagnostics): VM emits trace events + CallScriptDispatches stat

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

engine/Age.Engine.Tests/CallScriptIntegrationTests.cs

@@ -31,8 +31,8 @@ public class CallScriptIntegrationTests
         var host = new NullHost();
         var vm = new VirtualMachine(script, t, host, null, provider);
         vm.Run();
-        Assert.Equal(2, host.CallScripts);       // ADDILLSUB + CALCREVISE both dispatched
+        Assert.Equal(2, vm.CallScriptDispatches); // ADDILLSUB + CALCREVISE both dispatched
-        Assert.Equal("exit", vm.HaltReason);     // subroutines returned; ADDILL reached its own exit
+        Assert.Equal("exit", vm.HaltReason);      // subroutines returned; ADDILL reached its own exit
     }
 
     [Fact]

engine/Age.Engine.Tests/CallScriptTests.cs

@@ -58,12 +58,13 @@ public class CallScriptTests
             OP_MOV, 3, 0x11, 3, 0x10,
             OP_EXIT);
         var host = new NullHost();
-        var vm = new VirtualMachine(caller, t, host, null, new MapProvider(new() { [5] = callee }));
+        var sink = new RecordingTraceSink();
+        var vm = new VirtualMachine(caller, t, host, null, new MapProvider(new() { [5] = callee }), sink);
         vm.Run();
         Assert.Equal(7, vm.Globals[0x10]);           // callee wrote a shared global
         Assert.Equal(7, vm.Globals[0x11]);           // caller read it AFTER the call returned
         Assert.Equal("exit", vm.HaltReason);         // top-level exit
-        Assert.Contains(5L, host.Calls);             // host notified
+        Assert.Contains(5L, sink.CallScriptIds);     // dispatch observed via the trace sink
     }
 
     [Fact]
@@ -72,10 +73,11 @@ public class CallScriptTests
         var t = Table();
         var caller = Asm(t, "CALLER", OP_CALLSCRIPT, 0, 5, OP_EXIT);
         var host = new NullHost();
-        var vm = new VirtualMachine(caller, t, host, null, null);   // no provider
+        var sink = new RecordingTraceSink();
+        var vm = new VirtualMachine(caller, t, host, null, null, sink);   // no provider
         vm.Run();
         Assert.Equal("exit", vm.HaltReason);        // did not halt on the call; stub + continue
-        Assert.Contains(5L, host.Calls);
+        Assert.Contains(5L, sink.CallScriptIds);
     }
 
     [Fact]

engine/Age.Engine.Tests/TestSupport.cs

@@ -1,4 +1,6 @@
 using System.Collections.Generic;
+using System.Linq;
+using Age.Engine.Diagnostics;
 using Age.Engine.Hosting;
 using Age.Engine.Model;
 
@@ -36,3 +38,14 @@ internal sealed class AnyProvider : IScriptProvider
     public AnyProvider(Script s) => _s = s;
     public Script? GetById(long id) => _s;
 }
+
+/// <summary>Captures every trace event for assertions; TracingSteps is settable so a test can
+/// exercise the Step gate both ways.</summary>
+internal sealed class RecordingTraceSink : ITraceSink
+{
+    public bool TracingSteps { get; init; }
+    public readonly List<TraceEvent> Events = new();
+    public void Emit(in TraceEvent e) => Events.Add(e);
+    public List<long> CallScriptIds =>
+        Events.Where(e => e.Kind == TraceEventKind.CallScript).Select(e => e.Id).ToList();
+}

engine/Age.Engine.Tests/TraceSinkTests.cs

@@ -1,10 +1,17 @@
+using System;
+using System.Collections.Generic;
 using System.IO;
+using System.Linq;
 using Age.Engine.Diagnostics;
 using Age.Engine.Model;
+using Age.Engine.Sys4;
+using Age.Engine.Vm;
 using Xunit;
 
 public class TraceSinkTests
 {
+    private static OpcodeTable Table() => OpcodeTableJson.Load(Paths.OpcodesJson);
+
     [Fact]
     public void FactoriesSetKindAndFields()
     {
@@ -41,4 +48,49 @@ public class TraceSinkTests
         Assert.Contains("call-script 0x1ab =ADDITEM (resolved)", outp);
         Assert.Contains("halt: exit @ 27994 steps", outp);
     }
+
+    [Fact]
+    public void VmEmitsFrameCallScriptAndHaltEvents()
+    {
+        var t = Table();
+        // callee: exit.  caller: call-script 5 ; exit.
+        var callee = ScriptAssembler.Assemble(t, "CALLEE",
+            new List<(int, Operand[])> { (0x2, Array.Empty<Operand>()) }, Array.Empty<string>());
+        var caller = ScriptAssembler.Assemble(t, "CALLER",
+            new List<(int, Operand[])> { (0x3, new[] { new Operand(0, 5) }), (0x2, Array.Empty<Operand>()) },
+            Array.Empty<string>());
+        var sink = new RecordingTraceSink();
+        var vm = new VirtualMachine(caller, t, new RecordingHost(), null,
+                                    new MapProvider(new() { [5] = callee }), sink);
+        vm.Run();
+
+        var kinds = sink.Events.Select(e => e.Kind).ToList();
+        Assert.Equal(TraceEventKind.FrameEnter, kinds[0]);                 // caller enters first
+        Assert.Equal(TraceEventKind.Halt, kinds[^1]);                      // halt is last
+        Assert.Equal(2, sink.Events.Count(e => e.Kind == TraceEventKind.FrameEnter));  // caller + callee
+        Assert.Equal(2, sink.Events.Count(e => e.Kind == TraceEventKind.FrameExit));
+        Assert.Contains(5L, sink.CallScriptIds);
+        Assert.Equal(1, vm.CallScriptDispatches);
+    }
+
+    [Fact]
+    public void StepEventsGatedByTracingSteps()
+    {
+        var t = Table();
+        // mov g[0x10]=7 ; exit  => 2 executed instructions.
+        var body = new List<(int, Operand[])>
+        {
+            (0x55, new[] { new Operand(3, 0x10), new Operand(0, 7) }),
+            (0x2, Array.Empty<Operand>()),
+        };
+        var s = ScriptAssembler.Assemble(t, "S", body, Array.Empty<string>());
+
+        var off = new RecordingTraceSink { TracingSteps = false };
+        new VirtualMachine(s, t, new RecordingHost(), null, null, off).Run();
+        Assert.Empty(off.Events.Where(e => e.Kind == TraceEventKind.Step));
+
+        var on = new RecordingTraceSink { TracingSteps = true };
+        new VirtualMachine(s, t, new RecordingHost(), null, null, on).Run();
+        Assert.Equal(2, on.Events.Count(e => e.Kind == TraceEventKind.Step));
+    }
 }

engine/Age.Engine/Vm/GameSession.cs

@@ -1,4 +1,5 @@
 using System.Text.Json;
+using Age.Engine.Diagnostics;
 using Age.Engine.Hosting;
 using Age.Engine.Model;
 
@@ -25,9 +26,10 @@ public sealed class GameSession
 
     /// <summary>Run one scene: seed a fresh VM from session state, execute, merge final state back.</summary>
     public SceneResult RunScene(Script script, OpcodeTable table, IHost host,
-                                VmOptions? options = null, IScriptProvider? provider = null)
+                                VmOptions? options = null, IScriptProvider? provider = null,
+                                ITraceSink? sink = null)
     {
-        var vm = new VirtualMachine(script, table, host, options, provider);
+        var vm = new VirtualMachine(script, table, host, options, provider, sink);
         foreach (var kv in Globals) vm.Globals[kv.Key] = kv.Value;
         foreach (var kv in GlobalStrings) vm.GlobalStrings[kv.Key] = kv.Value;
 

engine/Age.Engine/Vm/VirtualMachine.cs

@@ -1,3 +1,4 @@
+using Age.Engine.Diagnostics;
 using Age.Engine.Hosting;
 using Age.Engine.Model;
 namespace Age.Engine.Vm;
@@ -17,6 +18,8 @@ public sealed class VirtualMachine
     private readonly IScriptProvider? _provider;
     private ExecFrame _cur = null!;
     private int _depth;
+    private readonly ITraceSink _sink;
+    public long CallScriptDispatches { get; private set; }
 
     public Dictionary<int, long> Globals { get; } = new();
     public Dictionary<int, string> GlobalStrings { get; } = new();
@@ -24,8 +27,10 @@ public sealed class VirtualMachine
     public string? HaltReason { get; private set; }
     public long Steps { get; private set; }
 
-    public VirtualMachine(Script s, OpcodeTable t, IHost host, VmOptions? o = null, IScriptProvider? provider = null)
+    public VirtualMachine(Script s, OpcodeTable t, IHost host, VmOptions? o = null,
-    { _s = s; _t = t; _host = host; _o = o ?? new VmOptions(); _provider = provider; }
+                          IScriptProvider? provider = null, ITraceSink? sink = null)
+    { _s = s; _t = t; _host = host; _o = o ?? new VmOptions(); _provider = provider;
+      _sink = sink ?? NullTraceSink.Instance; }
 
     private static long Gi(Dictionary<int, long> d, int k) => d.TryGetValue(k, out var v) ? v : 0;
     private static string Gs(Dictionary<int, string> d, int k) => d.TryGetValue(k, out var v) ? v : "";
@@ -97,26 +102,30 @@ public sealed class VirtualMachine
     public void Run(int entryOffset = 0)
     {
         var top = new ExecFrame(_s, _s.IndexByOffset.TryGetValue(entryOffset, out var idx) ? idx : 0);
-        var outcome = RunFrame(top);
+        var outcome = RunFrame(top, FrameCause.TopScene);
         if (outcome == FrameOutcome.RanOff) HaltReason ??= "pc-out-of-range";
         else if (outcome == FrameOutcome.Returned) HaltReason ??= "exit";
         // Halted: HaltReason already set by the halting op.
+        _sink.Emit(TraceEvent.Halt(HaltReason ?? "unknown", Steps));
     }
 
-    private FrameOutcome RunFrame(ExecFrame frame)
+    private FrameOutcome RunFrame(ExecFrame frame, FrameCause cause, long callId = 0)
     {
         var prev = _cur; _cur = frame; _depth++;
+        _sink.Emit(TraceEvent.FrameEnter(frame.Script.Name, _depth, cause, callId));
         var outcome = FrameOutcome.RanOff;
         int pc = frame.Pc;
         while (pc >= 0 && pc < frame.Script.Instructions.Count)
         {
             if (Steps >= _o.MaxSteps) { HaltReason ??= "STEP-LIMIT"; outcome = FrameOutcome.Halted; break; }
             Steps++;
+            if (_sink.TracingSteps) _sink.Emit(TraceEvent.Step(pc, frame.Script.Instructions[pc], _depth));
             int next = Step(frame.Script.Instructions[pc], pc);
             if (next == FRAME_RETURN) { outcome = FrameOutcome.Returned; break; }
             if (next == HALT) { outcome = FrameOutcome.Halted; break; }
             pc = next;
         }
+        _sink.Emit(TraceEvent.FrameExit(frame.Script.Name, _depth, outcome.ToString()));
         _cur = prev; _depth--;
         return outcome;
     }
@@ -170,13 +179,18 @@ public sealed class VirtualMachine
             case "call-script":
             {
                 long id = a.Count > 0 ? Read(a[0]) : 0;
-                _host.CallScript(id);                       // notify (diagnostics)
+                CallScriptDispatches++;
-                if (_provider == null) return pc + 1;       // no script source: prior stub behavior
+                if (_provider == null)
+                {
+                    _sink.Emit(TraceEvent.CallScript(id, null));   // stub mode: notify only, no child pushed
+                    return pc + 1;
+                }
                 if (_depth >= _o.CallDepthCap) { HaltReason ??= "call-depth-exceeded"; return HALT; }
                 var child = _provider.GetById(id);
+                _sink.Emit(TraceEvent.CallScript(id, child?.Name));
                 if (child == null) { HaltReason ??= $"callscript-unresolved:0x{id:x}"; return HALT; }
                 var entry = child.IndexByOffset.TryGetValue(0, out var ci) ? ci : 0;
-                var outcome = RunFrame(new ExecFrame(child, entry));
+                var outcome = RunFrame(new ExecFrame(child, entry), FrameCause.CallScript, id);
                 if (outcome == FrameOutcome.Halted) return HALT;   // propagate whole-VM halt up
                 return pc + 1;                                      // Returned / RanOff: resume caller
             }
@@ -212,7 +226,7 @@ public sealed class VirtualMachine
             case "play-bgm":   _host.PlayBgm(Read(a[0])); return pc + 1;
             case "play-voice": _host.PlayVoice(Read(a[0])); return pc + 1;
             default:
-                _host.OnStub(op); return pc + 1;
+                _sink.Emit(TraceEvent.Stub(op, pc)); return pc + 1;
         }
     }
 }