mirror/psxrecomp
1
0
Fork 0
mirror of https://github.com/RetroPortingToolKit/psxrecomp synced 2026-10-25 18:05:12 -04:00
Code Issues Packages Projects Releases Wiki Activity

runtime: drive SIO TX via cycle-paced shifter

Browse Source 
TX_DATA writes now route through the SIO0 shifter under
SIO_MODEL_CYCLE_PACED. Pad and card share the single-byte shifter and
TX buffer; bus owner is tagged on the first byte of each SELECT cycle.
sio_advance() is driven from psx_advance_cycles() so the shifter and
ACK pipeline progress on the guest CPU clock without touching the
legacy IRQ countdown.

The SELECT-deassert and TX_EN 1->0 paths now restore TX_RDY|TX_EMPTY
when they kill an in-flight shifter. Without this, sio_stat retained
the TX-clear bits set by SHIFT_START and the next handler busy-waited
forever on TX_RDY=0 inside the exception, deadlocking the BIOS.
Watchdog dump captured the deadlock at chain handler 0x445C with
stat=0x0000 across 4 seconds of PC samples.

Diagnostics added (passive/gated):
- starvation_ring records SIO MMIO events + periodic PC samples,
  watchdog dumps to JSONL on TCP-poll starvation
- starvation_walk.py queries the dump (last/last_change/why_idle)

