From 5977400461a658e0596cbbc59ae226443ecf5fbc Mon Sep 17 00:00:00 2001 From: Sylpheed RE agent Date: Mon, 24 Aug 2026 07:45:41 +0000 Subject: [PATCH] [RE] log_stuck_waits v2: count CALLS per second, not just timeout streaks The v1 streak counter caught nothing during a real freeze: the healthy-run baseline and not one new (thread, object) pair, while the process burned 1255 ticks per 10 s with two guest threads sitting in KeWaitForSingleObject. That refuted "loops on timeouts against one object" and left two blind spots, and this covers both. A per-thread one-second window counts EVERY call, tracks how many DISTINCT objects it saw, and logs the last object and the last RESULT when the rate passes 500/s. So a thread rotating over several handles (which resets a same-object streak) and a thread whose waits SUCCEED rather than time out (which a timeout counter cannot see) both show up now. Self-selecting like v1: the healthy poller runs at ~33 calls/s on a 30 ms timeout, so the 500/s floor stays silent on a good run. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE --- .../kernel/xboxkrnl/xboxkrnl_threading.cc | 49 +++++++++++++++++++ 1 file changed, 49 insertions(+) diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc index 86e5d6513..495582325 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc @@ -1023,6 +1023,55 @@ uint32_t xeKeWaitForSingleObject(void* object_ptr, uint32_t wait_reason, // self-selecting instead: a healthy wait never reaches the threshold and logs // nothing at all, while a stuck one names itself within seconds. if (cvars::log_stuck_waits) { + // v2 (2026-08-24): the streak counter below caught NOTHING during a real + // freeze — the healthy-run baseline and not one new (thread, object) pair, + // while the process burned 1255 ticks per 10 s with two guest threads + // sitting in this function. That refuted the "loops on timeouts against one + // object" reading and left two blind spots, both of which this second + // counter covers: + // + // * the thread rotates over DIFFERENT objects, so a same-object streak + // never builds — hence the distinct-object count; + // * the waits SUCCEED rather than time out, so a timeout counter has + // nothing to count — hence counting every call and logging the result. + // + // A rate counter is self-selecting the same way: the healthy poller runs at + // ~33 calls/s (a 30 ms timeout), so a 500/s floor is silent on a good run. + { + static thread_local uint64_t window_start_ms = 0; + static thread_local uint32_t window_calls = 0; + static thread_local void* window_objects[8] = {}; + static thread_local uint32_t window_object_count = 0; + const uint64_t now_ms = Clock::QueryHostUptimeMillis(); + if (now_ms - window_start_ms >= 1000) { + if (window_calls > 500) { + XELOGW( + "[wait-rate] thread {:08X} called KeWaitForSingleObject {} times " + "in {} ms over {} distinct object(s); last object {:08X}, last " + "result {:08X}", + XThread::GetCurrentThreadHandle(), window_calls, + now_ms - window_start_ms, window_object_count, + kernel_state()->memory()->HostToGuestVirtual(object_ptr), result); + } + window_start_ms = now_ms; + window_calls = 0; + window_object_count = 0; + } + ++window_calls; + bool seen = false; + for (uint32_t i = 0; i < window_object_count; ++i) { + if (window_objects[i] == object_ptr) { + seen = true; + break; + } + } + if (!seen && window_object_count < 8) { + window_objects[window_object_count++] = object_ptr; + } else if (!seen) { + ++window_object_count; // more than 8: count them, stop recording + } + } + static thread_local void* last_object = nullptr; static thread_local uint32_t timeout_streak = 0; if (result == X_STATUS_TIMEOUT && object_ptr == last_object) {