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:
gamer147
2026-07-08 09:50:07 -04:00
parent db3cd9a68d
commit a256b8e6d8
10 changed files with 354 additions and 29 deletions

View File

@@ -1,23 +1,29 @@
using System.Collections.Generic;
using System.Linq;
using Age.Engine.Model;
namespace Age.Engine.Diagnostics;
/// <summary>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.</summary>
public sealed class TextTraceSink : ITraceSink
/// <summary>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 <paramref name="opFilter"/> 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.</summary>
public sealed class TextTraceSink : TraceSinkBase
{
private readonly TextWriter _w;
private readonly OpcodeTable? _table;
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)
{ _w = writer; _table = table; _steps = includeSteps; }
public TextTraceSink(TextWriter writer, OpcodeTable? table = null, bool includeSteps = false,
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)
{
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;
}