Validation: shell-only sanity stable; one CROSS press no longer
hangs; mc_read_done climbs from 0 -> 30+ with mc_aborts=0.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Matthew Stanley
2026-04-29 21:15:09 -07:00
parent 44ca157481
commit 479c51934a
7 changed files with 945 additions and 90 deletions
Download Patch File Download Diff File Expand all files Collapse all files
runtime/CMakeLists.txt
+1
View File
@@ -28,6 +28,7 @@ set(PSX_SHARED_SOURCES
src/psx_oracle_stub.c
src/psx_oracle_cmds.c
src/psx_cycles.c
src/starvation_ring.c
)
# ---- Native target: recompiled BIOS, stub interpreter ----
runtime/include/starvation_ring.h
+108
View File
@@ -0,0 +1,108 @@
/*
* starvation_ring.h — Always-on diagnostic ring for capturing SIO/MMIO
* state immediately before a TCP-starvation hang.
*
* Phase 1.0e-e2 debug aid. Scope: diagnostic-only. Records every SIO MMIO
* event (TX_DATA write, RX read, STAT read, CTRL write) plus a snapshot
* of all SIO bus state at that moment. Watchdog monitors host wall-clock
* since last debug_server_poll; if it exceeds a threshold, the ring is
* flushed to disk and the process aborts cleanly so the dump survives.
*
* NOT for permanent use. Disabled by setting STARVATION_RING_ENABLED=0.
*/
#ifndef PSXRECOMP_V4_STARVATION_RING_H
#define PSXRECOMP_V4_STARVATION_RING_H
#include <stdint.h>
#ifdef __cplusplus
extern "C" {
#endif
#ifndef STARVATION_RING_ENABLED
#define STARVATION_RING_ENABLED 1
#endif
#define STARVATION_RING_CAP (1 << 14) /* 16K entries */
typedef enum {
SR_EVT_NONE = 0,
SR_EVT_TX_DATA_WRITE = 1,
SR_EVT_RX_DATA_READ = 2,
SR_EVT_STAT_READ = 3,
SR_EVT_CTRL_WRITE = 4,
SR_EVT_MODE_WRITE = 5,
SR_EVT_BAUD_WRITE = 6,
SR_EVT_SHIFT_START = 7,
SR_EVT_BUFFER_LOAD = 8,
SR_EVT_TX_DROPPED = 9,
SR_EVT_SHIFT_DONE = 10,
SR_EVT_ACK_FIRE = 11,
SR_EVT_SELECT_ASSERT = 12,
SR_EVT_SELECT_DEASS = 13,
SR_EVT_RESET = 14,
SR_EVT_PC_SAMPLE = 15, /* periodic PC sample, no MMIO event */
} StarvationEventKind;
typedef struct {
uint64_t seq; /* monotonic sequence */
uint64_t psx_cycle_count; /* guest cycle clock at event */
uint64_t host_us; /* host monotonic time in microseconds */
uint32_t current_func; /* g_debug_current_func_addr */
uint32_t last_store_pc; /* g_debug_last_store_pc */
uint16_t sio_ctrl;
uint16_t sio_stat;
uint8_t tx_data; /* on TX_DATA writes; else 0 */
uint8_t rx_data; /* on RX_DATA reads; else 0 */
uint8_t kind; /* StarvationEventKind */
uint8_t in_exception;
uint8_t shift_active;
uint8_t tx_buffered;
uint8_t pending_ack;
uint8_t bus_owner; /* SioBusOwner */
uint8_t active_device; /* DEV_NONE/PAD/MEMCARD */
uint8_t mc_state;
uint8_t pad_state;
uint8_t selected_slot;
uint8_t g_sio_timing_active;
uint8_t tx_rdy_visible; /* (sio_stat & 1) at event time */
uint8_t tx_em_visible; /* (sio_stat & 4) at event time */
uint8_t pad8;
uint16_t pad16;
int shift_remaining; /* cycles left on shifter */
int ack_remaining; /* cycles left on ack */
uint32_t bus_byte_index;
uint32_t i_stat;
uint32_t i_mask;
} StarvationEntry;
void starvation_ring_record(uint8_t kind, uint8_t tx, uint8_t rx,
uint16_t ctrl, uint16_t stat,
int shift_active, int shift_remaining,
int tx_buffered, int pending_ack,
int ack_remaining,
uint8_t bus_owner, uint32_t bus_byte_index,
uint8_t active_device, uint8_t mc_state,
uint8_t pad_state, uint8_t selected_slot,
int g_sio_timing_active);
/* Watchdog: call from debug_server_poll() to refresh the heartbeat.
* If too much wall-time passes without a refresh AND the BIOS is
* actively running (post-boot), the ring is dumped and the process
* aborts. */
void starvation_watchdog_heartbeat(void);
/* Run watchdog check from a hot path (e.g. psx_advance_cycles). */
void starvation_watchdog_check(void);
/* Manual dump-to-file (for testing / TCP probe). Filename can be NULL. */
void starvation_ring_dump(const char *path);
/* Periodic PC sample. Caller responsible for throttling. */
void starvation_ring_pc_sample(void);
#ifdef __cplusplus
}
#endif
#endif /* PSXRECOMP_V4_STARVATION_RING_H */
runtime/src/debug_server.c
+6
View File
@@ -3105,6 +3105,12 @@ void debug_server_init(int port)
void debug_server_poll(void)
{
/* Phase 1.0e-e2 starvation watchdog heartbeat. Refreshes the
* "last poll wall-clock" timestamp; if too much time passes
* between calls, the ring is dumped and the runtime aborts. */
extern void starvation_watchdog_heartbeat(void);
starvation_watchdog_heartbeat();
if (s_listen == SOCK_INVALID) return;
if (s_client == SOCK_INVALID) {
runtime/src/psx_cycles.c
+22 -6
View File
@@ -1,19 +1,35 @@
/* psx_cycles.c — PSX guest CPU cycle clock.
*
* Phase 1.0e-e1: dispatches to peripheral-only sio_advance (does NOT
* touch legacy sio_irq_pending/countdown). Until 1.0e-e2 reroutes the
* TX path, sio_advance returns immediately at the g_sio_timing_active
* gate without doing any work. */
/* psx_cycles.c — PSX guest CPU cycle clock. */
#include "psx_cycles.h"
#include "sio.h"
#include "starvation_ring.h"
uint64_t psx_cycle_count = 0;
/* Throttle watchdog check to once per ~64K cycles to keep hot-path cost
* negligible (most blocks emit 5-30 cycles, so the check fires every
* ~2K-12K blocks). */
static uint32_t s_watchdog_throttle = 0;
static uint32_t s_pc_sample_throttle = 0;
void psx_advance_cycles(uint32_t cycles) {
if (cycles == 0) return;
psx_cycle_count += (uint64_t)cycles;
sio_advance(cycles);
s_watchdog_throttle += cycles;
if (s_watchdog_throttle >= 65536u) {
s_watchdog_throttle = 0;
starvation_watchdog_check();
}
/* PC sample every ~1M cycles (~30us PSX, ~333Hz) — small enough to
* localize a busy-wait loop, sparse enough to not flood the 16K ring
* during normal SIO traffic (~3000 samples/sec vs >10K SIO events/sec
* during card transactions). */
s_pc_sample_throttle += cycles;
if (s_pc_sample_throttle >= 1048576u) {
s_pc_sample_throttle = 0;
starvation_ring_pc_sample();
}
}
uint64_t psx_get_cycle_count(void) {
runtime/src/sio.c
+155 -84
View File
@@ -197,6 +197,60 @@ static int sio_card_burst_drain(int max_iters);
extern int psx_get_in_exception(void);
extern uint8_t psx_read_byte(uint32_t addr);
/* ---- Phase 1.0e-e2 cycle-paced SIO state (lifted above sio_write) ----
*
* Pad and card share a single shifter / one-byte buffer / ACK pipeline.
* No device-specific paths. Macro is in sio.h; defaults to 1. */
volatile int g_sio_timing_active = 0;
#if SIO_MODEL_CYCLE_PACED
#define SIO_BAUD_CYCLES_DEFAULT 1088
#define SIO_ACK_CYCLES_DEFAULT 170
static int sio_tick_quantum_cycles = 64;
static int sio_shift_active = 0;
static uint8_t sio_shift_byte = 0;
static int sio_shift_remaining = 0;
static int sio_tx_buffered = 0;
static uint8_t sio_tx_buffer = 0;
static int sio_pending_ack = 0;
static int sio_ack_remaining = 0;
typedef enum {
SIO_OWNER_NONE = 0, SIO_OWNER_CARD = 1, SIO_OWNER_PAD = 2, SIO_OWNER_UNKNOWN = 3
} SioBusOwner;
static SioBusOwner sio_bus_owner = SIO_OWNER_NONE;
static uint32_t sio_bus_byte_index = 0;
static uint64_t s_pace_tx_writes_buffered;
static uint64_t s_pace_tx_writes_dropped_busy;
static uint64_t s_pace_tx_writes_dropped_cross_device;
static uint64_t s_pace_cross_device_pad_during_card;
static uint64_t s_pace_tx_buffer_promoted;
static uint64_t s_pace_tx_buffer_promoted_during_card;
static uint64_t s_pace_pad_byte_processed_in_card_data;
static uint64_t s_pace_shift_completes;
static uint64_t s_pace_ack_fires;
#endif
/* ---- Starvation-ring helper -------------------------------------------
* Fill in current SIO state at every recorded event. */
#include "starvation_ring.h"
static void sr_record(uint8_t kind, uint8_t tx, uint8_t rx) {
#if SIO_MODEL_CYCLE_PACED
starvation_ring_record(kind, tx, rx,
sio_ctrl, sio_stat,
sio_shift_active, sio_shift_remaining,
sio_tx_buffered, sio_pending_ack,
sio_ack_remaining,
(uint8_t)sio_bus_owner, sio_bus_byte_index,
(uint8_t)active_device, (uint8_t)mc_state,
(uint8_t)pad_state, (uint8_t)selected_slot,
g_sio_timing_active);
#else
starvation_ring_record(kind, tx, rx, sio_ctrl, sio_stat,
0, 0, 0, 0, 0, 0, 0,
(uint8_t)active_device, (uint8_t)mc_state,
(uint8_t)pad_state, (uint8_t)selected_slot, 0);
#endif
}
/* ---- Card transaction ring buffer ---- */
static SioTxnEntry sio_txn_buf[SIO_TXN_CAP];
@@ -908,12 +962,21 @@ uint32_t sio_read(uint32_t addr) {
sio_tick(0);
switch (addr) {
case 0x1F801040: /* SIO_RX_DATA */
case 0x1F801040: /* SIO_RX_DATA */ {
uint8_t b = sio_rx_data;
sio_stat &= ~SIO_STAT_RX_RDY;
return sio_rx_data;
sr_record(SR_EVT_RX_DATA_READ, 0, b);
return b;
}
case 0x1F801044: /* SIO_STAT */
case 0x1F801044: { /* SIO_STAT — record only on value transitions */
static uint16_t s_last_stat_observed = 0xFFFF;
if (sio_stat != s_last_stat_observed) {
s_last_stat_observed = sio_stat;
sr_record(SR_EVT_STAT_READ, 0, 0);
}
return sio_stat;
}
case 0x1F801048: /* SIO_MODE */
return sio_mode;
@@ -943,42 +1006,56 @@ void sio_write(uint32_t addr, uint32_t value) {
sio_tx_data = (uint8_t)value;
sio_tx_writes++;
sio_last_ctrl_on_tx = sio_ctrl;
if (!(sio_ctrl & SIO_CTRL_TX_EN)) sio_tx_gated++;
if (sio_ctrl & SIO_CTRL_TX_EN) {
/* IRQ-arm chain audit: capture pre-state for diagnostics.
* NOTE: bucket by active_device AT-DECISION-TIME (post-process),
* not pre-process — sio_process_byte (re)assigns active_device
* on its first byte / on deselect-continuation. */
if (!(sio_ctrl & SIO_CTRL_TX_EN)) {
sio_tx_gated++;
sr_record(SR_EVT_TX_DATA_WRITE, (uint8_t)value, 0);
break;
}
#if SIO_MODEL_CYCLE_PACED
/* Cycle-paced TX. Pad and card share single bus. */
{
uint8_t b = (uint8_t)value;
sr_record(SR_EVT_TX_DATA_WRITE, b, 0);
if (sio_bus_byte_index == 0) {
sio_bus_owner = (b == 0x81) ? SIO_OWNER_CARD
: (b == 0x01) ? SIO_OWNER_PAD
: SIO_OWNER_UNKNOWN;
}
sio_bus_byte_index++;
if (!sio_shift_active) {
sio_shift_byte = b;
sio_shift_active = 1;
sio_shift_remaining = SIO_BAUD_CYCLES_DEFAULT;
sio_stat &= ~(SIO_STAT_TX_RDY | SIO_STAT_TX_EMPTY);
g_sio_timing_active = 1;
sr_record(SR_EVT_SHIFT_START, b, 0);
} else if (!sio_tx_buffered) {
sio_tx_buffer = b;
sio_tx_buffered = 1;
sio_stat &= ~SIO_STAT_TX_EMPTY;
s_pace_tx_writes_buffered++;
sr_record(SR_EVT_BUFFER_LOAD, b, 0);
} else {
s_pace_tx_writes_dropped_busy++;
sr_record(SR_EVT_TX_DROPPED, b, 0);
}
}
#else
{
uint16_t arm_dbg_ctrl_pre = sio_ctrl;
uint16_t arm_dbg_stat_pre = sio_stat;
sio_process_byte(sio_tx_data);
/* Capture the device the if-block will read. */
uint8_t arm_dbg_dev_at_decision = (uint8_t)active_device;
/* Model SIO busy: on real hardware TX_RDY clears during the
* byte transfer (~BAUD*8 cycles) and re-sets when complete.
* The BIOS pad polling tight-loops on TX_RDY before sending
* each byte. Without this, pad polling proceeds instantly
* over a card byte that's still "in flight", interleaving
* pad and card protocols within the same interrupt. */
sio_stat &= ~(SIO_STAT_TX_RDY | SIO_STAT_TX_EMPTY);
/* IRQ-arm chain audit: count attempts and failure reasons.
* Counted only for the card path (active_device==DEV_MEMCARD).
* Exposed via sio_get_card_arm_audit() / debug_server. */
extern void sio_card_arm_audit_record(int dev, uint16_t ctrl_pre,
uint16_t stat_pre, uint16_t stat_post,
int armed, int countdown_after);
int armed_now = 0;
if ((sio_stat & SIO_STAT_ACK) && (sio_ctrl & SIO_CTRL_ACK_IRQ_EN)) {
sio_stat &= ~SIO_STAT_ACK;
sio_irq_pending = 1;
/* Use a longer delay for card transfers to keep TX_RDY
* cleared through pad polling within the same ISR. */
sio_irq_countdown = (active_device == DEV_MEMCARD)
? SIO_IRQ_DELAY_CARD : SIO_IRQ_DELAY_PAD;
/* Arm IRQ ring context for capture at fire time. */
sio_irq_pending_source = (active_device == DEV_MEMCARD)
? SIO_IRQ_SRC_CARD_ACK : SIO_IRQ_SRC_PAD_ACK;
sio_irq_pending_slot = (uint8_t)selected_slot;
@@ -987,20 +1064,22 @@ void sio_write(uint32_t addr, uint32_t value) {
sio_irq_pending_byte_seq = sio_trace_seq;
armed_now = 1;
}
sio_card_arm_audit_record(arm_dbg_dev_at_decision, arm_dbg_ctrl_pre,
arm_dbg_stat_pre, sio_stat,
armed_now, sio_irq_countdown);
}
#endif
break;
case 0x1F801048: /* SIO_MODE */
sio_mode = (uint16_t)value;
sr_record(SR_EVT_MODE_WRITE, (uint8_t)(value & 0xFF), (uint8_t)((value >> 8) & 0xFF));
break;
case 0x1F80104A: /* SIO_CTRL */ {
uint16_t old_ctrl = sio_ctrl;
sio_ctrl = (uint16_t)value;
sr_record(SR_EVT_CTRL_WRITE, (uint8_t)(value & 0xFF), (uint8_t)((value >> 8) & 0xFF));
if (value & SIO_CTRL_ACK) {
sio_stat &= ~SIO_STAT_IRQ;
sio_stat &= ~SIO_STAT_ACK;
@@ -1026,7 +1105,39 @@ void sio_write(uint32_t addr, uint32_t value) {
active_device = DEV_NONE;
sio_irq_pending = 0;
sio_irq_countdown = 0;
#if SIO_MODEL_CYCLE_PACED
sio_shift_active = 0; sio_shift_remaining = 0;
sio_tx_buffered = 0;
sio_pending_ack = 0; sio_ack_remaining = 0;
sio_bus_owner = SIO_OWNER_NONE; sio_bus_byte_index = 0;
g_sio_timing_active = 0;
#endif
sr_record(SR_EVT_RESET, 0, 0);
}
#if SIO_MODEL_CYCLE_PACED
if (!(old_ctrl & SIO_CTRL_SELECT) && (value & SIO_CTRL_SELECT)) {
sio_bus_owner = SIO_OWNER_NONE;
sio_bus_byte_index = 0;
sr_record(SR_EVT_SELECT_ASSERT, 0, 0);
}
/* TX_EN 1→0 transition kills any in-flight shifter the same
* way SELECT-deassert does. Restore TX_RDY/TX_EMPTY so the
* SIO returns to an idle status word, matching the recovery
* the SELECT-deassert path now performs. */
if ((old_ctrl & SIO_CTRL_TX_EN) && !(value & SIO_CTRL_TX_EN)) {
if (sio_shift_active || sio_tx_buffered || sio_pending_ack) {
sio_shift_active = 0; sio_shift_remaining = 0;
sio_tx_buffered = 0;
sio_pending_ack = 0; sio_ack_remaining = 0;
if (!(value & SIO_CTRL_SELECT)) {
sio_bus_owner = SIO_OWNER_NONE;
sio_bus_byte_index = 0;
}
g_sio_timing_active = 0;
sio_stat |= SIO_STAT_TX_RDY | SIO_STAT_TX_EMPTY;
}
}
#endif
/* On SELECT deassert: reset all volatile protocol state.
*
* Earlier model preserved mc_state into mc_slots[] so a card
@@ -1067,12 +1178,27 @@ void sio_write(uint32_t addr, uint32_t value) {
}
pad_state = PAD_IDLE;
active_device = DEV_NONE;
#if SIO_MODEL_CYCLE_PACED
sio_shift_active = 0; sio_shift_remaining = 0;
sio_tx_buffered = 0;
sio_pending_ack = 0; sio_ack_remaining = 0;
sio_bus_owner = SIO_OWNER_NONE; sio_bus_byte_index = 0;
g_sio_timing_active = 0;
/* Killing an in-flight shifter mid-cycle leaves sio_stat
* with TX_RDY/TX_EMPTY clear (they were masked by
* SHIFT_START and only sio_handle_shift_complete restores
* them). Restore here so the next handler sees an idle
* SIO instead of busy-waiting forever on TX_RDY=0. */
sio_stat |= SIO_STAT_TX_RDY | SIO_STAT_TX_EMPTY;
#endif
sr_record(SR_EVT_SELECT_DEASS, 0, 0);
}
break;
}
case 0x1F80104E: /* SIO_BAUD */
sio_baud = (uint16_t)value;
sr_record(SR_EVT_BAUD_WRITE, (uint8_t)(value & 0xFF), (uint8_t)((value >> 8) & 0xFF));
break;
default:
@@ -1201,64 +1327,7 @@ void sio_get_burst_stats(uint64_t out[10]) {
#define SIO_MODEL_CYCLE_PACED 1
#endif
/* Hot-path active guard. Defined unconditionally (so its address exists
* for any caller), but only meaningfully used when macro=1. */
volatile int g_sio_timing_active = 0;
#if SIO_MODEL_CYCLE_PACED
/* ---- Phase 1.0b: cycle-paced SIO state (inert) ---------------------------
*
* Declared under macro guard so they exist only in cycle-paced builds.
* Phase 1.0b adds the variables; Phase 1.0c+ wires them into sio_tick /
* sio_write SIO_TX_DATA / sio_write SIO_CTRL paths. With the macro
* defaulting to 0 (Phase 1.0a/b posture), no code references these — they
* are file-scope statics with no callers, no readers, no telemetry hooks.
*
* Hardware-time constants. PSX SIO0 default baud (BAUD=0x88, factor 8) is
* approximately 1088 CPU cycles per byte; the device-side ACK arrives
* about 170 cycles after the byte completes shifting on the bus. */
#define SIO_BAUD_CYCLES_DEFAULT 1088
#define SIO_ACK_CYCLES_DEFAULT 170
/* Dispatch-loop quantum: SIO time advance per !in_exception
* psx_check_interrupts call. Tunable in Phase 1.0c+ via TCP. Phase 1.0b:
* declared only, never referenced. */
static int sio_tick_quantum_cycles = 64;
/* TX shifter and one-byte TX buffer modelling JOY_TX_DATA. */
static int sio_shift_active = 0;
static uint8_t sio_shift_byte = 0;
static int sio_shift_remaining = 0;
static int sio_tx_buffered = 0;
static uint8_t sio_tx_buffer = 0;
static int sio_pending_ack = 0;
static int sio_ack_remaining = 0;
/* Bus ownership over the SELECT lifetime. Set on FIRST accepted byte of
* each SELECT-asserted lifetime; never reclassified. Cleared on SELECT
* deassert / RESET / TX_EN clear. Not used in 1.0b. */
typedef enum {
SIO_OWNER_NONE = 0,
SIO_OWNER_CARD = 1,
SIO_OWNER_PAD = 2,
SIO_OWNER_UNKNOWN = 3,
} SioBusOwner;
static SioBusOwner sio_bus_owner = SIO_OWNER_NONE;
static uint32_t sio_bus_byte_index = 0;
/* Telemetry counters (Phase 1.0d will populate; Phase 1.0b just declares).
* pad_byte_processed_in_card_data is the hard-failure assertion: must
* remain 0 once cycle-paced TX path is wired. */
static uint64_t s_pace_tx_writes_buffered;
static uint64_t s_pace_tx_writes_dropped_busy;
static uint64_t s_pace_tx_writes_dropped_cross_device;
static uint64_t s_pace_cross_device_pad_during_card;
static uint64_t s_pace_tx_buffer_promoted;
static uint64_t s_pace_tx_buffer_promoted_during_card;
static uint64_t s_pace_pad_byte_processed_in_card_data;
static uint64_t s_pace_shift_completes;
static uint64_t s_pace_ack_fires;
#endif /* SIO_MODEL_CYCLE_PACED */
/* Cycle-paced SIO state moved above sio_write (after forward decls). */
#if SIO_MODEL_CYCLE_PACED
/* ---- Phase 1.0c-v2: cycle-paced sio_tick helpers (inert in 1.0c-v2) ---
@@ -1276,6 +1345,7 @@ static int sio_consume_ack_event(void) {
static void sio_fire_ack_irq(void) {
sio_stat |= SIO_STAT_ACK;
sr_record(SR_EVT_ACK_FIRE, 0, 0);
if (!(sio_ctrl & SIO_CTRL_ACK_IRQ_EN)) return;
sio_stat |= SIO_STAT_IRQ;
@@ -1307,6 +1377,7 @@ static void sio_fire_ack_irq(void) {
static void sio_handle_shift_complete(void) {
uint8_t b = sio_shift_byte;
sr_record(SR_EVT_SHIFT_DONE, b, 0);
if (b == 0x01 && mc_state >= MC_READ_DATA && mc_state <= MC_READ_END) {
s_pace_pad_byte_processed_in_card_data++;
}
runtime/src/starvation_ring.c
+243
View File
@@ -0,0 +1,243 @@
/* starvation_ring.c — diagnostic-only.
*
* Always-on ring of the last 16K SIO/MMIO events with full SIO state
* snapshot at each event. Watchdog flushes the ring to a file and
* aborts cleanly when host wall-clock since the last
* debug_server_poll exceeds the threshold (TCP listener has stopped
* draining the connection — symptom of dispatch-loop starvation).
*
* The dumped file is plain JSON-lines (one event per line) so it can
* be inspected with grep/jq even after the process terminated. */
#include "starvation_ring.h"
#include "psx_cycles.h"
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
#ifdef _WIN32
#include <windows.h>
static uint64_t host_us_now(void) {
LARGE_INTEGER f, c;
static LARGE_INTEGER freq = {0};
if (freq.QuadPart == 0) QueryPerformanceFrequency(&freq);
QueryPerformanceCounter(&c);
return (uint64_t)((c.QuadPart * 1000000ULL) / freq.QuadPart);
}
#else
#include <sys/time.h>
static uint64_t host_us_now(void) {
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return (uint64_t)ts.tv_sec * 1000000ULL + (uint64_t)ts.tv_nsec / 1000ULL;
}
#endif
extern uint32_t g_debug_current_func_addr;
extern uint32_t g_debug_last_store_pc;
extern uint32_t i_stat;
extern uint32_t i_mask;
extern int psx_get_in_exception(void);
#if STARVATION_RING_ENABLED
static StarvationEntry s_ring[STARVATION_RING_CAP];
static uint64_t s_seq = 0;
static uint64_t s_last_heartbeat_us = 0;
static int s_dump_done = 0;
/* Watchdog threshold: 4 seconds of wall-clock without a heartbeat is
* "TCP died, BIOS still running" territory. Real BIOS pad polling
* fires VBlank ~60Hz so debug_server_poll runs at ~60Hz. 4 seconds
* is well past any normal stall. */
#define STARVATION_TIMEOUT_US (4 * 1000000ULL)
void starvation_watchdog_heartbeat(void) {
s_last_heartbeat_us = host_us_now();
}
void starvation_ring_record(uint8_t kind, uint8_t tx, uint8_t rx,
uint16_t ctrl, uint16_t stat,
int shift_active, int shift_remaining,
int tx_buffered, int pending_ack,
int ack_remaining,
uint8_t bus_owner, uint32_t bus_byte_index,
uint8_t active_device, uint8_t mc_state,
uint8_t pad_state, uint8_t selected_slot,
int g_sio_timing_active) {
StarvationEntry *e = &s_ring[s_seq & (STARVATION_RING_CAP - 1)];
e->seq = s_seq++;
e->psx_cycle_count = psx_get_cycle_count();
e->host_us = host_us_now();
e->current_func = g_debug_current_func_addr;
e->last_store_pc = g_debug_last_store_pc;
e->sio_ctrl = ctrl;
e->sio_stat = stat;
e->tx_data = tx;
e->rx_data = rx;
e->kind = kind;
e->in_exception = (uint8_t)psx_get_in_exception();
e->shift_active = (uint8_t)shift_active;
e->tx_buffered = (uint8_t)tx_buffered;
e->pending_ack = (uint8_t)pending_ack;
e->bus_owner = bus_owner;
e->active_device = active_device;
e->mc_state = mc_state;
e->pad_state = pad_state;
e->selected_slot = selected_slot;
e->g_sio_timing_active = (uint8_t)g_sio_timing_active;
e->tx_rdy_visible = (uint8_t)((stat >> 0) & 1);
e->tx_em_visible = (uint8_t)((stat >> 2) & 1);
e->shift_remaining = shift_remaining;
e->ack_remaining = ack_remaining;
e->bus_byte_index = bus_byte_index;
e->i_stat = i_stat;
e->i_mask = i_mask;
}
static const char *kind_name(uint8_t k) {
switch (k) {
case SR_EVT_TX_DATA_WRITE: return "TX_WRITE";
case SR_EVT_RX_DATA_READ: return "RX_READ";
case SR_EVT_STAT_READ: return "STAT_READ";
case SR_EVT_CTRL_WRITE: return "CTRL_WRITE";
case SR_EVT_MODE_WRITE: return "MODE_WRITE";
case SR_EVT_BAUD_WRITE: return "BAUD_WRITE";
case SR_EVT_SHIFT_START: return "SHIFT_START";
case SR_EVT_BUFFER_LOAD: return "BUFFER_LOAD";
case SR_EVT_TX_DROPPED: return "TX_DROPPED";
case SR_EVT_SHIFT_DONE: return "SHIFT_DONE";
case SR_EVT_ACK_FIRE: return "ACK_FIRE";
case SR_EVT_SELECT_ASSERT: return "SELECT_ASSERT";
case SR_EVT_SELECT_DEASS: return "SELECT_DEASSERT";
case SR_EVT_RESET: return "RESET";
case SR_EVT_PC_SAMPLE: return "PC_SAMPLE";
default: return "?";
}
}
/* PC sampler. Records current PC + in_exc + i_stat/i_mask without
* touching SIO state — used to localize busy-wait loops that don't
* touch MMIO. Caller responsible for throttling (~every 1M cycles). */
void starvation_ring_pc_sample(void) {
StarvationEntry *e = &s_ring[s_seq & (STARVATION_RING_CAP - 1)];
e->seq = s_seq++;
e->psx_cycle_count = psx_get_cycle_count();
e->host_us = host_us_now();
e->current_func = g_debug_current_func_addr;
e->last_store_pc = g_debug_last_store_pc;
e->sio_ctrl = 0;
e->sio_stat = 0;
e->tx_data = 0;
e->rx_data = 0;
e->kind = SR_EVT_PC_SAMPLE;
e->in_exception = (uint8_t)psx_get_in_exception();
e->shift_active = 0;
e->tx_buffered = 0;
e->pending_ack = 0;
e->bus_owner = 0;
e->active_device = 0;
e->mc_state = 0;
e->pad_state = 0;
e->selected_slot = 0;
e->g_sio_timing_active = 0;
e->tx_rdy_visible = 0;
e->tx_em_visible = 0;
e->shift_remaining = 0;
e->ack_remaining = 0;
e->bus_byte_index = 0;
e->i_stat = i_stat;
e->i_mask = i_mask;
}
void starvation_ring_dump(const char *path) {
if (s_dump_done) return; /* dump exactly once */
s_dump_done = 1;
const char *file = path ? path : "starvation_dump.jsonl";
FILE *f = fopen(file, "w");
if (!f) return;
uint64_t total = s_seq;
uint64_t avail = total < STARVATION_RING_CAP ? total : STARVATION_RING_CAP;
fprintf(f, "{\"meta\":{\"total\":%llu,\"shown\":%llu,"
"\"last_heartbeat_us\":%llu,\"now_us\":%llu,"
"\"psx_cycle_count\":%llu,"
"\"current_func\":\"0x%08X\",\"last_store_pc\":\"0x%08X\","
"\"in_exception\":%u,\"i_stat\":\"0x%08X\",\"i_mask\":\"0x%08X\"}}\n",
(unsigned long long)total, (unsigned long long)avail,
(unsigned long long)s_last_heartbeat_us,
(unsigned long long)host_us_now(),
(unsigned long long)psx_get_cycle_count(),
g_debug_current_func_addr, g_debug_last_store_pc,
(unsigned)psx_get_in_exception(),
i_stat, i_mask);
uint64_t start = total > avail ? total - avail : 0;
for (uint64_t i = start; i < total; i++) {
StarvationEntry *e = &s_ring[i & (STARVATION_RING_CAP - 1)];
fprintf(f,
"{\"seq\":%llu,\"kind\":\"%s\",\"cyc\":%llu,\"us\":%llu,"
"\"func\":\"0x%08X\",\"pc\":\"0x%08X\","
"\"ctrl\":\"0x%04X\",\"stat\":\"0x%04X\","
"\"tx\":\"0x%02X\",\"rx\":\"0x%02X\","
"\"in_exc\":%u,\"shift_act\":%u,\"shift_rem\":%d,"
"\"buf\":%u,\"ack_pend\":%u,\"ack_rem\":%d,"
"\"owner\":%u,\"bbidx\":%u,"
"\"dev\":%u,\"mc\":%u,\"pad\":%u,\"slot\":%u,"
"\"gact\":%u,\"tx_rdy\":%u,\"tx_em\":%u,"
"\"i_stat\":\"0x%08X\",\"i_mask\":\"0x%08X\"}\n",
(unsigned long long)e->seq, kind_name(e->kind),
(unsigned long long)e->psx_cycle_count,
(unsigned long long)e->host_us,
e->current_func, e->last_store_pc,
e->sio_ctrl, e->sio_stat,
e->tx_data, e->rx_data,
e->in_exception, e->shift_active, e->shift_remaining,
e->tx_buffered, e->pending_ack, e->ack_remaining,
e->bus_owner, e->bus_byte_index,
e->active_device, e->mc_state, e->pad_state, e->selected_slot,
e->g_sio_timing_active, e->tx_rdy_visible, e->tx_em_visible,
e->i_stat, e->i_mask);
}
fclose(f);
}
void starvation_watchdog_check(void) {
if (s_dump_done) return;
if (s_last_heartbeat_us == 0) return; /* not initialized yet */
uint64_t now = host_us_now();
if (now - s_last_heartbeat_us > STARVATION_TIMEOUT_US) {
starvation_ring_dump(NULL);
/* Abort cleanly so the dump file is preserved and the user knows
* the runtime starved. */
fprintf(stderr, "starvation_watchdog: %llu us without heartbeat — "
"ring dumped to starvation_dump.jsonl, aborting\n",
(unsigned long long)(now - s_last_heartbeat_us));
fflush(stderr);
exit(2);
}
}
#else
void starvation_ring_record(uint8_t kind, uint8_t tx, uint8_t rx,
uint16_t ctrl, uint16_t stat,
int shift_active, int shift_remaining,
int tx_buffered, int pending_ack,
int ack_remaining,
uint8_t bus_owner, uint32_t bus_byte_index,
uint8_t active_device, uint8_t mc_state,
uint8_t pad_state, uint8_t selected_slot,
int g_sio_timing_active) {
(void)kind; (void)tx; (void)rx; (void)ctrl; (void)stat;
(void)shift_active; (void)shift_remaining;
(void)tx_buffered; (void)pending_ack; (void)ack_remaining;
(void)bus_owner; (void)bus_byte_index;
(void)active_device; (void)mc_state; (void)pad_state;
(void)selected_slot; (void)g_sio_timing_active;
}
void starvation_watchdog_heartbeat(void) {}
void starvation_watchdog_check(void) {}
void starvation_ring_dump(const char *path) { (void)path; }
void starvation_ring_pc_sample(void) {}
#endif /* STARVATION_RING_ENABLED */
tools/starvation_walk.py
+410
View File
@@ -0,0 +1,410 @@
#!/usr/bin/env python3
"""starvation_walk.py — query helper for starvation_dump.jsonl.
The starvation ring captures every SIO MMIO event + periodic PC samples
+ SIO state at each event. When the watchdog dumps, we get a JSONL file
where line 0 is the meta and lines 1..N are events in chronological order.
This walker reverses the order and answers questions of the form
"working backward from the watchdog fire, what was the last event that
matched <predicate>?". Reasoning forward through 14K events is wasteful;
reasoning backward is how we naturally diagnose hangs.
Examples:
starvation_walk.py meta
starvation_walk.py last kind=CTRL_WRITE
starvation_walk.py last_change ctrl
starvation_walk.py last_change stat
starvation_walk.py last stat=0x0000
starvation_walk.py last_nonzero stat
starvation_walk.py since_pc 0xBFC14054 kind=CTRL_WRITE
starvation_walk.py between 12900 12910
starvation_walk.py why_idle # composite: last events that drove SIO idle
Predicate syntax:
field=value — equality (decimal or 0xHEX, both sides normalized to int)
field~regex — string match (against the JSON value as text)
field!=value — not equal
field>value — greater (numeric)
Multiple predicates AND together: `kind=CTRL_WRITE ctrl=0x0000`.
"""
from __future__ import annotations
import json
import re
import sys
from pathlib import Path
from typing import Any, Callable, Iterable
DEFAULT_PATH = Path("starvation_dump.jsonl")
NUMERIC_FIELDS = {
"seq", "cyc", "us",
"in_exc", "shift_act", "shift_rem", "buf", "ack_pend", "ack_rem",
"owner", "bbidx", "dev", "mc", "pad", "slot", "gact", "tx_rdy", "tx_em",
}
HEX_FIELDS = {
"func", "pc", "ctrl", "stat", "tx", "rx", "i_stat", "i_mask",
}
ALL_FIELDS = NUMERIC_FIELDS | HEX_FIELDS | {"kind"}
def _parse_int(s: str) -> int:
s = s.strip()
if s.lower().startswith("0x"):
return int(s, 16)
return int(s, 10)
def _coerce(field: str, raw_value: Any) -> Any:
"""Coerce a JSON value to a comparable form per field type."""
if field == "kind":
return str(raw_value)
if field in HEX_FIELDS:
if isinstance(raw_value, str):
return _parse_int(raw_value)
return int(raw_value)
if field in NUMERIC_FIELDS:
return int(raw_value)
return raw_value
def _coerce_pred_value(field: str, raw: str) -> Any:
if field == "kind":
return raw
if field in HEX_FIELDS or field in NUMERIC_FIELDS:
return _parse_int(raw)
return raw
PRED_RE = re.compile(r"^([a-zA-Z_][a-zA-Z0-9_]*)(==|!=|=|~|>=|<=|>|<)(.+)$")
def parse_predicate(token: str) -> Callable[[dict], bool]:
m = PRED_RE.match(token)
if not m:
raise ValueError(f"bad predicate: {token!r}")
field, op, raw = m.group(1), m.group(2), m.group(3)
if op == "==":
op = "="
def get(entry: dict) -> Any:
if field not in entry:
return None
return _coerce(field, entry[field])
if op == "~":
rx = re.compile(raw)
return lambda e: (lambda v: v is not None and rx.search(str(v)))(get(e))
target = _coerce_pred_value(field, raw)
if op == "=":
return lambda e: get(e) == target
if op == "!=":
return lambda e: get(e) != target
if op == ">":
return lambda e: (lambda v: v is not None and v > target)(get(e))
if op == "<":
return lambda e: (lambda v: v is not None and v < target)(get(e))
if op == ">=":
return lambda e: (lambda v: v is not None and v >= target)(get(e))
if op == "<=":
return lambda e: (lambda v: v is not None and v <= target)(get(e))
raise ValueError(f"bad op: {op!r}")
def parse_predicates(tokens: Iterable[str]) -> Callable[[dict], bool]:
preds = [parse_predicate(t) for t in tokens]
if not preds:
return lambda _e: True
return lambda e: all(p(e) for p in preds)
def load(path: Path) -> tuple[dict, list[dict]]:
lines = path.read_text(encoding="utf-8").splitlines()
if not lines:
return {}, []
meta_obj = json.loads(lines[0])
meta = meta_obj.get("meta", {}) if isinstance(meta_obj, dict) else {}
events: list[dict] = []
for line in lines[1:]:
line = line.strip()
if not line:
continue
try:
events.append(json.loads(line))
except json.JSONDecodeError:
continue
return meta, events
def fmt(e: dict) -> str:
"""Compact one-line entry render."""
return (
f"#{e.get('seq'):>5} {e.get('kind','?'):>15} "
f"cyc={e.get('cyc')} us={e.get('us')} "
f"func={e.get('func')} pc={e.get('pc')} "
f"ctrl={e.get('ctrl')} stat={e.get('stat')} "
f"tx={e.get('tx')} rx={e.get('rx')} "
f"in_exc={e.get('in_exc')} shift={e.get('shift_act')}/{e.get('shift_rem')} "
f"ack={e.get('ack_pend')}/{e.get('ack_rem')} "
f"owner={e.get('owner')} bbidx={e.get('bbidx')} "
f"dev={e.get('dev')} mc={e.get('mc')} pad={e.get('pad')} "
f"gact={e.get('gact')} i_stat={e.get('i_stat')} i_mask={e.get('i_mask')}"
)
def cmd_meta(meta: dict, _events: list[dict], _argv: list[str]) -> int:
for k, v in meta.items():
print(f"{k:>20}: {v}")
return 0
def cmd_last(meta: dict, events: list[dict], argv: list[str]) -> int:
pred = parse_predicates(argv)
for e in reversed(events):
if pred(e):
print(fmt(e))
return 0
print("no match")
return 1
def cmd_first(meta: dict, events: list[dict], argv: list[str]) -> int:
pred = parse_predicates(argv)
for e in events:
if pred(e):
print(fmt(e))
return 0
print("no match")
return 1
def cmd_all(meta: dict, events: list[dict], argv: list[str]) -> int:
"""Print every match (forward order) with optional limit."""
limit = None
rest = []
for tok in argv:
if tok.startswith("limit="):
limit = int(tok[len("limit="):])
else:
rest.append(tok)
pred = parse_predicates(rest)
n = 0
for e in events:
if pred(e):
print(fmt(e))
n += 1
if limit and n >= limit:
break
print(f"# {n} match(es)", file=sys.stderr)
return 0 if n > 0 else 1
def cmd_count(meta: dict, events: list[dict], argv: list[str]) -> int:
pred = parse_predicates(argv)
n = sum(1 for e in events if pred(e))
print(n)
return 0
def cmd_last_change(meta: dict, events: list[dict], argv: list[str]) -> int:
"""Find the last entry where <field> changed value vs the prior entry.
Optional extra predicates restrict which entries are considered.
"""
if not argv:
print("usage: last_change <field> [pred ...]", file=sys.stderr)
return 2
field = argv[0]
if field not in ALL_FIELDS:
print(f"unknown field: {field}", file=sys.stderr)
return 2
pred = parse_predicates(argv[1:])
last_val = object()
change_event = None
prior_event = None
for e in events:
if not pred(e):
continue
if field not in e:
continue
v = _coerce(field, e[field])
if last_val is object:
last_val = v
continue
if v != last_val:
change_event = e
prior_event_at_change = prior_event
last_val = v
prior_event = e
if change_event is None:
print("no change")
return 1
print("LAST CHANGE OF", field)
if 'prior_event_at_change' in locals() and prior_event_at_change is not None:
print(" prior:", fmt(prior_event_at_change))
print(" after:", fmt(change_event))
return 0
def cmd_last_nonzero(meta: dict, events: list[dict], argv: list[str]) -> int:
"""Last entry where <field> was non-zero."""
if not argv:
print("usage: last_nonzero <field>", file=sys.stderr)
return 2
field = argv[0]
pred = parse_predicates(argv[1:])
for e in reversed(events):
if not pred(e):
continue
if field not in e:
continue
v = _coerce(field, e[field])
if isinstance(v, int) and v != 0:
print(fmt(e))
return 0
print("no nonzero")
return 1
def cmd_between(meta: dict, events: list[dict], argv: list[str]) -> int:
if len(argv) < 2:
print("usage: between <seq_a> <seq_b> [pred ...]", file=sys.stderr)
return 2
a, b = int(argv[0]), int(argv[1])
if a > b:
a, b = b, a
pred = parse_predicates(argv[2:])
for e in events:
s = e.get("seq")
if s is None:
continue
if a <= s <= b and pred(e):
print(fmt(e))
return 0
def cmd_since_pc(meta: dict, events: list[dict], argv: list[str]) -> int:
"""Walk forward from the last entry whose pc equals <pc>."""
if not argv:
print("usage: since_pc <pc> [pred ...]", file=sys.stderr)
return 2
target = _parse_int(argv[0])
pred = parse_predicates(argv[1:])
start_idx = None
for i in range(len(events) - 1, -1, -1):
pc = events[i].get("pc")
if pc is None:
continue
if _parse_int(pc) == target:
start_idx = i
break
if start_idx is None:
print("pc not seen")
return 1
print(f"# starting at #{events[start_idx].get('seq')}")
for e in events[start_idx:]:
if pred(e):
print(fmt(e))
return 0
def cmd_why_idle(meta: dict, events: list[dict], argv: list[str]) -> int:
"""Composite walk: identify the events that drove SIO into idle.
Walks back from the end and reports:
- last SHIFT_START / SHIFT_DONE / ACK_FIRE
- last CTRL_WRITE that wrote ctrl=0x0000 or RESET
- last SELECT_DEASSERT / SELECT_ASSERT
- last TX_WRITE
- last STAT value transition before the hang
- first PC that repeats in the trailing PC samples
"""
finds = []
def find_last(label: str, pred: Callable[[dict], bool]):
for e in reversed(events):
if pred(e):
finds.append((label, e))
return
find_last("last SHIFT_START", lambda e: e.get("kind") == "SHIFT_START")
find_last("last SHIFT_DONE", lambda e: e.get("kind") == "SHIFT_DONE")
find_last("last ACK_FIRE", lambda e: e.get("kind") == "ACK_FIRE")
find_last("last TX_WRITE", lambda e: e.get("kind") == "TX_WRITE")
find_last("last RX_READ", lambda e: e.get("kind") == "RX_READ")
find_last("last CTRL_WRITE", lambda e: e.get("kind") == "CTRL_WRITE")
find_last("last CTRL=0x0000",
lambda e: e.get("kind") == "CTRL_WRITE"
and e.get("ctrl") == "0x0000")
find_last("last SELECT_ASSERT",
lambda e: e.get("kind") == "SELECT_ASSERT")
find_last("last SELECT_DEASSERT",
lambda e: e.get("kind") == "SELECT_DEASSERT")
find_last("last RESET", lambda e: e.get("kind") == "RESET")
find_last("last STAT_READ", lambda e: e.get("kind") == "STAT_READ")
print(f"# meta: psx_cycle_count={meta.get('psx_cycle_count')} "
f"current_func={meta.get('current_func')} "
f"in_exception={meta.get('in_exception')} "
f"i_stat={meta.get('i_stat')} i_mask={meta.get('i_mask')}")
finds.sort(key=lambda kv: -(kv[1].get("seq") or 0))
for label, e in finds:
print(f"{label:>22}: {fmt(e)}")
# PC-sample histogram (trailing N seconds of PC samples).
pc_samples = [e for e in events if e.get("kind") == "PC_SAMPLE"]
if pc_samples:
hist: dict[tuple[str, str], int] = {}
for e in pc_samples:
key = (str(e.get("func")), str(e.get("pc")))
hist[key] = hist.get(key, 0) + 1
ranked = sorted(hist.items(), key=lambda kv: -kv[1])
print("\n# pc-sample histogram (top 5):")
for (func, pc), n in ranked[:5]:
pct = 100.0 * n / len(pc_samples)
print(f" {n:>5} ({pct:5.1f}%) func={func} pc={pc}")
return 0
COMMANDS = {
"meta": cmd_meta,
"last": cmd_last,
"first": cmd_first,
"all": cmd_all,
"count": cmd_count,
"last_change": cmd_last_change,
"last_nonzero": cmd_last_nonzero,
"between": cmd_between,
"since_pc": cmd_since_pc,
"why_idle": cmd_why_idle,
}
def main(argv: list[str]) -> int:
path = DEFAULT_PATH
if argv and argv[0].startswith("--file="):
path = Path(argv[0][len("--file="):])
argv = argv[1:]
if not argv:
print(__doc__)
print("commands:", " ".join(COMMANDS), file=sys.stderr)
return 2
cmd = argv[0]
rest = argv[1:]
if cmd not in COMMANDS:
print(f"unknown command: {cmd}", file=sys.stderr)
print("commands:", " ".join(COMMANDS), file=sys.stderr)
return 2
if not path.exists():
print(f"no dump at {path}", file=sys.stderr)
return 2
meta, events = load(path)
return COMMANDS[cmd](meta, events, rest)
if __name__ == "__main__":
sys.exit(main(sys.argv[1:]))