Fix iOS startup event waits

Author: aperezro

UnleashedRecomp/kernel/imports.cpp

@@ -17,6 +17,68 @@
 #include <ntstatus.h>
 #endif
 
+static std::atomic<uint32_t> g_keSetEventGeneration;
+
+static void NotifyWaitForMultipleObjects()
+{
+    ++g_keSetEventGeneration;
+    g_keSetEventGeneration.notify_all();
+}
+
+#ifdef UNLEASHED_RECOMP_IOS
+static uint32_t GetGuestLinkRegisterForLog()
+{
+#ifndef PPC_CONFIG_SKIP_LR
+    if (auto* ctx = GetPPCContext())
+        return uint32_t(ctx->lr);
+#endif
+
+    return 0;
+}
+
+static bool ShouldLogKernelWait(uint32_t count)
+{
+    return count <= 128 || (count % 512) == 0;
+}
+
+static const char* GetDispatcherTypeName(uint32_t type)
+{
+    switch (type)
+    {
+    case 0:
+        return "NotificationEvent";
+    case 1:
+        return "SynchronizationEvent";
+    case 5:
+        return "Semaphore";
+    default:
+        return "Unknown";
+    }
+}
+
+static void LogKernelWait(const char* name, uint32_t object, uint32_t timeout, int64_t rawTimeout, uint32_t type, uint32_t signalState, uint32_t extra = 0)
+{
+    static std::atomic<uint32_t> s_waitLogCount;
+    const uint32_t count = ++s_waitLogCount;
+    if (!ShouldLogKernelWait(count))
+        return;
+
+    LOGFN("iOS wait #{} {} object=0x{:08X} type={}({}) signal={} timeout={} rawTimeout={} extra={} lr=0x{:08X} thread=0x{:08X}",
+        count,
+        name,
+        object,
+        GetDispatcherTypeName(type),
+        type,
+        signalState,
+        timeout,
+        rawTimeout,
+        extra,
+        GetGuestLinkRegisterForLog(),
+        GuestThread::GetCurrentThreadId());
+}
+
+#endif
+
 struct Event final : KernelObject, HostObject<XKEVENT>
 {
     bool manualReset;
@@ -83,6 +145,8 @@ struct Event final : KernelObject, HostObject<XKEVENT>
         else
             signaled.notify_one();
 
+        NotifyWaitForMultipleObjects();
+
         return TRUE;
     }
 
@@ -93,8 +157,6 @@ struct Event final : KernelObject, HostObject<XKEVENT>
     }
 };
 
-static std::atomic<uint32_t> g_keSetEventGeneration;
-
 struct Semaphore final : KernelObject, HostObject<XKSEMAPHORE>
 {
     std::atomic<uint32_t> count;
@@ -158,9 +220,44 @@ struct Semaphore final : KernelObject, HostObject<XKSEMAPHORE>
 
         count += releaseCount;
         count.notify_all();
+        NotifyWaitForMultipleObjects();
     }
 };
 
