mirror/psxrecomp
1
0
Fork 0
mirror of https://github.com/RetroPortingToolKit/psxrecomp synced 2026-10-27 10:38:46 -04:00
Code Issues Packages Projects Releases Wiki Activity

debug server: total send budget + serve-stall telemetry (root cause of 'attract degradation')

Browse Source 
The two pre-fix attract-idle 'degradations' (2026-06-10 dumps ...393 and
...707) were observer interference, not guest bugs:
- both wedge dumps show 8/8 main-thread stack samples inside WS2_32!send
  (same call site) — the main-thread-pumped server blocked sending to a
  trickle-draining client, throttling the loop to ~6 fps;
- the 'frame counter reset to 0' was a second process instance (no reset
  path exists for s_frame_count or psx_cycle_count; dump ...707 has lower
  cycles than ...393);
- the 'kernel-only dispatch loop' signature (0xB0/0x650, restore target
  0x80068024, EPC 0x80000048, dispatch_count 0) is the normal Tomba
  title-attract idle pattern — identical in a healthy 60-min post-fix soak.

Fix the loophole and make recurrence self-evident:
- send_all_blocking gains a 15 s TOTAL budget per response (the 2 s
  SO_SNDTIMEO only bounded zero-progress chunks; a slow-but-alive client
  could throttle the emulator indefinitely while heartbeating the
  starvation watchdog). Over budget -> client dropped, runtime unharmed.
- cumulative tcp_send_stall_ms + tcp_clients_dropped exported in the
  freeze heartbeat (top level + per-tick ring 'tcp_ms') and in every
  wedge/fatal dump header, so a TCP-throttled window is attributable at
  a glance. Documented in TCP_COMMANDS.md.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Matthew Stanley
2026-06-10 14:12:11 -07:00
parent 31377b6d4a
commit aa536b899c
4 changed files with 82 additions and 6 deletions
Download Patch File Download Diff File Expand all files Collapse all files
TCP_COMMANDS.md
+21
View File
@@ -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:
runtime/include/debug_server.h
+7
View File
@@ -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);
runtime/src/debug_server.c
+38 -4
View File
@@ -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++;
}
}
runtime/src/freeze_heartbeat.c
+16 -2
View File
@@ -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;