diff --git a/runtime/CMakeLists.txt b/runtime/CMakeLists.txt index f13ca703..ba4bddf2 100644 --- a/runtime/CMakeLists.txt +++ b/runtime/CMakeLists.txt @@ -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 ---- diff --git a/runtime/include/starvation_ring.h b/runtime/include/starvation_ring.h new file mode 100644 index 00000000..57eb7a6a --- /dev/null +++ b/runtime/include/starvation_ring.h @@ -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 + +#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 */ diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index e864e84a..277bf3b4 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -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) { diff --git a/runtime/src/psx_cycles.c b/runtime/src/psx_cycles.c index 7e212328..49846e17 100644 --- a/runtime/src/psx_cycles.c +++ b/runtime/src/psx_cycles.c @@ -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) { diff --git a/runtime/src/sio.c b/runtime/src/sio.c index 590be919..a5bf375c 100644 --- a/runtime/src/sio.c +++ b/runtime/src/sio.c @@ -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++; } diff --git a/runtime/src/starvation_ring.c b/runtime/src/starvation_ring.c new file mode 100644 index 00000000..a0ff01f1 --- /dev/null +++ b/runtime/src/starvation_ring.c @@ -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 +#include +#include +#include + +#ifdef _WIN32 +#include +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 +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 */ diff --git a/tools/starvation_walk.py b/tools/starvation_walk.py new file mode 100644 index 00000000..906e91b1 --- /dev/null +++ b/tools/starvation_walk.py @@ -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 ?". 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 changed value vs the prior entry. + + Optional extra predicates restrict which entries are considered. + """ + if not argv: + print("usage: last_change [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 was non-zero.""" + if not argv: + print("usage: last_nonzero ", 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 [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 .""" + if not argv: + print("usage: since_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:]))