diff --git a/native/desktop/system.cpp b/native/desktop/system.cpp index dc90bb3..3a2c00c 100644 --- a/native/desktop/system.cpp +++ b/native/desktop/system.cpp @@ -370,11 +370,15 @@ bool NativeWindows::system_dispatch(std::string_view name) throw uint32_t(8); std::erase_if(timers, [&](const Timer &timer) { return timer.window == args[0] && timer.id == id; }); timers.push_back({args[0], id, args[3], interval, std::chrono::steady_clock::now() + std::chrono::milliseconds(interval), false, environment.thread_id()}); + if (std::getenv("RAVEN_TRACE_TIMERS")) + std::cerr << "timer set " << std::hex << args[0] << ' ' << id << std::dec << " every " << interval << " ms on thread " << environment.thread_id() << '\n'; result = id; } else if (name == "KillTimer") { const auto args = process.api_arguments(2); const auto before = timers.size(); std::erase_if(timers, [&](const Timer &timer) { return timer.window == args[0] && timer.id == args[1]; }); + if (std::getenv("RAVEN_TRACE_TIMERS")) + std::cerr << "timer kill " << std::hex << args[0] << ' ' << args[1] << std::dec << '\n'; if (before == timers.size()) throw uint32_t(1814); result = 1; diff --git a/native/nt/thread_api.cpp b/native/nt/thread_api.cpp index 8dd12a4..373542b 100644 --- a/native/nt/thread_api.cpp +++ b/native/nt/thread_api.cpp @@ -314,7 +314,7 @@ void register_thread_api(ApiRegistry ®istry, KernelContext &context) return std::nullopt; return std::chrono::steady_clock::now() + std::chrono::nanoseconds(from_now * 100); }; - const auto multiple = [wait, handle_at](ApiCall &call, bool alertable) { + const auto multiple = [wait, handle_at, &objects, &threads](ApiCall &call, bool alertable) { const uint32_t count = call.u32(0); if (count > 64 || !call[1]) { call.fail(87, wait_failed); @@ -323,6 +323,17 @@ void register_thread_api(ApiRegistry ®istry, KernelContext &context) std::vector handles(count); for (uint32_t index = 0; index < count; ++index) handles[index] = handle_at(call, call[1], index); + // RAVEN_TRACE_WAITS also names what a wait for several objects is given: each handle, its type and whether it is signaled. + static const bool traced = std::getenv("RAVEN_TRACE_WAITS") != nullptr; + if (traced && call.u32(3)) { + std::fprintf(stderr, "raven: thread %u waits for %s of", threads.current_id(), call.u32(2) ? "all" : "any"); + for (const auto handle : handles) { + const auto object = objects.object(handle); + std::fprintf(stderr, " %llx %s %d", (unsigned long long)handle, object ? to_utf8(std::u16string(object->type_name())).c_str() : "?", + objects.signaled(handle, threads.current_id())); + } + std::fprintf(stderr, "\n"); + } call.ret(wait(call, handles, call.u32(2), call.u32(3), alertable)); }; registry.add("WaitForMultipleObjects", 4, [multiple](ApiCall &call) { multiple(call, false); }); diff --git a/native/nt/threads.cpp b/native/nt/threads.cpp index d989640..5db3356 100644 --- a/native/nt/threads.cpp +++ b/native/nt/threads.cpp @@ -17,6 +17,7 @@ #include #include #include +#include namespace raven { @@ -512,7 +513,10 @@ bool NativeThreads::block(std::function ready, std::optional ready, std::optionalid, states[size_t(thread->state)]); + if (thread->state == GuestThread::State::waiting && thread->waiting_in) + std::fprintf(stderr, " in %s for %lld ms", thread->waiting_in, + (long long)std::chrono::duration_cast(checked - thread->waiting_since).count()); + if (thread->suspend_count) + std::fprintf(stderr, " suspended %d", thread->suspend_count); + std::fprintf(stderr, " rip %llx rsp %llx\n", (unsigned long long)thread->snapshot.context.registers.rip, (unsigned long long)thread->snapshot.context.registers.rsp); + } +} + bool NativeThreads::yield() { serve(); diff --git a/native/nt/threads.h b/native/nt/threads.h index 9cd2035..346024d 100644 --- a/native/nt/threads.h +++ b/native/nt/threads.h @@ -32,6 +32,9 @@ struct GuestThread { // Wait condition: pure check, evaluated by the scheduler; the thread resumes when it holds or the wake time passes. std::function ready; std::optional wake; + // The API the thread waits in and since when, for the list RAVEN_DUMP_THREADS_ON asks for. + const char *waiting_in = nullptr; + std::chrono::steady_clock::time_point waiting_since; uint32_t exit_code = 0x103; int suspend_count = 0; uint64_t start = 0, parameter = 0; @@ -114,7 +117,7 @@ public: void add_pump(std::function work) { pumps.push_back(std::move(work)); } // Runs at every scheduling decision, also while threads run: requests from other processes are answered without waiting for idleness. void add_service(std::function work) { services.push_back(std::move(work)); } - void serve() { for (const auto &service : services) service(); } + void serve(); // Ends the scheduler's idle wait early: called from a host thread that finished work a waiting guest thread looks for. void nudge(); // For a wait outside the scheduler, such as a thread waiting for window messages while the others wait too: the latest time it may