+#ifdef UNLEASHED_RECOMP_IOS
+static const char* GetKernelObjectName(KernelObject* object)
+{
+    if (dynamic_cast<Event*>(object) != nullptr)
+        return "Event";
+
+    if (dynamic_cast<Semaphore*>(object) != nullptr)
+        return "Semaphore";
+
+    if (dynamic_cast<GuestThreadHandle*>(object) != nullptr)
+        return "GuestThread";
+
+    return "KernelObject";
+}
+
+static void LogKernelHandleWait(const char* name, uint32_t handle, KernelObject* object, uint32_t timeout, int64_t rawTimeout)
+{
+    static std::atomic<uint32_t> s_handleWaitLogCount;
+    const uint32_t count = ++s_handleWaitLogCount;
+    if (!ShouldLogKernelWait(count))
+        return;
+
+    LOGFN("iOS handle wait #{} {} handle=0x{:08X} objectType={} timeout={} rawTimeout={} lr=0x{:08X} thread=0x{:08X}",
+        count,
+        name,
+        handle,
+        GetKernelObjectName(object),
+        timeout,
+        rawTimeout,
+        GetGuestLinkRegisterForLog(),
+        GuestThread::GetCurrentThreadId());
+}
+#endif
+
 inline void CloseKernelObject(XDISPATCHER_HEADER& header)
 {
     if (header.WaitListHead.Flink != OBJECT_SIGNATURE)
@@ -408,7 +505,11 @@ uint32_t NtWaitForSingleObjectEx(uint32_t Handle, uint32_t WaitMode, uint32_t Al
 
     if (IsKernelObject(Handle))
     {
-        return GetKernelObject(Handle)->Wait(timeout);
+        auto* object = GetKernelObject(Handle);
+#ifdef UNLEASHED_RECOMP_IOS
+        LogKernelHandleWait("NtWaitForSingleObjectEx", Handle, object, timeout, Timeout ? int64_t(*Timeout) : 0);
+#endif
+        return object->Wait(timeout);
     }
     else
     {
@@ -569,6 +670,21 @@ uint32_t KeDelayExecutionThread(uint32_t WaitMode, bool Alertable, be<int64_t>*
 
     uint32_t timeout = GuestTimeoutToMilliseconds(Timeout);
 
+#ifdef UNLEASHED_RECOMP_IOS
+    static std::atomic<uint32_t> s_delayLogCount;
+    const uint32_t delayLogCount = ++s_delayLogCount;
+    if (timeout == INFINITE || timeout >= 500 || delayLogCount <= 16)
+    {
+        LOGFN("iOS delay #{} timeout={} rawTimeout={} waitMode={} lr=0x{:08X} thread=0x{:08X}",
+            delayLogCount,
+            timeout,
+            Timeout ? int64_t(*Timeout) : 0,
+            WaitMode,
+            GetGuestLinkRegisterForLog(),
+            GuestThread::GetCurrentThreadId());
+    }
+#endif
+
 #ifdef _WIN32
     Sleep(timeout);
 #else
@@ -999,9 +1115,6 @@ bool KeSetEvent(XKEVENT* pEvent, uint32_t Increment, bool Wait)
 {
     bool result = QueryKernelObject<Event>(*pEvent)->Set();
 
-    ++g_keSetEventGeneration;
-    g_keSetEventGeneration.notify_all();
-
     return result;
 }
 
@@ -1015,6 +1128,15 @@ uint32_t KeWaitForSingleObject(XDISPATCHER_HEADER* Object, uint32_t WaitReason,
     const uint32_t timeout = GuestTimeoutToMilliseconds(Timeout);
     assert(timeout == INFINITE);
 
+#ifdef UNLEASHED_RECOMP_IOS
+    LogKernelWait("KeWaitForSingleObject",
+        g_memory.MapVirtual(Object),
+        timeout,
+        Timeout ? int64_t(*Timeout) : 0,
+        Object->Type,
+        Object->SignalState);
+#endif
+
     switch (Object->Type)
     {
         case 0:
@@ -1325,6 +1447,12 @@ uint32_t NtResumeThread(GuestThreadHandle* hThread, uint32_t* suspendCount)
 
 uint32_t NtSetEvent(Event* handle, uint32_t* previousState)
 {
+#ifdef UNLEASHED_RECOMP_IOS
+    LOGFN("iOS NtSetEvent handle=0x{:08X} lr=0x{:08X} thread=0x{:08X}",
+        g_memory.MapVirtual(handle),
+        GetGuestLinkRegisterForLog(),
+        GuestThread::GetCurrentThreadId());
+#endif
     handle->Set();
     return 0;
 }
@@ -1506,6 +1634,17 @@ uint32_t KeWaitForMultipleObjects(uint32_t Count, xpointer<XDISPATCHER_HEADER>*
     const uint64_t timeout = GuestTimeoutToMilliseconds(Timeout);
     assert(timeout == INFINITE);
 
+#ifdef UNLEASHED_RECOMP_IOS
+    auto* firstObject = Count > 0 ? Objects[0].get() : nullptr;
+    LogKernelWait("KeWaitForMultipleObjects",
+        firstObject != nullptr ? g_memory.MapVirtual(firstObject) : 0,
+        uint32_t(timeout),
+        Timeout ? int64_t(*Timeout) : 0,
+        firstObject != nullptr ? firstObject->Type : 0xFFFFFFFF,
+        firstObject != nullptr ? uint32_t(firstObject->SignalState) : 0,
+        (Count << 8) | WaitType);
+#endif
+
     if (WaitType == 0) // Wait all
     {
         for (size_t i = 0; i < Count; i++)

UnleashedRecomp/main.cpp

@@ -214,7 +214,7 @@ int main(int argc, char *argv[])
     os::logger::Init();
 
 #ifdef UNLEASHED_RECOMP_IOS
-    LOGN("iOS startup build: install-validation-v3");
+    LOGN("iOS startup build: sync-wait-fix-v4");
 #endif
 
     PreloadContext preloadContext;

UnleashedRecomp/misc_impl.cpp

@@ -1,6 +1,7 @@
 #include "stdafx.h"
 #include <kernel/function.h>
 #include <kernel/xdm.h>
+#include <os/logger.h>
 
 uint32_t QueryPerformanceCounterImpl(LARGE_INTEGER* lpPerformanceCount)
 {
@@ -46,7 +47,13 @@ GUEST_FUNCTION_HOOK(sub_831CCAA0, memset);
 #ifdef _WIN32
 GUEST_FUNCTION_HOOK(sub_82BD4CA8, OutputDebugStringA);
 #else
-GUEST_FUNCTION_STUB(sub_82BD4CA8);
+static void OutputDebugStringAImpl(const char* message)
+{
+    if (message != nullptr && message[0] != '\0')
+        LOGFN("Guest debug: {}", message);
+}
+
+GUEST_FUNCTION_HOOK(sub_82BD4CA8, OutputDebugStringAImpl);
 #endif
 
 GUEST_FUNCTION_HOOK(sub_82BD4AC8, QueryPerformanceCounterImpl);

UnleashedRecomp/res/version.txt

@@ -1,4 +1,4 @@
 VERSION_MILESTONE=""
 VERSION_MAJOR=1
 VERSION_MINOR=0
-VERSION_REVISION=5
+VERSION_REVISION=6