diff --git a/src/xenia/kernel/kernel_flags.cc b/src/xenia/kernel/kernel_flags.cc index bb9e9200e..bc415b6b4 100644 --- a/src/xenia/kernel/kernel_flags.cc +++ b/src/xenia/kernel/kernel_flags.cc @@ -14,3 +14,11 @@ DEFINE_bool(headless, false, "UI"); DEFINE_bool(log_high_frequency_kernel_calls, false, "Log kernel calls with the kHighFrequency tag.", "Logging"); +DEFINE_bool(log_stuck_waits, false, + "Reverse-engineering aid: when a guest thread times out over and " + "over on the SAME object, log which object it is. Silent on a " + "healthy run - a wait that is being satisfied never builds a " + "streak - so it can be left on. Exists because " + "KeWaitForSingleObject is kHighFrequency and the flag that would " + "log it slows the emulator past booting.", + "Logging"); diff --git a/src/xenia/kernel/kernel_flags.h b/src/xenia/kernel/kernel_flags.h index 04a6d6ebf..54253512c 100644 --- a/src/xenia/kernel/kernel_flags.h +++ b/src/xenia/kernel/kernel_flags.h @@ -13,5 +13,6 @@ DECLARE_bool(headless); DECLARE_bool(log_high_frequency_kernel_calls); +DECLARE_bool(log_stuck_waits); #endif // XENIA_KERNEL_KERNEL_FLAGS_H_ diff --git a/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc b/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc index 62e263b4e..86e5d6513 100644 --- a/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc +++ b/src/xenia/kernel/xboxkrnl/xboxkrnl_threading.cc @@ -12,9 +12,11 @@ #include "xenia/base/clock.h" #include "xenia/base/platform.h" #include "xenia/cpu/processor.h" +#include "xenia/kernel/kernel_flags.h" #include "xenia/kernel/util/shim_utils.h" #include "xenia/kernel/xboxkrnl/xboxkrnl_private.h" #include "xenia/kernel/xsemaphore.h" +#include "xenia/kernel/xthread.h" #include "xenia/kernel/xtimer.h" #include "xenia/xbox.h" @@ -1001,6 +1003,46 @@ uint32_t xeKeWaitForSingleObject(void* object_ptr, uint32_t wait_reason, X_STATUS result = object->Wait(wait_reason, processor_mode, alertable, timeout_ptr); + + // [RE] Name the object a stuck thread is waiting on, without paying for + // logging every wait. + // + // Project Sylpheed freezes mid-mission about half the time. Under gdb every + // one of the emulator's 79 threads is in a WAIT, yet the process still burns + // 1253 ticks per 10 s -- 280 of them in guest threads that the backtrace shows + // blocked in this very function. So they are cycling: a timed wait that + // expires and is immediately re-entered on an object nobody signals. + // + // Logging that object the ordinary way is not possible: KeWaitForSingleObject + // is kHighFrequency, so it is silent unless --log_high_frequency_kernel_calls, + // and THAT flag slows the emulator so far that a boot did not reach the intro + // movie in seventeen minutes (175 MB of log). See + // docs/re/mission-freeze-resume-spin.md in the Reborn repo. + // + // A per-thread counter of CONSECUTIVE timeouts on the SAME object is + // 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) { + static thread_local void* last_object = nullptr; + static thread_local uint32_t timeout_streak = 0; + if (result == X_STATUS_TIMEOUT && object_ptr == last_object) { + ++timeout_streak; + if (timeout_streak == 100 || (timeout_streak % 500) == 0) { + uint32_t guest_va = + kernel_state()->memory()->HostToGuestVirtual(object_ptr); + XELOGW( + "[wait-probe] thread {:08X} has timed out {} times in a row on " + "object {:08X} (type {}), timeout={}", + XThread::GetCurrentThreadHandle(), timeout_streak, guest_va, + static_cast(object->type()), + timeout_ptr ? *timeout_ptr : 0ull); + } + } else { + last_object = object_ptr; + timeout_streak = (result == X_STATUS_TIMEOUT) ? 1 : 0; + } + } + if (alertable) { if (result == X_STATUS_USER_APC) { xeProcessUserApcs(nullptr);