Files
psxrecomp/tools/analyze_sio_trace.py
T
Matthew Stanley 5b3c7dd08d phase4: freeze_check diagnostic + accumulated overnight infra
Today's session work
- runtime/src/debug_server.c: freeze_check TCP cmd snapshots all liveness
  counters (PC, exception entries, exception_reentry_blocks, dirty_ram
  blocks/insns, fn_entry total + top-K histogram, SIO IRQ pending +
  countdown, sio_stat/i_stat/i_mask, mc_max_state) for tight-loop
  diagnosis when the runtime hangs
- runtime/src/debug_server.c: wtrace slot 12 covering [0x72F0..0x72F4]
  (data-byte counter); measured peak=1 confirming setup_data_phase resets
  the counter mid-cycle
- runtime/src/interrupts.c: exception_entries_total + exception_reentry_blocks
  counters + psx_get_freeze_diag accessor
- runtime/src/sio.c: sio_get_freeze_diag accessor for IRQ pacing internals
- memory entries: phase4_card_gate_setup_writes_2026_04_28 (refutes the
  prior \"missing [0x7568+slot] clearer\" framing — setup functions write
  LSB=0 directly), phase4_72f0_one_byte_per_vblank_2026_04_28 (peak=1
  measurement)

Overnight session work bundled in
- runtime/src/dirty_ram_interp.{c,h}: small MIPS interpreter for
  install-at-runtime kernel RAM stubs (Rule 18; e.g., SIO data-byte
  handler the BIOS writes to RAM 0xCF0)
- recompiler/src/full_function_emitter.{cpp,h}: 3057 jal/jalr continuation
  return labels added to dispatch table (continuation fix); branch
  fall-through fix for conditional-branch delay slots
- recompiler/src/strict_translator.cpp: matching translator updates
- generated/: regenerated SCPH1001 dispatch + full C output reflecting
  the recompiler changes
- runtime/include/debug_server.h, src/memory.c: card_txn ring + SIO IRQ
  ring + EvCB walk ring + per-PC dirty_ram counters + always-on wtrace
  coverage for [0x755A], [0x7514], [0x7528], [0x7520], [0x74A4],
  [0x75C0..C8], [0x74B8..C0]
- recompiler/tests/, runtime/tests/: SIO/card protocol unit tests
- tools/: 60+ Python diagnostic scripts (chain_trace analysis, SIO trace
  diff, EvCB walker, wtrace dumpers, etc.)
- docs/: psx_bios_disasm reference + dynamic_handler_install rationale
- OVERNIGHT_2026_04_28.md, SUMMARY_20260412_2.md: session logs

Phase 4 status (still blocked, root cause better understood)
- BIOS card chain runs through R-handlers correctly (chain_trace shows
  R1..R11 cycling 26x); shell IS retriggering _card_read
- Install handler at ROM 0xBFC15F1C increments [0x72F0] correctly per
  SIO IRQ; gate at <0x80 / <0x7F is correct
- Bottleneck: SIO IRQ countdown is access-paced, fires ~1× per VBlank
  vs ~128× needed; setup_data_phase (called from outer coord on VBlank)
  zeroes [0x72F0] before counter reaches 128
- Both attempted fixes today caused freezes:
  * VBlank deferral on [0x75C0]==1 — pending VBlank already in i_stat
    delivered anyway; tighter dispatch gate also locked up
  * Cycle-paced sio_tick at rates 50, 200 (and gated on [0x75C0]==1) —
    runtime freezes once data phase activates, root cause unidentified
- delay=5 narrows the threshold (peak=2 vs peak=1, no freeze) but
  doesn't get to 0x80
- Real fix likely requires deeper instrumentation of the freeze (call
  stack / dispatch state at the moment of TCP starvation)

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-04-28 21:29:19 -07:00

64 lines
2.4 KiB
Python

#!/usr/bin/env python3
"""Analyze sio_trace for abort patterns and state distribution."""
import json
import sys
from collections import Counter
path = sys.argv[1] if len(sys.argv) > 1 else '/tmp/sio_trace_full.json'
with open(path) as f:
data = json.load(f)
MC_NAMES = {
0:'IDLE', 1:'CMD', 2:'ID1', 3:'ID2', 4:'ADDR_MSB', 5:'ADDR_LSB',
6:'R_ACK1', 7:'R_ACK2', 8:'R_DATA', 9:'R_CHK', 10:'R_END',
}
# Count aborts by mc_state at abort
abort_states = Counter()
abort_funcs = Counter()
card_entries = 0
for e in data['entries']:
tx = int(e['tx'], 16) if isinstance(e['tx'], str) else e['tx']
if e['abort']:
state_name = MC_NAMES.get(e['mc_pre'], str(e['mc_pre']))
abort_states[state_name] += 1
abort_funcs[e['func']] += 1
if e['dev_post'] == 2 or e['dev_pre'] == 2:
card_entries += 1
print(f"Total entries: {data['count']}, Card-related: {card_entries}")
print(f"\nAbort by mc_state at abort time:")
for state, count in abort_states.most_common():
print(f" {state}: {count}")
print(f"\nAbort by calling function:")
for func, count in abort_funcs.most_common():
print(f" {func}: {count}")
# Find entries past ADDR_MSB
past = [e for e in data['entries'] if e['mc_post'] > 4]
print(f"\nEntries reaching past ADDR_MSB (state >4): {len(past)}")
for e in past[:10]:
tx = int(e['tx'], 16) if isinstance(e['tx'], str) else e['tx']
rx = int(e['rx'], 16) if isinstance(e['rx'], str) else e['rx']
pre = MC_NAMES.get(e['mc_pre'], str(e['mc_pre']))
post = MC_NAMES.get(e['mc_post'], str(e['mc_post']))
print(f" seq={e['seq']} tx=0x{tx:02X} rx=0x{rx:02X} mc:{pre}->{post} func={e['func']}")
# Show a complete card transaction attempt (first one in buffer)
print(f"\n--- First complete card transaction in buffer ---")
in_card = False
for e in data['entries']:
tx = int(e['tx'], 16) if isinstance(e['tx'], str) else e['tx']
rx = int(e['rx'], 16) if isinstance(e['rx'], str) else e['rx']
if tx == 0x81 and e['dev_post'] == 2:
in_card = True
if in_card:
pre = MC_NAMES.get(e['mc_pre'], str(e['mc_pre']))
post = MC_NAMES.get(e['mc_post'], str(e['mc_post']))
flag = " *ABORT*" if e['abort'] else ""
print(f" seq={e['seq']} tx=0x{tx:02X} rx=0x{rx:02X} mc:{pre:>10}->{post:<10} func={e['func']}{flag}")
if e['abort'] or (e['mc_post'] == 0 and e['mc_pre'] != 0):
in_card = False
break