feat(diag): aggregating + filtered trace sinks (histogram, op-filter, per-script)
The existing trace framework only had a flat text formatter, so every question became 'dump millions of lines, then grep'. This session that cost a long wrong detour. Add, all observe-only (parity preserved): - HistogramTraceSink: execution counts per opcode AND per call-site (script:pc) with a sample operand. Dumped sorted after the run. This is what instantly showed the 493k headless 'sleep's are INPUTNAME.BIN:0x1c3 (a name-entry poll loop), not the opening. - TraceSinkBase: tracks the frame stack -> attributes each step to its REAL script (nested call-script frames included) = the 'which script is this pc in?' answer a bare step trace can't give. - TextTraceSink: op-filter (--trace-ops sleep,draw-texture,...) + script:pc tags. - CompositeTraceSink: fan-out (text + histogram + Godot's call-script queue). - OpcodeTable.ByLabel: mnemonic -> opcode for --trace-ops. - CLI: --trace-histogram, --trace-ops, robust --trace-file (mkdir -p). - Godot: --trace-histogram <file> profiles the REAL run (headless flow diverges: real run to page 1 is 562 steps / 0 sleeps vs headless 2M steps / 493k sleeps). - Also: --sleep-scale <f> debug knob to slow the paced opening for inspection. Engine 56/56 (4 new); sweep parity 284/13; Godot builds + dogfooded end-to-end. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
@@ -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`
|
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: …`.
|
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 <csv>`** — 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 <path>` now creates the parent directory if missing.
|
||||||
|
- **Godot** accepts **`--trace-histogram <file>`** — 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
|
**Godot frontend** (`S:/Godot/Godot_v4.7…`; project = `godot/`). Toolchain: `godot --headless --path godot
|
||||||
--import` → `dotnet build godot/Himegari.csproj` → `godot [--headless] --path godot [-- <userargs>]`.
|
--import` → `dotnet build godot/Himegari.csproj` → `godot [--headless] --path godot [-- <userargs>]`.
|
||||||
Plays the real bytecode with call-script execution on (subroutines run live). `--headless` can't render
|
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`.
|
- `--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 <png> [--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 <png> [--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 <dir> [--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`.
|
- `--shot-sequence <dir> [--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 <f>` — 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
|
## Asset resolution / graphics
|
||||||
|
|
||||||
|
|||||||
@@ -11,17 +11,9 @@ var table = OpcodeTableJson.Load(Paths.OpcodesJson);
|
|||||||
// `trace` stays provider-less on purpose (the base-ISA offset oracle).
|
// `trace` stays provider-less on purpose (the base-ISA offset oracle).
|
||||||
var provider = Sys4ScriptProvider.Load(table);
|
var provider = Sys4ScriptProvider.Load(table);
|
||||||
|
|
||||||
// --trace [--trace-file <path>] [--trace-steps] → a TextTraceSink to console or file; else inert.
|
// Diagnostics flags (see the TraceSetup class below): --trace (text flow), --trace-steps (every op),
|
||||||
static ITraceSink BuildSink(string[] a, OpcodeTable tbl)
|
// --trace-ops <csv> (only these mnemonics/hex, tagged with their script), --trace-histogram (op +
|
||||||
{
|
// call-site execution counts, dumped after the run), --trace-file <path> (write to a file, else console).
|
||||||
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);
|
|
||||||
}
|
|
||||||
|
|
||||||
if (args.Length == 0) { Console.WriteLine("usage: run <file> | trace <out.json>"); return 1; }
|
if (args.Length == 0) { Console.WriteLine("usage: run <file> | trace <out.json>"); return 1; }
|
||||||
|
|
||||||
@@ -29,8 +21,10 @@ if (args[0] == "run")
|
|||||||
{
|
{
|
||||||
var script = Sys4Loader.Load(args[1], table);
|
var script = Sys4Loader.Load(args[1], table);
|
||||||
var runHost = new CaptureHost();
|
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();
|
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})");
|
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}");
|
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();
|
var sources = vm.Emitted.Select(e => e.Script).Distinct().ToList();
|
||||||
@@ -133,13 +127,15 @@ if (args[0] == "play")
|
|||||||
session.Seed(k, v);
|
session.Seed(k, v);
|
||||||
}
|
}
|
||||||
long totalLines = 0;
|
long totalLines = 0;
|
||||||
|
using var trace = TraceSetup.Build(args, table); // one sink across the sequence (histogram aggregates)
|
||||||
foreach (var name in scenes)
|
foreach (var name in scenes)
|
||||||
{
|
{
|
||||||
var script = Sys4Loader.Load(scripts[name.ToUpperInvariant()], table);
|
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;
|
totalLines += r.Emitted.Count;
|
||||||
Console.WriteLine($" {name,-14} {r.Emitted.Count,4} lines, {r.Steps,7} steps (halt: {r.Halt})");
|
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");
|
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}"); }
|
if (saveState != null) { File.WriteAllText(saveState, session.ToJson()); Console.WriteLine($"[state] saved -> {saveState}"); }
|
||||||
return 0;
|
return 0;
|
||||||
@@ -198,15 +194,17 @@ if (args[0] == "sweep")
|
|||||||
|
|
||||||
var haltDist = new SortedDictionary<string, int>(StringComparer.Ordinal);
|
var haltDist = new SortedDictionary<string, int>(StringComparer.Ordinal);
|
||||||
long totalLines = 0; var anomalies = new List<string>();
|
long totalLines = 0; var anomalies = new List<string>();
|
||||||
|
using var trace = TraceSetup.Build(args, table); // one sink across the corpus (histogram aggregates)
|
||||||
foreach (var name in names)
|
foreach (var name in names)
|
||||||
{
|
{
|
||||||
var session = Fresh();
|
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";
|
var halt = r.Halt ?? "null";
|
||||||
haltDist[halt] = haltDist.GetValueOrDefault(halt) + 1;
|
haltDist[halt] = haltDist.GetValueOrDefault(halt) + 1;
|
||||||
totalLines += r.Emitted.Count;
|
totalLines += r.Emitted.Count;
|
||||||
if (halt != "exit") anomalies.Add($"{name}: {r.Emitted.Count} lines, halt={halt}");
|
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($"swept {names.Count} scenes{(boot ? " (booted)" : "")}: {totalLines} total lines");
|
||||||
Console.WriteLine("halt distribution: " + string.Join(", ", haltDist.Select(kv => $"{kv.Key}={kv.Value}")));
|
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); }
|
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;
|
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<int>? filter = null;
|
||||||
|
if (opsCsv != null)
|
||||||
|
{
|
||||||
|
filter = new HashSet<int>();
|
||||||
|
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<ITraceSink>();
|
||||||
|
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,
|
||||||
|
};
|
||||||
|
}
|
||||||
|
|
||||||
|
/// <summary>After the run, dump the histogram (if enabled). Text/filter output already streamed live.</summary>
|
||||||
|
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
|
sealed class AudioTraceHost : IHost
|
||||||
{
|
{
|
||||||
private readonly ResourceMap _res;
|
private readonly ResourceMap _res;
|
||||||
|
|||||||
80
engine/Age.Engine.Tests/DiagnosticsSinkTests.cs
Normal file
80
engine/Age.Engine.Tests/DiagnosticsSinkTests.cs
Normal file
@@ -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<Operand>()) }, Array.Empty<string>());
|
||||||
|
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<Operand>()) }, Array.Empty<string>());
|
||||||
|
|
||||||
|
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<Operand>()) }, Array.Empty<string>());
|
||||||
|
var sw = new StringWriter();
|
||||||
|
var filter = new HashSet<int> { 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);
|
||||||
|
}
|
||||||
|
}
|
||||||
17
engine/Age.Engine/Diagnostics/CompositeTraceSink.cs
Normal file
17
engine/Age.Engine/Diagnostics/CompositeTraceSink.cs
Normal file
@@ -0,0 +1,17 @@
|
|||||||
|
namespace Age.Engine.Diagnostics;
|
||||||
|
|
||||||
|
/// <summary>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.</summary>
|
||||||
|
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); }
|
||||||
|
}
|
||||||
72
engine/Age.Engine/Diagnostics/HistogramTraceSink.cs
Normal file
72
engine/Age.Engine/Diagnostics/HistogramTraceSink.cs
Normal file
@@ -0,0 +1,72 @@
|
|||||||
|
using System.Collections.Generic;
|
||||||
|
using System.IO;
|
||||||
|
using System.Linq;
|
||||||
|
using Age.Engine.Model;
|
||||||
|
namespace Age.Engine.Diagnostics;
|
||||||
|
|
||||||
|
/// <summary>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.</summary>
|
||||||
|
public sealed class HistogramTraceSink : TraceSinkBase
|
||||||
|
{
|
||||||
|
public override bool TracingSteps => true; // needs every Step
|
||||||
|
|
||||||
|
private readonly object _lock = new();
|
||||||
|
private readonly Dictionary<int, long> _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; }
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
/// <summary>How many times the given opcode executed.</summary>
|
||||||
|
public long OpCount(int op) { lock (_lock) return _opCounts.GetValueOrDefault(op); }
|
||||||
|
|
||||||
|
/// <summary>Total instructions executed (all frames).</summary>
|
||||||
|
public long TotalSteps { get { lock (_lock) return _totalSteps; } }
|
||||||
|
|
||||||
|
/// <summary>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).</summary>
|
||||||
|
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();
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -1,23 +1,29 @@
|
|||||||
|
using System.Collections.Generic;
|
||||||
|
using System.Linq;
|
||||||
using Age.Engine.Model;
|
using Age.Engine.Model;
|
||||||
namespace Age.Engine.Diagnostics;
|
namespace Age.Engine.Diagnostics;
|
||||||
|
|
||||||
/// <summary>The one built-in formatter: writes each event as a deterministic text line to a
|
/// <summary>The built-in text formatter: writes each event as a deterministic line to a TextWriter
|
||||||
/// TextWriter (Console.Out or a file). Indents by frame depth. If an OpcodeTable is supplied, Step
|
/// (Console.Out or a file), indented by frame depth. Step lines are tagged with the current script
|
||||||
/// lines show the mnemonic; otherwise the raw opcode. Step lines only appear when includeSteps is set.</summary>
|
/// (the "which script is this op in" answer) and, when <paramref name="opFilter"/> is set, only ops in
|
||||||
public sealed class TextTraceSink : ITraceSink
|
/// 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.</summary>
|
||||||
|
public sealed class TextTraceSink : TraceSinkBase
|
||||||
{
|
{
|
||||||
private readonly TextWriter _w;
|
private readonly TextWriter _w;
|
||||||
private readonly OpcodeTable? _table;
|
private readonly OpcodeTable? _table;
|
||||||
private readonly bool _steps;
|
private readonly bool _steps;
|
||||||
|
private readonly HashSet<int>? _opFilter; // null = all ops; else only these ops' Step/Stub lines
|
||||||
|
|
||||||
public TextTraceSink(TextWriter writer, OpcodeTable? table = null, bool includeSteps = false)
|
public TextTraceSink(TextWriter writer, OpcodeTable? table = null, bool includeSteps = false,
|
||||||
{ _w = writer; _table = table; _steps = includeSteps; }
|
HashSet<int>? 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)
|
switch (e.Kind)
|
||||||
{
|
{
|
||||||
case TraceEventKind.FrameEnter:
|
case TraceEventKind.FrameEnter:
|
||||||
@@ -25,12 +31,14 @@ public sealed class TextTraceSink : ITraceSink
|
|||||||
case TraceEventKind.FrameExit:
|
case TraceEventKind.FrameExit:
|
||||||
_w.WriteLine($"{indent}« {e.Name} ({e.Text})"); break;
|
_w.WriteLine($"{indent}« {e.Name} ({e.Text})"); break;
|
||||||
case TraceEventKind.Step:
|
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:
|
case TraceEventKind.CallScript:
|
||||||
_w.WriteLine($"{indent} call-script 0x{e.Id:x} ={e.Name ?? "?"} " +
|
_w.WriteLine($"{indent} call-script 0x{e.Id:x} ={e.Name ?? "?"} " +
|
||||||
$"({(e.Name != null ? "resolved" : "stub/unresolved")})"); break;
|
$"({(e.Name != null ? "resolved" : "stub/unresolved")})"); break;
|
||||||
case TraceEventKind.Stub:
|
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:
|
case TraceEventKind.Halt:
|
||||||
_w.WriteLine($"halt: {e.Text} @ {e.Steps} steps"); break;
|
_w.WriteLine($"halt: {e.Text} @ {e.Steps} steps"); break;
|
||||||
}
|
}
|
||||||
|
|||||||
28
engine/Age.Engine/Diagnostics/TraceSinkBase.cs
Normal file
28
engine/Age.Engine/Diagnostics/TraceSinkBase.cs
Normal file
@@ -0,0 +1,28 @@
|
|||||||
|
using System.Collections.Generic;
|
||||||
|
namespace Age.Engine.Diagnostics;
|
||||||
|
|
||||||
|
/// <summary>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.</summary>
|
||||||
|
public abstract class TraceSinkBase : ITraceSink
|
||||||
|
{
|
||||||
|
private readonly Stack<string> _frames = new();
|
||||||
|
|
||||||
|
/// <summary>Name of the innermost frame currently executing ("?" before the first FrameEnter).</summary>
|
||||||
|
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);
|
||||||
|
}
|
||||||
@@ -11,4 +11,12 @@ public sealed class OpcodeTable
|
|||||||
}
|
}
|
||||||
public string Label(int op) => _t.TryGetValue(op, out var e) ? e.Label : "";
|
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;
|
public int Argc(int op) => _t.TryGetValue(op, out var e) ? e.Argc : -1;
|
||||||
|
|
||||||
|
/// <summary>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.</summary>
|
||||||
|
public int? ByLabel(string label)
|
||||||
|
{
|
||||||
|
foreach (var kv in _t) if (kv.Value.Label == label) return kv.Key;
|
||||||
|
return null;
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -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;
|
// 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
|
// 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).
|
// MILLISECONDS (docs/engine-re.md sleep section + opcodes.toml 0xc8). Headless CLI hosts no-op it (parity).
|
||||||
|
public double SleepScale = 1.0; // --sleep-scale <f>: debug multiplier to slow/speed the paced opening for inspection
|
||||||
public void Sleep(long duration)
|
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);
|
if (ms > 0) Thread.Sleep(ms);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -20,6 +20,10 @@ public partial class Main : Godot.Control
|
|||||||
private VirtualMachine _vm = null!;
|
private VirtualMachine _vm = null!;
|
||||||
private GodotAdvHost _host = null!;
|
private GodotAdvHost _host = null!;
|
||||||
private GodotTraceSink _trace = 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 volatile bool _done;
|
||||||
private bool _ended;
|
private bool _ended;
|
||||||
private bool _selftest;
|
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
|
bool boot = System.Array.IndexOf(userArgs, "--boot") >= 0; // run SYSTEM4's state prefix first
|
||||||
string scene = "SC0000"; // --scene <NAME>: which scene to play (default SC0000)
|
string scene = "SC0000"; // --scene <NAME>: which scene to play (default SC0000)
|
||||||
var seeds = new List<(int Addr, long Val)>(); // --seed 0xADDR=VAL (repeatable) — initial global state
|
var seeds = new List<(int Addr, long Val)>(); // --seed 0xADDR=VAL (repeatable) — initial global state
|
||||||
|
double sleepScale = 1.0; // --sleep-scale <f>: slow/speed the paced opening for inspection
|
||||||
|
string? histFile = null; // --trace-histogram <file>: op/call-site execution counts of the REAL run
|
||||||
for (int i = 0; i < userArgs.Length; i++)
|
for (int i = 0; i < userArgs.Length; i++)
|
||||||
{
|
{
|
||||||
if (userArgs[i] == "--scene" && i + 1 < userArgs.Length) scene = userArgs[i + 1];
|
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-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] == "--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] == "--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)
|
if (userArgs[i] == "--seed" && i + 1 < userArgs.Length)
|
||||||
{
|
{
|
||||||
var kv = userArgs[i + 1].Split('=');
|
var kv = userArgs[i + 1].Split('=');
|
||||||
@@ -111,9 +119,16 @@ public partial class Main : Godot.Control
|
|||||||
IScriptProvider provider;
|
IScriptProvider provider;
|
||||||
if (_selftest) (script, provider) = BuildSelfTestScene(table);
|
if (_selftest) (script, provider) = BuildSelfTestScene(table);
|
||||||
else { script = Sys4Loader.Load(Paths.Scripts()[scene.ToUpperInvariant() + ".BIN"], table); provider = Sys4ScriptProvider.Load(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();
|
_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
|
// --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.
|
// INIT2's gfx handle array 0x62455.. (skips the UI scripts LOGO/OP/TITLE). State carries via globals.
|
||||||
if (boot && !_selftest)
|
if (boot && !_selftest)
|
||||||
@@ -170,6 +185,7 @@ public partial class Main : Godot.Control
|
|||||||
if (_done && !_ended)
|
if (_done && !_ended)
|
||||||
{
|
{
|
||||||
_ended = true;
|
_ended = true;
|
||||||
|
DumpHistogram();
|
||||||
ReportSubroutines();
|
ReportSubroutines();
|
||||||
ShowEnd();
|
ShowEnd();
|
||||||
if (_selftest) RunSelfTest();
|
if (_selftest) RunSelfTest();
|
||||||
@@ -186,7 +202,24 @@ public partial class Main : Godot.Control
|
|||||||
_host.SignalInput();
|
_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 <file>. 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) ----
|
// ---- 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
|
// Clear the screen and composite the VM's current VISIBLE gfx objects in ascending-handle order (= the
|
||||||
|
|||||||
Reference in New Issue
Block a user