fabi/Xenia-Canary
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[RE] log_stuck_waits v2: count CALLS per second, not just timeout streaks

Browse Source 
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) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE
This commit is contained in:
Sylpheed RE agent
2026-08-24 07:45:41 +00:00
parent 820696c114
commit 5977400461
1 changed files with 49 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

49
src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc
View File

@@ -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) {