Instruction-trace debugging
Trace hello_world.nds first (maintainer rule) — it's the cheapest gate: tiny, boots
instantly, deterministic from boot with no input/savestate, exercises the core jit path. A
strict self-diff on it catches most emitter regressions in seconds before you spend time on
the heavier roms.
The heavy hammer. Before reaching for it, try the cheaper steps in DEVELOPMENT.md §4:
read the panic, A/B the engine (INTERP_THRESHOLD 0 = pure jit / 255 = always interpret /
100 = production in src/jit/interpreter/mod.rs), and count events first — with a
DEBUG_LOG build, grep-counting send interrupt / interrupt { / can't interrupt /
hle ipc send lines over a window characterizes a hang in minutes (irqs flowing = game
alive; sends without dispatches = starvation; no irq traffic = pre-irq-setup spin).
Setup
DEBUG_LOG is derived from the build profile (main.rs: const_str_equal(BUILD_PROFILE_NAME, "debug")) — no source edit. Build the debug profile (plain cargo build, opt-level 3
since the profile bump) to get a logging binary; --inst-log and friends only register under
it. Stdout becomes huge — redirect to a real disk or pipe through grep --line-buffered,
never a small tmpfs.
- To force the JIT path (so an emitter change is actually exercised in the trace) sed
INTERP_THRESHOLD=0 (src/jit/interpreter/mod.rs) — otherwise blocks interpret for their
first 100 executions and the emitted code the change touches may never run. Restore it after.
- For an A/B pair, build the two variants as SEPARATE edit+build commands (chained
sed && cargo build can skip the recompile via the mtime race), confirm the
"Compiling dsvita" line appears, and md5sum both binaries to prove they differ.
Capture
| mode |
how |
| From boot |
dsvita --inst-log <path> <rom> ... (boot with NO input = deterministic, diffs cleanly) |
| Final stretch only |
dsvita --inst-log-lazy <path> ... with DSVITA_DBG_PORT=<port>, then send inst-log to the port at the interesting moment (printf 'inst-log\n' | nc -q0 127.0.0.1 <port>) |
| Flush + stop |
kill -INT <pid> (the panic hook also flushes — a crash self-captures its tail) |
Local capture: tools/trace.sh <out.ilog> boots $DSVITA_TEST_ROM under qemu.
Decode & analyze
tools/trace_decode.sh <path> > out.txt # exact per-inst text (regs + InstInfo), x86-NATIVE
grep -a "^ARM9 Executed" out.txt # per-cpu register-state stream
tools/trace_decode.sh <path> --cpu 1 --index # filter to one cpu (0=ARM9,1=ARM7), number records
tools/extract.sh <ilog> <out.txt> [maxlines] # ARM7 stream shortcut
tools/sync.sh <ilog> <out.txt> # IPCSYNC (0x4000180) handshake traffic
tools/trace_diff.py <a.ilog> <b.ilog> [W] # streaming binary differ with HLE-gap resync
trace_decode.sh builds/runs tools/trace-decode — a detached crate that reuses dsvita's REAL
disassembler (#[path] includes of src/jit/disassembler/**, inst_info, op) but links no
C/C++, so it decodes on the x86 dev box where there is no dsvita binary. Its output is identical
to the in-emulator dsvita decode-inst-log <path> (which still works on an arm/aarch64 box).
Interleaved memory read/write at X with value Y text records show io handshakes,
overlay/file loads, and pointer provenance — grep them before writing new tooling.
Diff parity rules (each cost real time once)
- Neither engine logs taken branches; the jit logs EXTRA records the interpreter doesn't
("enter block" markers, return-stack-resume re-logs, same-block
bls). Filter to
Executed records and drop records whose InstInfo writes PC before comparing.
- Same PC + different registers = real bug. Different PC sequence + same registers =
usually benign timing skew; io-poll loops legitimately differ in iteration count.
- An interp-vs-jit diff cannot distinguish "interp = hardware, jit HLE ≠ hardware" (benign)
from "interp ≠ hardware" (bug) — break ties with a third reference (NooDS; instrument its
Memory::write with an address watch for a known-good write sequence).
- Never decode or analyze traces on the test box — always scp the .ilog to the dev
machine first (maintainer rule). The box's SD is slow and small; the dev machine chews a
24 GB log in seconds. Decoding/diffing is pure ilog parsing — architecture-independent, so
it ALWAYS happens on the dev machine regardless of where the trace was captured. On an x86
dev box (no dsvita binary) decode with
tools/trace_decode.sh and diff with trace_diff.py
— both run natively there.
- Only run a built binary locally when the dev machine's arch matches it.
tracediff.sh
runs the aarch64-unknown-linux-gnu side natively — that assumes an aarch64 dev box
(the current setup: native a64 + qemu-arm for the a32 side). On an x86 dev machine,
neither the a64 nor the armhf binary runs natively at useful speed: capture BOTH sides on
the pi (armhf is native there) — or use qemu-arm locally only for the a32 side — and still
pull the ilogs to decode/diff locally. Don't blindly invoke tracediff.sh off an aarch64
box.
- A byte-identical boot-window diff is NECESSARY BUT NOT SUFFICIENT for a jit/emitter
change. Boot (2M–4M records) never reaches JIT arena reset (
reset_blocks when the ~28MB
arena fills), fs-clear overlay reloads, or state that only forms after warmup (self-modifying
code paths, a rarely-hit interrupt). An emitter change once passed a 4M-record MKDS-boot diff
byte-identical yet crashed the game at ~40s, well past the boot window. So after the strict
diff, ALSO run real games (release-debug) past arena reset — ~40–60s at -f 1, and screenshot.
Standing set: Mario Kart DS, Pokémon Diamond, HeartGold. (Diamond/HG are NitroSDK overlay reloaders.)
Keeping traces small
DSVITA_INST_LOG_TEXT=0 drops the interleaved text records — on a commercial boot they
outweigh the instruction records. Strict A/B diffs never need them.
- Instruction records are delta-encoded automatically (~5x smaller than the old fixed 80 B
records; keyframe every 2^20 records per cpu). All readers (decode-inst-log,
trace_diff.py) handle both formats.
- The very frequent mem.rs "memory read/write at" lines are compact binary TAG_MEM records
(6-10 B vs ~40-50 B text; slice/DMA element lines batch into one record). The decoder
regenerates the exact old text lines, so decoded output and greps are unchanged.
DSVITA_INST_LOG_TEXT=0 drops them like any text. Logs from before July 10 2026 still
decode; older binaries can't read new logs.
DSVITA_INST_LOG_MAX=N stops the log after exactly N records, flushed from the logging
thread — use it instead of SIGINT for A/B pairs (a signal stop can tear a record).
1---2name: inst-trace3description: Capture, decode, and diff binary per-instruction traces to localize emulation bugs — use when debugging an interpreter-vs-jit divergence, a game hang/crash/corruption, wrong register values, or when asked to trace-diff two engine configurations.4---56# Instruction-trace debugging78**Trace hello_world.nds first** (maintainer rule) — it's the cheapest gate: tiny, boots9instantly, deterministic from boot with no input/savestate, exercises the core jit path. A10strict self-diff on it catches most emitter regressions in seconds before you spend time on11the heavier roms.1213The heavy hammer. Before reaching for it, try the cheaper steps in DEVELOPMENT.md §4:14read the panic, A/B the engine (`INTERP_THRESHOLD` 0 = pure jit / 255 = always interpret /15100 = production in `src/jit/interpreter/mod.rs`), and **count events first** — with a16DEBUG_LOG build, grep-counting `send interrupt` / `interrupt {` / `can't interrupt` /17`hle ipc send` lines over a window characterizes a hang in minutes (irqs flowing = game18alive; sends without dispatches = starvation; no irq traffic = pre-irq-setup spin).1920## Setup21221. `DEBUG_LOG` is derived from the build profile (`main.rs`: `const_str_equal(BUILD_PROFILE_NAME,23 "debug")`) — no source edit. **Build the `debug` profile** (plain `cargo build`, opt-level 324 since the profile bump) to get a logging binary; `--inst-log` and friends only register under25 it. Stdout becomes huge — redirect to a real disk or pipe through `grep --line-buffered`,26 never a small tmpfs.272. To force the JIT path (so an emitter change is actually exercised in the trace) sed28 `INTERP_THRESHOLD=0` (`src/jit/interpreter/mod.rs`) — otherwise blocks interpret for their29 first 100 executions and the emitted code the change touches may never run. Restore it after.303. For an A/B pair, build the two variants as SEPARATE edit+build commands (chained31 `sed && cargo build` can skip the recompile via the mtime race), confirm the32 "Compiling dsvita" line appears, and `md5sum` both binaries to prove they differ.3334## Capture3536| mode | how |37|---|---|38| From boot | `dsvita --inst-log <path> <rom> ...` (boot with NO input = deterministic, diffs cleanly) |39| Final stretch only | `dsvita --inst-log-lazy <path> ...` with `DSVITA_DBG_PORT=<port>`, then send `inst-log` to the port at the interesting moment (`printf 'inst-log\n' \| nc -q0 127.0.0.1 <port>`) |40| Flush + stop | `kill -INT <pid>` (the panic hook also flushes — a crash self-captures its tail) |4142Local capture: `tools/trace.sh <out.ilog>` boots `$DSVITA_TEST_ROM` under qemu.4344## Decode & analyze4546```bash47tools/trace_decode.sh <path> > out.txt # exact per-inst text (regs + InstInfo), x86-NATIVE48grep -a "^ARM9 Executed" out.txt # per-cpu register-state stream49tools/trace_decode.sh <path> --cpu 1 --index # filter to one cpu (0=ARM9,1=ARM7), number records50tools/extract.sh <ilog> <out.txt> [maxlines] # ARM7 stream shortcut51tools/sync.sh <ilog> <out.txt> # IPCSYNC (0x4000180) handshake traffic52tools/trace_diff.py <a.ilog> <b.ilog> [W] # streaming binary differ with HLE-gap resync53```5455`trace_decode.sh` builds/runs `tools/trace-decode` — a detached crate that reuses dsvita's REAL56disassembler (`#[path]` includes of `src/jit/disassembler/**`, `inst_info`, `op`) but links no57C/C++, so it decodes on the x86 dev box where there is no dsvita binary. Its output is identical58to the in-emulator `dsvita decode-inst-log <path>` (which still works on an arm/aarch64 box).5960Interleaved `memory read/write at X with value Y` text records show io handshakes,61overlay/file loads, and pointer provenance — grep them before writing new tooling.6263## Diff parity rules (each cost real time once)6465- Neither engine logs taken branches; the jit logs EXTRA records the interpreter doesn't66 ("enter block" markers, return-stack-resume re-logs, same-block `bl`s). Filter to67 `Executed` records and drop records whose InstInfo writes PC before comparing.68- Same PC + different registers = real bug. Different PC sequence + same registers =69 usually benign timing skew; io-poll loops legitimately differ in iteration count.70- An interp-vs-jit diff cannot distinguish "interp = hardware, jit HLE ≠ hardware" (benign)71 from "interp ≠ hardware" (bug) — break ties with a third reference (NooDS; instrument its72 Memory::write with an address watch for a known-good write sequence).73- **Never decode or analyze traces on the test box** — always scp the .ilog to the dev74 machine first (maintainer rule). The box's SD is slow and small; the dev machine chews a75 24 GB log in seconds. Decoding/diffing is pure ilog parsing — architecture-independent, so76 it ALWAYS happens on the dev machine regardless of where the trace was captured. On an x8677 dev box (no dsvita binary) decode with `tools/trace_decode.sh` and diff with `trace_diff.py`78 — both run natively there.79- **Only run a built binary locally when the dev machine's arch matches it.** `tracediff.sh`80 runs the `aarch64-unknown-linux-gnu` side natively — that assumes an **aarch64 dev box**81 (the current setup: native a64 + `qemu-arm` for the a32 side). On an **x86 dev machine**,82 neither the a64 nor the armhf binary runs natively at useful speed: capture BOTH sides on83 the pi (armhf is native there) — or use `qemu-arm` locally only for the a32 side — and still84 pull the ilogs to decode/diff locally. Don't blindly invoke `tracediff.sh` off an aarch6485 box.86- **A byte-identical boot-window diff is NECESSARY BUT NOT SUFFICIENT** for a jit/emitter87 change. Boot (2M–4M records) never reaches JIT arena reset (`reset_blocks` when the ~28MB88 arena fills), fs-clear overlay reloads, or state that only forms after warmup (self-modifying89 code paths, a rarely-hit interrupt). An emitter change once passed a 4M-record MKDS-boot diff90 byte-identical yet crashed the game at ~40s, well past the boot window. So after the strict91 diff, ALSO run real games (release-debug) past arena reset — ~40–60s at `-f 1`, and screenshot.92 Standing set: Mario Kart DS, Pokémon Diamond, HeartGold. (Diamond/HG are NitroSDK overlay reloaders.)9394## Keeping traces small9596- `DSVITA_INST_LOG_TEXT=0` drops the interleaved text records — on a commercial boot they97 outweigh the instruction records. Strict A/B diffs never need them.98- Instruction records are delta-encoded automatically (~5x smaller than the old fixed 80 B99 records; keyframe every 2^20 records per cpu). All readers (decode-inst-log,100 trace_diff.py) handle both formats.101- The very frequent mem.rs "memory read/write at" lines are compact binary TAG_MEM records102 (6-10 B vs ~40-50 B text; slice/DMA element lines batch into one record). The decoder103 regenerates the exact old text lines, so decoded output and greps are unchanged.104 `DSVITA_INST_LOG_TEXT=0` drops them like any text. Logs from before July 10 2026 still105 decode; older binaries can't read new logs.106- `DSVITA_INST_LOG_MAX=N` stops the log after exactly N records, flushed from the logging107 thread — use it instead of SIGINT for A/B pairs (a signal stop can tear a record).