diff --git a/engine/Age.Engine.Tests/CallScriptIntegrationTests.cs b/engine/Age.Engine.Tests/CallScriptIntegrationTests.cs index b8b8647..1351cd1 100644 --- a/engine/Age.Engine.Tests/CallScriptIntegrationTests.cs +++ b/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("exit", vm.HaltReason); // subroutines returned; ADDILL reached its own exit + Assert.Equal(2, vm.CallScriptDispatches); // ADDILLSUB + CALCREVISE both dispatched + Assert.Equal("exit", vm.HaltReason); // subroutines returned; ADDILL reached its own exit } [Fact] diff --git a/engine/Age.Engine.Tests/CallScriptTests.cs b/engine/Age.Engine.Tests/CallScriptTests.cs index 170c0e5..aca7f6f 100644 --- a/engine/Age.Engine.Tests/CallScriptTests.cs +++ b/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] diff --git a/engine/Age.Engine.Tests/TestSupport.cs b/engine/Age.Engine.Tests/TestSupport.cs index d2211c0..cba1d6b 100644 --- a/engine/Age.Engine.Tests/TestSupport.cs +++ b/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; } + +/// Captures every trace event for assertions; TracingSteps is settable so a test can +/// exercise the Step gate both ways. +internal sealed class RecordingTraceSink : ITraceSink +{ + public bool TracingSteps { get; init; } + public readonly List Events = new(); + public void Emit(in TraceEvent e) => Events.Add(e); + public List CallScriptIds => + Events.Where(e => e.Kind == TraceEventKind.CallScript).Select(e => e.Id).ToList(); +} diff --git a/engine/Age.Engine.Tests/TraceSinkTests.cs b/engine/Age.Engine.Tests/TraceSinkTests.cs index d3cbb68..efee966 100644 --- a/engine/Age.Engine.Tests/TraceSinkTests.cs +++ b/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()) }, Array.Empty()); + var caller = ScriptAssembler.Assemble(t, "CALLER", + new List<(int, Operand[])> { (0x3, new[] { new Operand(0, 5) }), (0x2, Array.Empty()) }, + Array.Empty()); + 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()), + }; + var s = ScriptAssembler.Assemble(t, "S", body, Array.Empty()); + + 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)); + } } diff --git a/engine/Age.Engine/Vm/GameSession.cs b/engine/Age.Engine/Vm/GameSession.cs index 0507c8e..c909eee 100644 --- a/engine/Age.Engine/Vm/GameSession.cs +++ b/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 /// Run one scene: seed a fresh VM from session state, execute, merge final state back. 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; diff --git a/engine/Age.Engine/Vm/VirtualMachine.cs b/engine/Age.Engine/Vm/VirtualMachine.cs index 57b05bc..87989af 100644 --- a/engine/Age.Engine/Vm/VirtualMachine.cs +++ b/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 Globals { get; } = new(); public Dictionary 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) - { _s = s; _t = t; _host = host; _o = o ?? new VmOptions(); _provider = provider; } + public VirtualMachine(Script s, OpcodeTable t, IHost host, VmOptions? o = null, + 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 d, int k) => d.TryGetValue(k, out var v) ? v : 0; private static string Gs(Dictionary 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) - if (_provider == null) return pc + 1; // no script source: prior stub behavior + CallScriptDispatches++; + 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; } } }