[RE] log_stuck_waits: name the object a stuck thread keeps timing out on
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 the backtrace shows blocked inside KeWaitForSingleObject. So they are cycling: a timed wait that expires and is re-entered on an object nobody signals. Naming that object is the next step. Logging it the ordinary way is not possible. KeWaitForSingleObject is kHighFrequency, so it is silent unless --log_high_frequency_kernel_calls=true, and measured: that flag writes 175 MB and leaves the emulator seventeen minutes into a boot with the screen still black. So count CONSECUTIVE timeouts on the SAME object, per thread, in xeKeWaitForSingleObject, and log at 100 and then every 500. It is self-selecting: a wait that is being satisfied never builds a streak. Measured on a healthy 25-minute Stage 02 run: 27 lines, all one thread (F800004C) polling one Event (guest VA BE56BB5C) with a ~30 ms timeout - a legitimate poller, and the baseline a frozen run has to be compared against. Not "silent", as first drafted, but quiet enough to leave on. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE
This commit is contained in:
@@ -14,3 +14,11 @@ DEFINE_bool(headless, false,
|
|||||||
"UI");
|
"UI");
|
||||||
DEFINE_bool(log_high_frequency_kernel_calls, false,
|
DEFINE_bool(log_high_frequency_kernel_calls, false,
|
||||||
"Log kernel calls with the kHighFrequency tag.", "Logging");
|
"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");
|
||||||
|
|||||||
@@ -13,5 +13,6 @@
|
|||||||
|
|
||||||
DECLARE_bool(headless);
|
DECLARE_bool(headless);
|
||||||
DECLARE_bool(log_high_frequency_kernel_calls);
|
DECLARE_bool(log_high_frequency_kernel_calls);
|
||||||
|
DECLARE_bool(log_stuck_waits);
|
||||||
|
|
||||||
#endif // XENIA_KERNEL_KERNEL_FLAGS_H_
|
#endif // XENIA_KERNEL_KERNEL_FLAGS_H_
|
||||||
|
|||||||
@@ -12,9 +12,11 @@
|
|||||||
#include "xenia/base/clock.h"
|
#include "xenia/base/clock.h"
|
||||||
#include "xenia/base/platform.h"
|
#include "xenia/base/platform.h"
|
||||||
#include "xenia/cpu/processor.h"
|
#include "xenia/cpu/processor.h"
|
||||||
|
#include "xenia/kernel/kernel_flags.h"
|
||||||
#include "xenia/kernel/util/shim_utils.h"
|
#include "xenia/kernel/util/shim_utils.h"
|
||||||
#include "xenia/kernel/xboxkrnl/xboxkrnl_private.h"
|
#include "xenia/kernel/xboxkrnl/xboxkrnl_private.h"
|
||||||
#include "xenia/kernel/xsemaphore.h"
|
#include "xenia/kernel/xsemaphore.h"
|
||||||
|
#include "xenia/kernel/xthread.h"
|
||||||
#include "xenia/kernel/xtimer.h"
|
#include "xenia/kernel/xtimer.h"
|
||||||
#include "xenia/xbox.h"
|
#include "xenia/xbox.h"
|
||||||
|
|
||||||
@@ -1001,6 +1003,46 @@ uint32_t xeKeWaitForSingleObject(void* object_ptr, uint32_t wait_reason,
|
|||||||
|
|
||||||
X_STATUS result =
|
X_STATUS result =
|
||||||
object->Wait(wait_reason, processor_mode, alertable, timeout_ptr);
|
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<uint32_t>(object->type()),
|
||||||
|
timeout_ptr ? *timeout_ptr : 0ull);
|
||||||
|
}
|
||||||
|
} else {
|
||||||
|
last_object = object_ptr;
|
||||||
|
timeout_streak = (result == X_STATUS_TIMEOUT) ? 1 : 0;
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
if (alertable) {
|
if (alertable) {
|
||||||
if (result == X_STATUS_USER_APC) {
|
if (result == X_STATUS_USER_APC) {
|
||||||
xeProcessUserApcs(nullptr);
|
xeProcessUserApcs(nullptr);
|
||||||
|
|||||||
Reference in New Issue
Block a user