From f7751c2b93342f8441ae5c81768991aacd0203fd Mon Sep 17 00:00:00 2001 From: gamer147 Date: Wed, 29 Jul 2026 18:51:06 -0400 Subject: [PATCH] Capture actionable STEP-LIMIT diagnostics --- docs/phase-b-framework.md | 13 ++++++ docs/tools-reference.md | 7 +++ .../Age.Engine.Tests/Age.Engine.Tests.csproj | 1 + .../Age.Engine.Tests/GodotTraceSinkTests.cs | 45 ++++++++++++++++++ godot/GodotTraceSink.cs | 33 ++++++++----- godot/Main.cs | 17 +++++-- godot/StepLimitDiagnosticFormatter.cs | 46 +++++++++++++++++++ 7 files changed, 146 insertions(+), 16 deletions(-) create mode 100644 godot/StepLimitDiagnosticFormatter.cs diff --git a/docs/phase-b-framework.md b/docs/phase-b-framework.md index 07643be..0bdcd2a 100644 --- a/docs/phase-b-framework.md +++ b/docs/phase-b-framework.md @@ -928,6 +928,19 @@ installed-A1215 regressions prove the exact prefix and unchanged PCM payload. Va tests, a zero-warning Godot build, and the Himegari-targeted threaded selftest, which loads the real A1215 buffer through Godot and reports `first-riff-boundary=ok` without seek spam. +**Stage 01-01 STEP-LIMIT diagnostics added (2026-07-29):** after a reveal-zone event, the persistent +SYSTEM4 run reached its artificial 20,000,000-instruction cap. `SYSTEM4 P592` correctly identifies the last +ADV boundary (`SC0600@0x33fd`, followed by cleanup and return), but the page map cannot identify code that +runs after that page. The final page was recorded about 29 seconds before the halt, so the existing report +cannot distinguish an SC0600 cleanup loop from resumed FIELD processing. + +Godot now retains the deepest frame chain before a halted frame unwinds and automatically emits a bounded +STEP-LIMIT report: exact script/offset/opcode, nested frame chain, hottest sites in the final 128 instructions, +and the final 16-instruction sequence. It also writes the ordinary full stall snapshot as +`user://diagnostics/step-limit-.json` and copies its coordinate/path. Focused formatter/stack +regressions and all 530 engine tests pass; the Godot build is warning-free and the Himegari-targeted threaded +selftest passes. No loop behavior or safety limit has been changed pending one instrumented reproduction. + **Cyclic reset implemented (2026-07-29):** `0x230(handle)` now gets or creates the retained object, disables the four looping channels represented by the compositor, and clears the complete native start/period block—including the preserved raw state for the currently unmodeled second cyclic matrix. diff --git a/docs/tools-reference.md b/docs/tools-reference.md index 1551794..76ba381 100644 --- a/docs/tools-reference.md +++ b/docs/tools-reference.md @@ -213,6 +213,13 @@ and pending movie records include `first_frame_source_pts_ms`; the ordinary `mov the same source PTS alongside the render frame, which distinguishes encoded stream lead-in from decode/presentation latency. +If the interactive VM reaches its `STEP-LIMIT` safety cap, Godot now captures the same diagnostic +automatically as `user://diagnostics/step-limit-.json` and copies its coordinate/path to the +clipboard. Before nested frames unwind, the trace sink preserves the deepest active script stack. The console +also prints the exact final script/offset/opcode, that frame chain, the hottest sites in the bounded final +128-instruction window, and the final 16-instruction sequence. This makes the last ADV locator unnecessary for +identifying a post-dialogue loop; send either the `step-limit` console block or the generated JSON. + ## Native FFmpeg movie shim (Windows x64) These PowerShell tools build the selected Windows-x64 live movie backend. The dependency manifest pins an diff --git a/engine/Age.Engine.Tests/Age.Engine.Tests.csproj b/engine/Age.Engine.Tests/Age.Engine.Tests.csproj index c761e82..3e7e782 100644 --- a/engine/Age.Engine.Tests/Age.Engine.Tests.csproj +++ b/engine/Age.Engine.Tests/Age.Engine.Tests.csproj @@ -30,6 +30,7 @@ + diff --git a/engine/Age.Engine.Tests/GodotTraceSinkTests.cs b/engine/Age.Engine.Tests/GodotTraceSinkTests.cs index fd2a4ac..5bdd335 100644 --- a/engine/Age.Engine.Tests/GodotTraceSinkTests.cs +++ b/engine/Age.Engine.Tests/GodotTraceSinkTests.cs @@ -1,5 +1,6 @@ using Age.Engine.Diagnostics; using Age.Engine.Model; +using Age.Engine.Sys4; public class GodotTraceSinkTests { @@ -28,4 +29,48 @@ public class GodotTraceSinkTests Assert.Equal(0x2400 + 12, snapshot.RecentSteps[0].Offset); Assert.Equal(0x2400 + 139, snapshot.RecentSteps[^1].Offset); } + + [Fact] + public void HaltSnapshotRetainsDeepestStackBeforeFramesUnwind() + { + using var locator = new PageLocatorState("SYSTEM4", null); + var sink = new GodotTraceSink(locator); + sink.Emit(TraceEvent.FrameEnter("SYSTEM4.BIN", 0, FrameCause.TopScene)); + sink.Emit(TraceEvent.FrameEnter("FIELD.BIN", 1, FrameCause.CallScript, 0x337d)); + sink.Emit(TraceEvent.FrameEnter("SC0600.BIN", 2, FrameCause.CallScript, 0x1202)); + sink.Emit(TraceEvent.Step(10, + new Instruction(0x3403, 0x8f, new[] { new Operand(0, 0x6f28) }), 2)); + + sink.Emit(TraceEvent.FrameExit("SC0600.BIN", 2, "Halted")); + sink.Emit(TraceEvent.FrameExit("FIELD.BIN", 1, "Halted")); + sink.Emit(TraceEvent.FrameExit("SYSTEM4.BIN", 0, "Halted")); + + GodotTraceSnapshot snapshot = Assert.IsType(sink.HaltSnapshot); + Assert.Equal("SC0600.BIN", snapshot.CurrentScript); + Assert.Equal(0x3403, snapshot.CurrentOffset); + Assert.Equal(new[] { "SYSTEM4.BIN", "FIELD.BIN", "SC0600.BIN" }, snapshot.CallStack); + } + + [Fact] + public void StepLimitReportShowsCoordinateFramesHotSitesAndTail() + { + OpcodeTable table = OpcodeTableJson.Load(Paths.OpcodesJson); + var recent = new[] + { + new GodotTraceStepSnapshot("FIELD.BIN", 0x100, 0x55, 1), + new GodotTraceStepSnapshot("FIELD.BIN", 0x107, 0x8e, 1), + new GodotTraceStepSnapshot("FIELD.BIN", 0x100, 0x55, 1), + }; + var snapshot = new GodotTraceSnapshot( + "FIELD.BIN", 0x100, 0x55, 1, + new[] { "SYSTEM4.BIN", "FIELD.BIN" }, recent); + + string report = StepLimitDiagnosticFormatter.Format(snapshot, table, topSites: 2, tailSteps: 2); + + Assert.Contains("[step-limit] last: FIELD@0x100 op=0x055 mov depth=1", report); + Assert.Contains("[step-limit] frames: SYSTEM4 > FIELD", report); + Assert.Contains("2x FIELD@0x100 op=0x055 mov", report); + Assert.DoesNotContain("SYSTEM4@0x", report); + Assert.EndsWith("[step-limit] FIELD@0x100 op=0x055 mov", report); + } } diff --git a/godot/GodotTraceSink.cs b/godot/GodotTraceSink.cs index a2e3c28..6dd8b4e 100644 --- a/godot/GodotTraceSink.cs +++ b/godot/GodotTraceSink.cs @@ -15,6 +15,7 @@ public sealed class GodotTraceSink : ITraceSink private readonly Stack _scripts = new(); private readonly Queue _recentSteps = new(); private GodotTraceStepSnapshot? _latestStep; + private GodotTraceSnapshot? _haltSnapshot; public GodotTraceSink(PageLocatorState locator, GodotTimelineLog? timeline = null) { _locator = locator; _timeline = timeline; } // The page locator needs the exact script/offset even when the heavier timeline log is disabled. @@ -54,6 +55,8 @@ public sealed class GodotTraceSink : ITraceSink string[] callStack; lock (_snapshotLock) { + if (e.Text == "Halted" && _haltSnapshot == null) + _haltSnapshot = SnapshotLocked(); if (_scripts.Count > 0) _scripts.Pop(); callStack = CurrentCallStackLocked(); } @@ -84,17 +87,13 @@ public sealed class GodotTraceSink : ITraceSink public GodotTraceSnapshot Snapshot() { - lock (_snapshotLock) - { - GodotTraceStepSnapshot? current = _latestStep; - return new GodotTraceSnapshot( - current?.Script ?? (_scripts.Count > 0 ? _scripts.Peek() : ""), - current?.Offset ?? -1, - current?.Opcode ?? -1, - current?.Depth ?? System.Math.Max(0, _scripts.Count - 1), - CurrentCallStackLocked(), - _recentSteps.ToArray()); - } + lock (_snapshotLock) return SnapshotLocked(); + } + + /// The deepest still-active script stack captured before a halted frame unwinds. + public GodotTraceSnapshot? HaltSnapshot + { + get { lock (_snapshotLock) return _haltSnapshot; } } /// Allocation-free current coordinate for once-per-frame diagnostics. @@ -109,6 +108,18 @@ public sealed class GodotTraceSink : ITraceSink System.Array.Reverse(stack); return stack; } + + private GodotTraceSnapshot SnapshotLocked() + { + GodotTraceStepSnapshot? current = _latestStep; + return new GodotTraceSnapshot( + current?.Script ?? (_scripts.Count > 0 ? _scripts.Peek() : ""), + current?.Offset ?? -1, + current?.Opcode ?? -1, + current?.Depth ?? System.Math.Max(0, _scripts.Count - 1), + CurrentCallStackLocked(), + _recentSteps.ToArray()); + } } public sealed record GodotTraceStepSnapshot(string Script, int Offset, int Opcode, int Depth); diff --git a/godot/Main.cs b/godot/Main.cs index 2535338..89244e8 100644 --- a/godot/Main.cs +++ b/godot/Main.cs @@ -580,6 +580,12 @@ public partial class Main : Godot.Control GD.Print($"[vm] ended: {_vm!.HaltReason ?? "unknown"} after {_vm.Steps} steps"); ReportSubroutines(); ShowEnd(); + if (_vm.HaltReason == "STEP-LIMIT") + { + GodotTraceSnapshot haltTrace = _trace.HaltSnapshot ?? _trace.Snapshot(); + GD.Print(StepLimitDiagnosticFormatter.Format(haltTrace, _table!)); + CaptureStallDiagnostic(haltTrace, "step-limit"); + } if (_selftest) RunSelfTest(); } } @@ -742,12 +748,13 @@ public partial class Main : Godot.Control private static bool IsAdvanceAction(int action) => action is 4 or 5; private static bool HasAdvanceAction(int mask) => (mask & ((1 << 4) | (1 << 5))) != 0; - private void CaptureStallDiagnostic() + private void CaptureStallDiagnostic(GodotTraceSnapshot? traceOverride = null, + string snapshotKind = "stall") { try { long nowMs = _clock.NowMs; - GodotTraceSnapshot trace = _trace.Snapshot(); + GodotTraceSnapshot trace = traceOverride ?? _trace.Snapshot(); var activeMovies = _movies .OrderBy(pair => pair.Key) .Select(pair => @@ -815,7 +822,7 @@ public partial class Main : Godot.Control string directory = ProjectSettings.GlobalizePath("user://diagnostics"); System.IO.Directory.CreateDirectory(directory); string path = System.IO.Path.Combine(directory, - $"stall-{System.DateTimeOffset.Now:yyyyMMdd-HHmmss-fff}.json"); + $"{snapshotKind}-{System.DateTimeOffset.Now:yyyyMMdd-HHmmss-fff}.json"); var jsonOptions = new JsonSerializerOptions { WriteIndented = true, @@ -825,10 +832,10 @@ public partial class Main : Godot.Control string coordinate = trace.CurrentOffset >= 0 ? $"{System.IO.Path.GetFileNameWithoutExtension(trace.CurrentScript).ToUpperInvariant()}@0x{trace.CurrentOffset:x}" : trace.CurrentScript; - string clipboard = $"{coordinate} · stall snapshot {path}"; + string clipboard = $"{coordinate} · {snapshotKind} snapshot {path}"; DisplayServer.ClipboardSet(clipboard); _status.Text = $"Diagnostic saved: {coordinate} (path copied)"; - GD.Print($"[diagnostic] stall snapshot {coordinate} -> {path}"); + GD.Print($"[diagnostic] {snapshotKind} snapshot {coordinate} -> {path}"); } catch (System.Exception exception) { diff --git a/godot/StepLimitDiagnosticFormatter.cs b/godot/StepLimitDiagnosticFormatter.cs new file mode 100644 index 0000000..9b02d7a --- /dev/null +++ b/godot/StepLimitDiagnosticFormatter.cs @@ -0,0 +1,46 @@ +using System; +using System.IO; +using System.Linq; +using System.Text; +using Age.Engine.Model; + +/// Formats the bounded trace retained by the Godot frontend when the VM safety cap fires. +public static class StepLimitDiagnosticFormatter +{ + public static string Format(GodotTraceSnapshot snapshot, OpcodeTable table, + int topSites = 8, int tailSteps = 16) + { + string Location(GodotTraceStepSnapshot step) + { + string script = Path.GetFileNameWithoutExtension(step.Script).ToUpperInvariant(); + string mnemonic = table.Label(step.Opcode); + if (string.IsNullOrEmpty(mnemonic)) mnemonic = "unknown"; + return $"{script}@0x{step.Offset:x} op=0x{step.Opcode:x3} {mnemonic}"; + } + + var output = new StringBuilder(); + var current = new GodotTraceStepSnapshot( + snapshot.CurrentScript, snapshot.CurrentOffset, snapshot.CurrentOpcode, snapshot.CurrentDepth); + output.AppendLine($"[step-limit] last: {Location(current)} depth={snapshot.CurrentDepth}"); + output.AppendLine($"[step-limit] frames: {string.Join(" > ", + snapshot.CallStack.Select(name => Path.GetFileNameWithoutExtension(name).ToUpperInvariant()))}"); + output.AppendLine($"[step-limit] hot sites in final {snapshot.RecentSteps.Count} steps:"); + foreach (var site in snapshot.RecentSteps + .GroupBy(step => (step.Script, step.Offset, step.Opcode)) + .OrderByDescending(group => group.Count()) + .ThenBy(group => group.Key.Script, StringComparer.Ordinal) + .ThenBy(group => group.Key.Offset) + .Take(Math.Max(0, topSites))) + { + var sample = new GodotTraceStepSnapshot( + site.Key.Script, site.Key.Offset, site.Key.Opcode, 0); + output.AppendLine($"[step-limit] {site.Count(),4}x {Location(sample)}"); + } + + int tailStart = Math.Max(0, snapshot.RecentSteps.Count - Math.Max(0, tailSteps)); + output.AppendLine($"[step-limit] final {snapshot.RecentSteps.Count - tailStart} steps:"); + for (int index = tailStart; index < snapshot.RecentSteps.Count; index++) + output.AppendLine($"[step-limit] {Location(snapshot.RecentSteps[index])}"); + return output.ToString().TrimEnd(); + } +}