diff --git a/docs/tools-reference.md b/docs/tools-reference.md index 75f51a3..7f54ea3 100644 --- a/docs/tools-reference.md +++ b/docs/tools-reference.md @@ -94,6 +94,24 @@ gated). Absent ⇒ no tracing (`NullTraceSink`, byte-identical run). This is an frontends consume it instead of reimplementing a diagnostic `IHost`. Example: `play SC0000.BIN --trace` shows `» SC0000.BIN (enter, TopScene)` → `call-script 0xee =INPUTNAME.BIN (resolved)` → `halt: …`. +**Aggregating / filtered diagnostics** (added 2026-07-08 after a full `--trace-steps` dump proved unusable +at 2.5M lines). All observe-only → parity preserved; all on `run`/`play`/`sweep`: +- **`--trace-histogram`** — instead of a per-line dump, aggregate **execution counts per opcode** and per + **call-site `(script:pc)`** (with a sample first operand), dumped sorted after the run. Answers "how many + times did op X run, and from where?" directly. This is what pinpointed, in one line, that the 493,175 + `sleep`s in a headless `play` come from `INPUTNAME.BIN:0x1c3` — a name-entry input-poll loop that spins + only because headless has no keyboard — not from the opening. Step lines are attributed to the **real + running script** (nested call-script frames included), the "which script is this pc in?" answer a bare + step trace can't give. +- **`--trace-ops `** — filter the text trace to only the named ops (mnemonics or `0x` hex, e.g. + `--trace-ops sleep,draw-texture,wait-for-input`), each line tagged `script:pc`. The ordered interleaving of + a few ops of interest without the flood. +- `--trace-file ` now creates the parent directory if missing. +- **Godot** accepts **`--trace-histogram `** — profile the **real** run (headless flow diverges because + `wait-for-input` is a no-op there; the real run to page 1 is ~562 steps with **0** sleeps vs headless's 2M + steps / 493k sleeps). Dumped when the scene ends or the window closes. e.g. + `godot --path godot -- --boot --shot out/p1.png --trace-histogram out/hist.txt`. + **Godot frontend** (`S:/Godot/Godot_v4.7…`; project = `godot/`). Toolchain: `godot --headless --path godot --import` → `dotnet build godot/Himegari.csproj` → `godot [--headless] --path godot [-- ]`. Plays the real bytecode with call-script execution on (subroutines run live). `--headless` can't render @@ -104,6 +122,7 @@ texture ops (no GPU context) — run windowed for real scenes. User args (after - `--boot` — run SYSTEM4's state prefix (`INITCONFIG/INIT2/INIT`) via `GameSession` before the scene, so scene-assumed boot state (chiefly INIT2's gfx handle array) is present. **Needed for the gfx CGs to render** (without it the opening event CGs collapse/drift). e.g. `godot --path godot -- --boot`. - `--shot [--shot-page N]` — capture page N to a PNG then quit (dev screenshot). At scene end it also prints the call-scripts executed as nested frames. - `--shot-sequence [--frames N]` — dump one PNG per rendered frame (`frame_0000.png…`, default N=180 ≈ 3s @60fps) then quit, auto-advancing past input waits. Verifies **time-based (sleep-paced) effects** — e.g. the opening `AE*` burst — as distinct frames, which a single `--shot` cannot. CPU/IO-heavy by design (a PNG every frame); a dev diagnostic, not a normal run. e.g. `godot --path godot -- --boot --shot-sequence out/seq --frames 300`. +- `--sleep-scale ` — multiply every `sleep` (op 0xc8) duration by `f` (default 1.0). The authentic opening burst is only ~2 s, too fast to eyeball live; `--sleep-scale 5` stretches it to ~10 s so the paced sequence (arcane `AE*` → character CGs → settled BG) is watchable. Debug-only; leave at 1.0 for real playback. ## Asset resolution / graphics diff --git a/engine/Age.Cli/Program.cs b/engine/Age.Cli/Program.cs index eb0655b..4c58a5f 100644 --- a/engine/Age.Cli/Program.cs +++ b/engine/Age.Cli/Program.cs @@ -11,17 +11,9 @@ var table = OpcodeTableJson.Load(Paths.OpcodesJson); // `trace` stays provider-less on purpose (the base-ISA offset oracle). var provider = Sys4ScriptProvider.Load(table); -// --trace [--trace-file ] [--trace-steps] → a TextTraceSink to console or file; else inert. -static ITraceSink BuildSink(string[] a, OpcodeTable tbl) -{ - if (!a.Contains("--trace")) return NullTraceSink.Instance; - bool steps = a.Contains("--trace-steps"); - int fi = Array.IndexOf(a, "--trace-file"); - TextWriter w = (fi >= 0 && fi + 1 < a.Length) - ? new StreamWriter(a[fi + 1]) { AutoFlush = true } - : Console.Out; - return new TextTraceSink(w, tbl, steps); -} +// Diagnostics flags (see the TraceSetup class below): --trace (text flow), --trace-steps (every op), +// --trace-ops (only these mnemonics/hex, tagged with their script), --trace-histogram (op + +// call-site execution counts, dumped after the run), --trace-file (write to a file, else console). if (args.Length == 0) { Console.WriteLine("usage: run | trace "); return 1; } @@ -29,8 +21,10 @@ if (args[0] == "run") { var script = Sys4Loader.Load(args[1], table); var runHost = new CaptureHost(); - var vm = new VirtualMachine(script, table, runHost, null, provider, BuildSink(args, table)); + using var trace = TraceSetup.Build(args, table); + var vm = new VirtualMachine(script, table, runHost, null, provider, trace.Sink); vm.Run(); + trace.Report(); Console.WriteLine($"{Path.GetFileName(args[1])}: {vm.Steps} steps, {vm.Emitted.Count} show-text, {vm.CallScriptDispatches} call-scripts (halt: {vm.HaltReason})"); foreach (var (off, text, scr) in vm.Emitted.Take(30)) Console.WriteLine($" [{scr} 0x{off:x}] {text}"); var sources = vm.Emitted.Select(e => e.Script).Distinct().ToList(); @@ -133,13 +127,15 @@ if (args[0] == "play") session.Seed(k, v); } long totalLines = 0; + using var trace = TraceSetup.Build(args, table); // one sink across the sequence (histogram aggregates) foreach (var name in scenes) { var script = Sys4Loader.Load(scripts[name.ToUpperInvariant()], table); - var r = session.RunScene(script, table, new CaptureHost(), null, provider, BuildSink(args, table)); + var r = session.RunScene(script, table, new CaptureHost(), null, provider, trace.Sink); totalLines += r.Emitted.Count; Console.WriteLine($" {name,-14} {r.Emitted.Count,4} lines, {r.Steps,7} steps (halt: {r.Halt})"); } + trace.Report(); Console.WriteLine($"total: {totalLines} lines across {scenes.Count} scene(s); {session.Globals.Count} globals carried"); if (saveState != null) { File.WriteAllText(saveState, session.ToJson()); Console.WriteLine($"[state] saved -> {saveState}"); } return 0; @@ -198,15 +194,17 @@ if (args[0] == "sweep") var haltDist = new SortedDictionary(StringComparer.Ordinal); long totalLines = 0; var anomalies = new List(); + using var trace = TraceSetup.Build(args, table); // one sink across the corpus (histogram aggregates) foreach (var name in names) { var session = Fresh(); - var r = session.RunScene(Sys4Loader.Load(scripts[name], table), table, new CaptureHost(), null, provider, BuildSink(args, table)); + var r = session.RunScene(Sys4Loader.Load(scripts[name], table), table, new CaptureHost(), null, provider, trace.Sink); var halt = r.Halt ?? "null"; haltDist[halt] = haltDist.GetValueOrDefault(halt) + 1; totalLines += r.Emitted.Count; if (halt != "exit") anomalies.Add($"{name}: {r.Emitted.Count} lines, halt={halt}"); } + trace.Report(); Console.WriteLine($"swept {names.Count} scenes{(boot ? " (booted)" : "")}: {totalLines} total lines"); Console.WriteLine("halt distribution: " + string.Join(", ", haltDist.Select(kv => $"{kv.Key}={kv.Value}"))); if (anomalies.Count > 0) { Console.WriteLine($"non-exit halts ({anomalies.Count}):"); foreach (var a in anomalies) Console.WriteLine(" " + a); } @@ -231,6 +229,67 @@ if (args[0] == "trace") } Console.WriteLine("unknown command"); return 1; +// Assembles the diagnostic sink from CLI flags and owns the file writer + the post-run histogram dump. +// Inert (NullTraceSink) unless a --trace* flag is present, so normal runs are untouched (parity). +sealed class TraceSetup : IDisposable +{ + public ITraceSink Sink { get; private init; } = NullTraceSink.Instance; + private HistogramTraceSink? _hist; + private TextWriter? _file; // owned file writer; null => console + private OpcodeTable? _table; + + public static TraceSetup Build(string[] a, OpcodeTable tbl) + { + bool text = a.Contains("--trace"); + bool steps = a.Contains("--trace-steps"); + bool hist = a.Contains("--trace-histogram"); + string? opsCsv = ArgVal(a, "--trace-ops"); + if (!text && !hist && opsCsv == null) return new TraceSetup(); // inert + + int fi = Array.IndexOf(a, "--trace-file"); + TextWriter? file = null; + if (fi >= 0 && fi + 1 < a.Length) + { + var path = a[fi + 1]; + var dir = Path.GetDirectoryName(path); + if (!string.IsNullOrEmpty(dir)) Directory.CreateDirectory(dir); // robust: create parent dir + file = new StreamWriter(path) { AutoFlush = true }; + } + TextWriter w = file ?? Console.Out; + + HashSet? filter = null; + if (opsCsv != null) + { + filter = new HashSet(); + foreach (var tok in opsCsv.Split(',', StringSplitOptions.RemoveEmptyEntries | StringSplitOptions.TrimEntries)) + { + int? op = tok.StartsWith("0x") ? Convert.ToInt32(tok, 16) : tbl.ByLabel(tok); + if (op is int o) filter.Add(o); + else Console.Error.WriteLine($"--trace-ops: unknown op '{tok}' (ignored)"); + } + } + + var sinks = new List(); + if (text || filter != null) sinks.Add(new TextTraceSink(w, tbl, steps, filter)); + HistogramTraceSink? h = null; + if (hist) { h = new HistogramTraceSink(); sinks.Add(h); } + + return new TraceSetup + { + Sink = sinks.Count == 1 ? sinks[0] : new CompositeTraceSink(sinks.ToArray()), + _hist = h, _file = file, _table = tbl, + }; + } + + /// After the run, dump the histogram (if enabled). Text/filter output already streamed live. + public void Report() => _hist?.WriteReport(_file ?? Console.Out, _table); + + public void Dispose() { _file?.Flush(); _file?.Dispose(); } + + private static string? ArgVal(string[] a, string key) + { int i = Array.IndexOf(a, key); return i >= 0 && i + 1 < a.Length ? a[i + 1] : null; } +} + sealed class AudioTraceHost : IHost { private readonly ResourceMap _res; diff --git a/engine/Age.Engine.Tests/DiagnosticsSinkTests.cs b/engine/Age.Engine.Tests/DiagnosticsSinkTests.cs new file mode 100644 index 0000000..c0b298d --- /dev/null +++ b/engine/Age.Engine.Tests/DiagnosticsSinkTests.cs @@ -0,0 +1,80 @@ +using System; +using System.Collections.Generic; +using System.IO; +using Age.Engine.Diagnostics; +using Age.Engine.Model; +using Age.Engine.Sys4; +using Age.Engine.Vm; +using Xunit; + +public class DiagnosticsSinkTests +{ + private static OpcodeTable Table() => OpcodeTableJson.Load(Paths.OpcodesJson); + + [Fact] + public void OpcodeTable_ByLabel_ResolvesMnemonicToOpcode() + { + var t = Table(); + Assert.Equal(0xc8, t.ByLabel("sleep")); + Assert.Equal(0x55, t.ByLabel("mov")); + Assert.Null(t.ByLabel("no-such-op")); + } + + [Fact] + public void Histogram_CountsOps_AndAttributesCallSitesToTheRightScript() + { + var t = Table(); + // callee SUB: mov g[0x20]=99 ; exit. caller MAIN: mov g[0x10]=1 ; call-script 5 ; exit. + var sub = ScriptAssembler.Assemble(t, "SUB", + new List<(int, Operand[])> { (0x55, new[] { new Operand(3, 0x20), new Operand(0, 99) }), + (0x2, Array.Empty()) }, Array.Empty()); + var main = ScriptAssembler.Assemble(t, "MAIN", + new List<(int, Operand[])> { (0x55, new[] { new Operand(3, 0x10), new Operand(0, 1) }), + (0x3, new[] { new Operand(0, 5) }), + (0x2, Array.Empty()) }, Array.Empty()); + + var hist = new HistogramTraceSink(); + new VirtualMachine(main, t, new RecordingHost(), null, new MapProvider(new() { [5] = sub }), hist).Run(); + + Assert.Equal(2, hist.OpCount(0x55)); // one mov in each frame + Assert.Equal(2, hist.OpCount(0x2)); // one exit in each frame + + var sw = new StringWriter(); + hist.WriteReport(sw, t); + var report = sw.ToString(); + // Same pc (0) in two scripts must be two distinct call-sites, each tagged with its script + arg0. + Assert.Contains("MAIN:0x0 mov arg0=16", report); // 0x10 + Assert.Contains("SUB:0x0 mov arg0=32", report); // 0x20 + } + + [Fact] + public void TextSink_OpFilter_ShowsOnlyFilteredOps_TaggedWithScript() + { + var t = Table(); + var scene = ScriptAssembler.Assemble(t, "F", + new List<(int, Operand[])> { (0x55, new[] { new Operand(3, 0x10), new Operand(0, 1) }), // mov + (0xc8, new[] { new Operand(0, 200) }), // sleep + (0x2, Array.Empty()) }, Array.Empty()); + var sw = new StringWriter(); + var filter = new HashSet { 0xc8 }; + var sink = new TextTraceSink(sw, t, includeSteps: false, opFilter: filter); + new VirtualMachine(scene, t, new RecordingHost(), null, null, sink).Run(); + + var outp = sw.ToString(); + Assert.Contains("F:0001 sleep", outp); // filtered op appears, tagged with its script + pc + Assert.DoesNotContain(" mov ", outp); // non-filtered op is suppressed + } + + [Fact] + public void Composite_FansOut_AndTracingStepsIsAnyChild() + { + var a = new RecordingTraceSink { TracingSteps = false }; + var b = new RecordingTraceSink { TracingSteps = true }; + var c = new CompositeTraceSink(a, b); + Assert.True(c.TracingSteps); // any child needs steps + + c.Emit(TraceEvent.Halt("x", 3)); + Assert.Single(a.Events); + Assert.Single(b.Events); + } +} diff --git a/engine/Age.Engine/Diagnostics/CompositeTraceSink.cs b/engine/Age.Engine/Diagnostics/CompositeTraceSink.cs new file mode 100644 index 0000000..421b7c8 --- /dev/null +++ b/engine/Age.Engine/Diagnostics/CompositeTraceSink.cs @@ -0,0 +1,17 @@ +namespace Age.Engine.Diagnostics; + +/// Fans one event stream out to several sinks, so e.g. a live text trace and an aggregating +/// histogram (or Godot's call-script queue) can run together. TracingSteps is true if ANY child needs +/// steps, so the VM's cheap gate stays correct. +public sealed class CompositeTraceSink : ITraceSink +{ + private readonly ITraceSink[] _sinks; + public CompositeTraceSink(params ITraceSink[] sinks) => _sinks = sinks; + + public bool TracingSteps + { + get { foreach (var s in _sinks) if (s.TracingSteps) return true; return false; } + } + + public void Emit(in TraceEvent e) { foreach (var s in _sinks) s.Emit(in e); } +} diff --git a/engine/Age.Engine/Diagnostics/HistogramTraceSink.cs b/engine/Age.Engine/Diagnostics/HistogramTraceSink.cs new file mode 100644 index 0000000..f916c93 --- /dev/null +++ b/engine/Age.Engine/Diagnostics/HistogramTraceSink.cs @@ -0,0 +1,72 @@ +using System.Collections.Generic; +using System.IO; +using System.Linq; +using Age.Engine.Model; +namespace Age.Engine.Diagnostics; + +/// Aggregating diagnostic sink: counts opcode executions overall and per call-site +/// (script, pc), keeping a sample first operand. Answers "how many times did op X run, and from +/// where?" directly — the question that, this session, took a 2.5M-line text dump + grep/awk to +/// answer (sleep ran 493,175× from one call-site). Observe-only → trace parity preserved. +/// +/// Thread-safe: Emit runs on the VM thread; WriteReport/OpCount may be read from another thread +/// (e.g. the Godot main thread at scene end), so both take a lock. +public sealed class HistogramTraceSink : TraceSinkBase +{ + public override bool TracingSteps => true; // needs every Step + + private readonly object _lock = new(); + private readonly Dictionary _opCounts = new(); + private readonly Dictionary<(string Script, int Pc, int Op), Site> _sites = new(); + private long _totalSteps; + + private sealed class Site { public long Count; public long SampleArg0; public bool HasArg; } + + protected override void OnEvent(in TraceEvent e) + { + if (e.Kind != TraceEventKind.Step) return; + var args = e.Ins?.Args; + bool hasArg = args is { Count: > 0 }; + long arg0 = hasArg ? args![0].Value : 0; + var key = (CurrentScript, e.Pc, e.Opcode); + lock (_lock) + { + _totalSteps++; + _opCounts[e.Opcode] = _opCounts.GetValueOrDefault(e.Opcode) + 1; + if (!_sites.TryGetValue(key, out var s)) { s = new Site(); _sites[key] = s; } + s.Count++; + if (hasArg) { s.SampleArg0 = arg0; s.HasArg = true; } + } + } + + /// How many times the given opcode executed. + public long OpCount(int op) { lock (_lock) return _opCounts.GetValueOrDefault(op); } + + /// Total instructions executed (all frames). + public long TotalSteps { get { lock (_lock) return _totalSteps; } } + + /// Write a sorted report: the opcode histogram, then the hottest call-sites (each tagged + /// with the script it ran in and a sample first operand). + public void WriteReport(TextWriter w, OpcodeTable? table = null, int topSites = 50) + { + string Mn(int op) => table?.Label(op) is { Length: > 0 } l ? l : $"0x{op:x}"; + lock (_lock) + { + w.WriteLine($"=== opcode execution histogram — {_totalSteps} steps, {_opCounts.Count} distinct ops ==="); + w.WriteLine($"{"count",12} op mnemonic"); + foreach (var kv in _opCounts.OrderByDescending(k => k.Value).ThenBy(k => k.Key)) + w.WriteLine($"{kv.Value,12} 0x{kv.Key:x3} {Mn(kv.Key)}"); + + w.WriteLine($"=== hottest call-sites (top {topSites} of {_sites.Count}) ==="); + w.WriteLine($"{"count",12} script:pc mnemonic sample-arg0"); + foreach (var kv in _sites.OrderByDescending(k => k.Value.Count).ThenBy(k => k.Key.Script).Take(topSites)) + { + var (script, pc, op) = kv.Key; + var s = kv.Value; + string arg = s.HasArg ? $" arg0={s.SampleArg0}" : ""; + w.WriteLine($"{s.Count,12} {script}:0x{pc:x} {Mn(op)}{arg}"); + } + w.Flush(); + } + } +} diff --git a/engine/Age.Engine/Diagnostics/TextTraceSink.cs b/engine/Age.Engine/Diagnostics/TextTraceSink.cs index ccad598..d75d70f 100644 --- a/engine/Age.Engine/Diagnostics/TextTraceSink.cs +++ b/engine/Age.Engine/Diagnostics/TextTraceSink.cs @@ -1,23 +1,29 @@ +using System.Collections.Generic; +using System.Linq; using Age.Engine.Model; namespace Age.Engine.Diagnostics; -/// The one built-in formatter: writes each event as a deterministic text line to a -/// TextWriter (Console.Out or a file). Indents by frame depth. If an OpcodeTable is supplied, Step -/// lines show the mnemonic; otherwise the raw opcode. Step lines only appear when includeSteps is set. -public sealed class TextTraceSink : ITraceSink +/// The built-in text formatter: writes each event as a deterministic line to a TextWriter +/// (Console.Out or a file), indented by frame depth. Step lines are tagged with the current script +/// (the "which script is this op in" answer) and, when is set, only ops in +/// the filter are printed — so you can watch just sleep/draw-texture/wait-for-input in execution order +/// instead of a multi-million-line flood. If an OpcodeTable is supplied, Step lines show the mnemonic. +public sealed class TextTraceSink : TraceSinkBase { private readonly TextWriter _w; private readonly OpcodeTable? _table; private readonly bool _steps; + private readonly HashSet? _opFilter; // null = all ops; else only these ops' Step/Stub lines - public TextTraceSink(TextWriter writer, OpcodeTable? table = null, bool includeSteps = false) - { _w = writer; _table = table; _steps = includeSteps; } + public TextTraceSink(TextWriter writer, OpcodeTable? table = null, bool includeSteps = false, + HashSet? opFilter = null) + { _w = writer; _table = table; _opFilter = opFilter; _steps = includeSteps || opFilter != null; } - public bool TracingSteps => _steps; + public override bool TracingSteps => _steps; - public void Emit(in TraceEvent e) + protected override void OnEvent(in TraceEvent e) { - string indent = new string(' ', Math.Max(0, e.Depth - 1) * 2); + string indent = new string(' ', System.Math.Max(0, e.Depth - 1) * 2); switch (e.Kind) { case TraceEventKind.FrameEnter: @@ -25,12 +31,14 @@ public sealed class TextTraceSink : ITraceSink case TraceEventKind.FrameExit: _w.WriteLine($"{indent}« {e.Name} ({e.Text})"); break; case TraceEventKind.Step: - _w.WriteLine($"{indent} {e.Pc:x4} {Mnemonic(e.Opcode)} {Args(e.Ins)}"); break; + if (_opFilter != null && !_opFilter.Contains(e.Opcode)) break; + _w.WriteLine($"{indent} {CurrentScript}:{e.Pc:x4} {Mnemonic(e.Opcode)} {Args(e.Ins)}"); break; case TraceEventKind.CallScript: _w.WriteLine($"{indent} call-script 0x{e.Id:x} ={e.Name ?? "?"} " + $"({(e.Name != null ? "resolved" : "stub/unresolved")})"); break; case TraceEventKind.Stub: - _w.WriteLine($"{indent} {e.Pc:x4} STUB op=0x{e.Opcode:x}"); break; + if (_opFilter != null && !_opFilter.Contains(e.Opcode)) break; + _w.WriteLine($"{indent} {CurrentScript}:{e.Pc:x4} STUB op=0x{e.Opcode:x}"); break; case TraceEventKind.Halt: _w.WriteLine($"halt: {e.Text} @ {e.Steps} steps"); break; } diff --git a/engine/Age.Engine/Diagnostics/TraceSinkBase.cs b/engine/Age.Engine/Diagnostics/TraceSinkBase.cs new file mode 100644 index 0000000..1a142bd --- /dev/null +++ b/engine/Age.Engine/Diagnostics/TraceSinkBase.cs @@ -0,0 +1,28 @@ +using System.Collections.Generic; +namespace Age.Engine.Diagnostics; + +/// Base for sinks that need to know the currently-executing script. Tracks the frame stack +/// from FrameEnter/FrameExit (which emit regardless of the TracingSteps gate) so a subclass can key +/// per-instruction facts by the REAL running script — including inside nested call-script frames. +/// This is the "which script is offset 0x1c3 actually in?" fix: a bare Step event only carries pc + +/// depth, not the script name. +public abstract class TraceSinkBase : ITraceSink +{ + private readonly Stack _frames = new(); + + /// Name of the innermost frame currently executing ("?" before the first FrameEnter). + protected string CurrentScript => _frames.Count > 0 ? _frames.Peek() : "?"; + + public abstract bool TracingSteps { get; } + + public void Emit(in TraceEvent e) + { + // Push before dispatch so the FrameEnter itself is attributed to the entered frame; pop after + // dispatch so the FrameExit is still attributed to the exiting frame. + if (e.Kind == TraceEventKind.FrameEnter) _frames.Push(e.Name ?? "?"); + OnEvent(e); + if (e.Kind == TraceEventKind.FrameExit && _frames.Count > 0) _frames.Pop(); + } + + protected abstract void OnEvent(in TraceEvent e); +} diff --git a/engine/Age.Engine/Model/OpcodeTable.cs b/engine/Age.Engine/Model/OpcodeTable.cs index fa77d01..58b62ef 100644 --- a/engine/Age.Engine/Model/OpcodeTable.cs +++ b/engine/Age.Engine/Model/OpcodeTable.cs @@ -11,4 +11,12 @@ public sealed class OpcodeTable } public string Label(int op) => _t.TryGetValue(op, out var e) ? e.Label : ""; public int Argc(int op) => _t.TryGetValue(op, out var e) ? e.Argc : -1; + + /// Reverse lookup: opcode by mnemonic label (e.g. "sleep" -> 0xc8), or null if none. + /// Used by --trace-ops to let a diagnostic filter name ops by mnemonic instead of raw hex. + public int? ByLabel(string label) + { + foreach (var kv in _t) if (kv.Value.Label == label) return kv.Key; + return null; + } } diff --git a/godot/GodotAdvHost.cs b/godot/GodotAdvHost.cs index 7021e41..ca6b621 100644 --- a/godot/GodotAdvHost.cs +++ b/godot/GodotAdvHost.cs @@ -47,9 +47,10 @@ public sealed class GodotAdvHost : IHost // Time-based sibling of WaitForInput's suspend. The native op arms a non-blocking main-loop-polled timer; // blocking this throwaway task thread is behaviorally equivalent given our threading model. Operand is // MILLISECONDS (docs/engine-re.md sleep section + opcodes.toml 0xc8). Headless CLI hosts no-op it (parity). + public double SleepScale = 1.0; // --sleep-scale : debug multiplier to slow/speed the paced opening for inspection public void Sleep(long duration) { - int ms = (int)System.Math.Clamp(duration, 0, 10_000); // cap so a pathological script can't hang the window + int ms = (int)System.Math.Clamp(duration * SleepScale, 0, 60_000); // cap so a pathological script can't hang the window if (ms > 0) Thread.Sleep(ms); } diff --git a/godot/Main.cs b/godot/Main.cs index b209008..242bc1b 100644 --- a/godot/Main.cs +++ b/godot/Main.cs @@ -20,6 +20,10 @@ public partial class Main : Godot.Control private VirtualMachine _vm = null!; private GodotAdvHost _host = null!; private GodotTraceSink _trace = null!; + private Age.Engine.Diagnostics.HistogramTraceSink? _hist; // --trace-histogram: profile the real run + private string? _histFile; + private Age.Engine.Model.OpcodeTable? _table; + private bool _histDumped; private volatile bool _done; private bool _ended; private bool _selftest; @@ -84,6 +88,8 @@ public partial class Main : Godot.Control bool boot = System.Array.IndexOf(userArgs, "--boot") >= 0; // run SYSTEM4's state prefix first string scene = "SC0000"; // --scene : which scene to play (default SC0000) var seeds = new List<(int Addr, long Val)>(); // --seed 0xADDR=VAL (repeatable) — initial global state + double sleepScale = 1.0; // --sleep-scale : slow/speed the paced opening for inspection + string? histFile = null; // --trace-histogram : op/call-site execution counts of the REAL run for (int i = 0; i < userArgs.Length; i++) { if (userArgs[i] == "--scene" && i + 1 < userArgs.Length) scene = userArgs[i + 1]; @@ -92,6 +98,8 @@ public partial class Main : Godot.Control if (userArgs[i] == "--shot-settle" && i + 1 < userArgs.Length) int.TryParse(userArgs[i + 1], out _shotSettleTarget); if (userArgs[i] == "--shot-sequence" && i + 1 < userArgs.Length) _seqDir = userArgs[i + 1]; if (userArgs[i] == "--frames" && i + 1 < userArgs.Length) int.TryParse(userArgs[i + 1], out _seqFrames); + if (userArgs[i] == "--sleep-scale" && i + 1 < userArgs.Length) double.TryParse(userArgs[i + 1], out sleepScale); + if (userArgs[i] == "--trace-histogram" && i + 1 < userArgs.Length) histFile = userArgs[i + 1]; if (userArgs[i] == "--seed" && i + 1 < userArgs.Length) { var kv = userArgs[i + 1].Split('='); @@ -111,9 +119,16 @@ public partial class Main : Godot.Control IScriptProvider provider; if (_selftest) (script, provider) = BuildSelfTestScene(table); else { script = Sys4Loader.Load(Paths.Scripts()[scene.ToUpperInvariant() + ".BIN"], table); provider = Sys4ScriptProvider.Load(table); } - _host = new GodotAdvHost(this, ResourceMap.Load(), scene); + _host = new GodotAdvHost(this, ResourceMap.Load(), scene) { SleepScale = sleepScale }; _trace = new GodotTraceSink(); - _vm = new VirtualMachine(script, table, _host, new VmOptions(MaxSteps: 20_000_000), provider, _trace); + // --trace-histogram: aggregate op/call-site execution counts of the REAL Godot run (headless flow + // diverges — wait-for-input is a no-op there — so this is the only way to profile the live path). + _table = table; + _histFile = histFile; + Age.Engine.Diagnostics.ITraceSink sink = _trace; + if (histFile != null) { _hist = new Age.Engine.Diagnostics.HistogramTraceSink(); + sink = new Age.Engine.Diagnostics.CompositeTraceSink(_trace, _hist); } + _vm = new VirtualMachine(script, table, _host, new VmOptions(MaxSteps: 20_000_000), provider, sink); // --boot: run SYSTEM4's state prefix (INITCONFIG/INIT2/INIT) so the scene sees boot state — chiefly // INIT2's gfx handle array 0x62455.. (skips the UI scripts LOGO/OP/TITLE). State carries via globals. if (boot && !_selftest) @@ -170,6 +185,7 @@ public partial class Main : Godot.Control if (_done && !_ended) { _ended = true; + DumpHistogram(); ReportSubroutines(); ShowEnd(); if (_selftest) RunSelfTest(); @@ -186,7 +202,24 @@ public partial class Main : Godot.Control _host.SignalInput(); } - public override void _ExitTree() { _host?.SignalInput(); } + public override void _ExitTree() { DumpHistogram(); _host?.SignalInput(); } + + // Write the real-run op/call-site histogram to --trace-histogram . Idempotent; called when the + // scene ends or the window closes (the opening parks at wait-for-input, so closing is the usual trigger). + private void DumpHistogram() + { + if (_histDumped || _hist == null || _histFile == null) return; + _histDumped = true; + try + { + var dir = System.IO.Path.GetDirectoryName(_histFile); + if (!string.IsNullOrEmpty(dir)) System.IO.Directory.CreateDirectory(dir); + using var w = new System.IO.StreamWriter(_histFile); + _hist.WriteReport(w, _table); + GD.Print($"[trace-histogram] wrote {_hist.TotalSteps} steps -> {_histFile}"); + } + catch (System.Exception e) { GD.Print($"[trace-histogram] write failed: {e.Message}"); } + } // ---- retained per-frame compositor (main thread, from _Process) ---- // Clear the screen and composite the VM's current VISIBLE gfx objects in ascending-handle order (= the