diff --git a/TCP_COMMANDS.md b/TCP_COMMANDS.md index 0ef91836..0e06696d 100644 --- a/TCP_COMMANDS.md +++ b/TCP_COMMANDS.md @@ -101,6 +101,27 @@ When a recompiled-BIOS bug is suspected, the two servers let you find the **firs --- +## Server send budget + serve-stall telemetry + +The server is pumped on the **main thread**: every millisecond it spends +sending a response is a millisecond the emulator does not run. Inline +responses are bounded — 2 s per zero-progress chunk and **15 s total per +response**; a client that exceeds the budget is disconnected (the runtime +never stalls indefinitely). Responses bigger than the budget allows must +use the `*_dump_file` variants, which write to disk instead of the socket. + +Cumulative serve-stall is exported as `tcp_send_stall_ms` / +`tcp_clients_dropped` in `psx_freeze_heartbeat.json` (plus per-tick +`tcp_ms` in its ring) and in every wedge/fatal dump header. **Check these +first when diagnosing slow or stalled frames** — on 2026-06-10 two +"attract-idle degradations" turned out to be a TCP client trickle-draining +mega-dumps, throttling the main loop to 6 fps (all 8 watchdog stack +samples inside `WS2_32!send`). A slow-frames wedge with a large +`tcp_send_stall_ms` delta over the same window is observer interference, +not a guest bug. + +--- + ## Rule when the server can't answer your question If an inspection need isn't covered by the existing commands, **do not fall back to printf or log files**. Instead: diff --git a/runtime/include/debug_server.h b/runtime/include/debug_server.h index cdd61ccf..18097062 100644 --- a/runtime/include/debug_server.h +++ b/runtime/include/debug_server.h @@ -87,6 +87,13 @@ void debug_server_init(int port); * Call once per vblank. */ void debug_server_poll(void); +/* TCP serve-stall telemetry: cumulative main-thread ms spent inside + * bounded TCP sends, and clients dropped for exceeding the send budget. + * Surfaced in the freeze heartbeat / wedge dumps so a TCP-throttled run + * is never misattributed to a guest-side stall. */ +uint64_t debug_server_get_tcp_stall_ms(void); +uint32_t debug_server_get_tcp_drops(void); + /* Record the current frame's state into the ring buffer. * Call after vblank processing. */ void debug_server_record_frame(void); diff --git a/runtime/src/debug_server.c b/runtime/src/debug_server.c index 572d29f9..406704dc 100644 --- a/runtime/src/debug_server.c +++ b/runtime/src/debug_server.c @@ -3291,18 +3291,46 @@ static uint32_t hex_to_u32(const char *s) /* ---- Send helpers ---- */ +/* TCP serve-stall telemetry. The server is pumped on the main thread, so + * every millisecond spent inside send_all_blocking is a millisecond the + * emulator did not run. Surfaced in the freeze heartbeat and wedge dumps + * so a TCP-throttled run can never be misread as a guest-side bug + * (2026-06-10: two pre-fix attract "degradations" were exactly this — + * 6 fps crawl + final stall, all main-thread time inside WS2_32!send). */ +static uint64_t s_tcp_send_stall_ms = 0; +static uint32_t s_tcp_clients_dropped = 0; + +uint64_t debug_server_get_tcp_stall_ms(void) { return s_tcp_send_stall_ms; } +uint32_t debug_server_get_tcp_drops(void) { return s_tcp_clients_dropped; } + +static uint64_t monotonic_ms(void) +{ +#ifdef _WIN32 + return (uint64_t)GetTickCount64(); +#else + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + return (uint64_t)ts.tv_sec * 1000u + (uint64_t)(ts.tv_nsec / 1000000); +#endif +} + /* Bounded blocking send. Returns 0 on success, -1 on failure/timeout. * * The server is pumped on the main thread, so an unbounded send to a * client that has stopped draining stalls the emulator until the * starvation watchdog (4 s) kills the whole process. Each chunk gets a - * 2 s send timeout and a watchdog heartbeat, so a healthy-but-slow - * client can take as long as it likes (progress = heartbeats), while a - * wedged client costs at most one timeout and then loses its - * connection — never the runtime. */ + * 2 s send timeout and a watchdog heartbeat. A slow-but-alive client is + * additionally bounded by a TOTAL budget per call: a trickle-draining + * client used to be able to throttle the emulator indefinitely (progress + * heartbeats kept the watchdog quiet). Past the budget the client loses + * its connection — never the runtime. Responses too big to send inside + * the budget must use the *_dump_file commands instead. */ +#define SEND_TOTAL_BUDGET_MS 15000u + static int send_all_blocking(sock_t sock, const char *data, size_t len) { int ok = 0; + uint64_t t_start = monotonic_ms(); #ifdef _WIN32 u_long mode = 0; ioctlsocket(sock, FIONBIO, &mode); @@ -3316,6 +3344,10 @@ static int send_all_blocking(sock_t sock, const char *data, size_t len) #endif size_t sent = 0; while (sent < len) { + if (monotonic_ms() - t_start > SEND_TOTAL_BUDGET_MS) { + ok = -1; + break; + } size_t want = len - sent; if (want > (1u << 20)) want = (1u << 20); int n = send(sock, data + sent, (int)want, 0); @@ -3335,6 +3367,7 @@ static int send_all_blocking(sock_t sock, const char *data, size_t len) #else fcntl(sock, F_SETFL, flags); #endif + s_tcp_send_stall_ms += monotonic_ms() - t_start; return ok; } @@ -3348,6 +3381,7 @@ void debug_server_send_line(const char *json) * runtime. The next poll() accepts a fresh client. */ sock_close(s_client); s_client = SOCK_INVALID; + s_tcp_clients_dropped++; } } diff --git a/runtime/src/freeze_heartbeat.c b/runtime/src/freeze_heartbeat.c index 07a690b4..c2005cec 100644 --- a/runtime/src/freeze_heartbeat.c +++ b/runtime/src/freeze_heartbeat.c @@ -122,6 +122,7 @@ typedef struct { uint8_t in_exception; uint8_t mc_max_state; long long wall_clock; + uint64_t tcp_stall_ms; } HbRingEntry; static HbRingEntry s_ring[RING_CAP]; static uint32_t s_ring_head = 0; @@ -300,6 +301,8 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc, " \"tx_writes\":%d,\n" " \"dirty_ram_blocks\":%llu,\n" " \"dirty_ram_insns\":%llu,\n" + " \"tcp_send_stall_ms\":%llu,\n" + " \"tcp_clients_dropped\":%u,\n" " \"present_slow_count\":%u,\n" " \"present_vsync_disabled\":%d,\n" " \"wedge_kind\":%u,\n" @@ -320,6 +323,8 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc, mc_max, tx_writes, (unsigned long long)g_dirty_ram_blocks_run, (unsigned long long)g_dirty_ram_insns_run, + (unsigned long long)debug_server_get_tcp_stall_ms(), + debug_server_get_tcp_drops(), g_present_slow_count, g_present_vsync_disabled, s_last_wedge_kind, @@ -346,7 +351,8 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc, "\"exc_re\":%llu,\"dirty_insns\":%llu," "\"cur_fn\":\"0x%08X\",\"store_pc\":\"0x%08X\"," "\"i_stat\":\"0x%08X\",\"sio_stat\":\"0x%04X\"," - "\"sio_ctrl\":\"0x%04X\",\"in_exc\":%u,\"mc_max\":%u}%s\n", + "\"sio_ctrl\":\"0x%04X\",\"in_exc\":%u,\"mc_max\":%u," + "\"tcp_ms\":%llu}%s\n", e->wall_clock, (unsigned long long)e->frame_count, (unsigned long long)e->psx_cycle_count, @@ -355,6 +361,7 @@ static void freeze_dump_write(long long wall, uint64_t frame, uint64_t cyc, e->current_func, e->last_store_pc, e->i_stat, (unsigned)e->sio_stat, (unsigned)e->sio_ctrl, (unsigned)e->in_exception, (unsigned)e->mc_max_state, + (unsigned long long)e->tcp_stall_ms, (i + 1 < avail) ? "," : ""); } fputs(" ],\n", f); @@ -507,6 +514,7 @@ static void heartbeat_write(void) { re->in_exception = (uint8_t)in_exc; re->mc_max_state = (uint8_t)mc_max; re->wall_clock = wall; + re->tcp_stall_ms = debug_server_get_tcp_stall_ms(); s_ring_head = (s_ring_head + 1) % RING_CAP; if (s_ring_count < RING_CAP) s_ring_count++; @@ -584,6 +592,8 @@ static void heartbeat_write(void) { " \"tx_writes\":%d,\n" " \"dirty_ram_blocks\":%llu,\n" " \"dirty_ram_insns\":%llu,\n" + " \"tcp_send_stall_ms\":%llu,\n" + " \"tcp_clients_dropped\":%u,\n" " \"fatal\":%s%s%s\n" "}\n", s_backend, @@ -608,6 +618,8 @@ static void heartbeat_write(void) { tx_writes, (unsigned long long)g_dirty_ram_blocks_run, (unsigned long long)g_dirty_ram_insns_run, + (unsigned long long)debug_server_get_tcp_stall_ms(), + debug_server_get_tcp_drops(), g_psx_fatal_reason ? "\"" : "", g_psx_fatal_reason ? g_psx_fatal_reason : "null", g_psx_fatal_reason ? "\"" : ""); @@ -635,7 +647,8 @@ static void heartbeat_write(void) { "\"exc_re\":%llu,\"dirty_insns\":%llu," "\"cur_fn\":\"0x%08X\",\"store_pc\":\"0x%08X\"," "\"i_stat\":\"0x%08X\",\"sio_stat\":\"0x%04X\"," - "\"sio_ctrl\":\"0x%04X\",\"in_exc\":%u,\"mc_max\":%u}%s\n", + "\"sio_ctrl\":\"0x%04X\",\"in_exc\":%u,\"mc_max\":%u," + "\"tcp_ms\":%llu}%s\n", e->wall_clock, (unsigned long long)e->frame_count, (unsigned long long)e->psx_cycle_count, @@ -644,6 +657,7 @@ static void heartbeat_write(void) { e->current_func, e->last_store_pc, e->i_stat, (unsigned)e->sio_stat, (unsigned)e->sio_ctrl, (unsigned)e->in_exception, (unsigned)e->mc_max_state, + (unsigned long long)e->tcp_stall_ms, (i + 1 < avail) ? "," : ""); if (m <= 0 || (size_t)(n + m) >= sizeof(buf)) break; n += m;