From 7b15d85f61d92db1f1f3c7b98578b0a6cd108e76 Mon Sep 17 00:00:00 2001 From: megboyzz Date: Sat, 19 Sep 2026 16:41:58 +0300 Subject: [PATCH] Drop uc_emu_start's instruction-count limit: 3.99x -> 2.73x slower than real time CallGuestFunction passed count=5000000 to uc_emu_start. Any non-zero count makes Unicorn install a GLOBAL UC_HOOK_CODE internally (uc.c:1202): uc_hook_add(uc, &uc->count_hook, UC_HOOK_CODE, hook_count_cb, NULL, 1, 0) begin=1 > end=0, which HOOK_BOUND_CHECK treats as matching EVERY address. So helper_uc_tracecode, a gen_set_pc_im PC sync, and check_exit_request were emitted and executed for EVERY GUEST INSTRUCTION - not per shim call. That is what the in-race profile had been showing: helper_uc_tracecode 34.54% helper_check_exit_request_arm 5.33% against 0.04% in MiscStubDispatch at ~65,000 stub dispatches/sec, which worked out to an impossible ~5.4us per dispatch. The arithmetic never fit because the divisor was wrong: tracecode was per instruction, not per dispatch. It also explains task #48's null result. Removing 17 probe hooks shortened the hook LIST but left this global entry in it, so the per-instruction call and the per-instruction PC sync - which also prevents TCG from chaining blocks - both remained. Measured on the Pixel 6a with the race's own clock, same method throughout: helper_uc_tracecode 34.54% -> absent from the top symbols stub dispatches 65k/s -> 76-93k/s (more guest work done) game time vs wall clock 3.99x -> 2.73x 27s of wall time advanced the race timer 30.13 -> 40.02 (9.89s); the sub-intervals gave 2.75x and 2.71x. Today's full progression is 7.2x -> 3.99x -> 2.73x. Trade-off, taken deliberately: a runaway guest loop inside one call now hangs instead of returning after 5M instructions to be caught by kMaxCallIterations. That net was already documented in this function as "not a security boundary", and since the 2026-09-05 stub fix a normal call completes in a single uc_emu_start anyway. A future watchdog should be one long-lived thread calling uc_emu_stop, NOT uc_emu_start's `timeout` argument, which spawns a thread per call (uc.c:1036). Also turns off the two temporary counters (kCountStubDispatches, kCountTextWrites) added to find this; the .text write counter answered its question with a flat zero, killing the self-modifying-code theory behind tb_invalidate_phys_page_fast_arm. Co-Authored-By: Claude --- mpcore/src/main/cpp/emu/guest_engine.cpp | 147 ++++++++++++++++++++++- 1 file changed, 146 insertions(+), 1 deletion(-) diff --git a/mpcore/src/main/cpp/emu/guest_engine.cpp b/mpcore/src/main/cpp/emu/guest_engine.cpp index 2afe1e9..26a04bc 100644 --- a/mpcore/src/main/cpp/emu/guest_engine.cpp +++ b/mpcore/src/main/cpp/emu/guest_engine.cpp @@ -122,6 +122,23 @@ constexpr uint32_t kGuardPageSize = kPageSize; // null malloc result and the engine faulted (READ_UNMAPPED) mid-load. The // backing store is one lazy anonymous mmap (see MapSegments), so reserving // more address space costs no resident memory until the guest touches it. +// Temporary measurement flags (2026-09-19, task #48 follow-up). Both OFF by +// default per this project's standing rule that any new always-on hook or +// counter must be opt-in - see kSynthesizeSwap and the UC_HOOK_BLOCK +// diagnostics for the two separate occasions an always-on diagnostic caused +// a user-visible regression. Flip on only while actively capturing. +// kCountStubDispatches - how often MiscStubDispatch really runs, to test +// whether the stub boundary explains helper_uc_tracecode's 41.66%. +// kCountTextWrites - guest writes landing in .text, which is what forces +// TCG to re-translate (tb_invalidate_phys_page_fast_arm, 3.15%). If this +// reports zero, the invalidation comes from somewhere else and that lead +// is dead. +constexpr bool kCountStubDispatches = false; +constexpr bool kCountTextWrites = false; +// libapp.so .text: offset 0x68000, size 0x916150 (readelf -S). +constexpr uint64_t kTextStart = 0x68000u; +constexpr uint64_t kTextEnd = 0x68000u + 0x916150u; + constexpr uint32_t kHeapSize = 768u * 1024 * 1024; constexpr uint32_t kStackSize = 8u * 1024 * 1024; // per-thread guest stack size, unchanged from before constexpr uint32_t kTrampolineArenaSize = 64 * 1024; @@ -179,6 +196,38 @@ struct ImportStubEntry { // ("don't patch this up") - this only observes, the fault still aborts // uc_emu_start exactly as before. +// See kCountTextWrites. Aggregates guest stores into .text by page and +// reports the busiest pages every few seconds; silent if nothing writes +// there, which is itself the answer. +void TextWriteProbeHookCb(uc_engine* /*uc*/, uc_mem_type /*type*/, uint64_t address, int /*size*/, + int64_t /*value*/, void* /*user_data*/) { + static std::mutex mu; + static std::map hitsByPage; + static uint64_t total = 0, lastReportNs = 0; + std::lock_guard lock(mu); + hitsByPage[address & ~0xFFFull]++; + total++; + uint64_t now = (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); + if (lastReportNs == 0) { lastReportNs = now; return; } + if (now - lastReportNs < 3000000000ull) return; + double dt = (now - lastReportNs) / 1e9; + lastReportNs = now; + std::vector> top(hitsByPage.begin(), hitsByPage.end()); + std::sort(top.begin(), top.end(), [](auto& a, auto& b) { return a.second > b.second; }); + std::string s; + for (size_t i = 0; i < top.size() && i < 5; i++) { + char buf[64]; + snprintf(buf, sizeof(buf), " 0x%llx:%llu", (unsigned long long)top[i].first, + (unsigned long long)top[i].second); + s += buf; + } + Log("GuestEngine: TEXTWRITE %.0f writes/sec into .text, %zu distinct pages, total %llu | busiest:%s", + (double)total / dt, hitsByPage.size(), (unsigned long long)total, s.c_str()); + total = 0; + hitsByPage.clear(); +} + bool mem_fault_hook_cb(uc_engine* uc, uc_mem_type type, uint64_t address, int size, int64_t /*value*/, void* /*user_data*/) { uint32_t pc = 0, lr = 0, sp = 0, r0 = 0, r1 = 0; uc_reg_read(uc, UC_ARM_REG_PC, &pc); @@ -649,6 +698,33 @@ void ZipIndexProbeHookCb(uc_engine* uc, uint64_t, uint32_t, void*) { // occasionally (once per section, not once per shim call in a hot byte // loop), so the stop/restart round-trip cost is irrelevant. void FnvHashAccelHookCb(uc_engine* uc, uint64_t, uint32_t, void*) { + // Task #48 follow-up (2026-09-19, temporary). In-race arithmetic says + // helper_uc_tracecode costs ~6.8us per MiscStubDispatch call, which is + // two orders of magnitude too much for a 9-entry list walk - so tracecode + // must be firing from somewhere the STUBRATE counter does not see. This + // hook is the prime suspect precisely because it still calls + // uc_emu_stop() below: that is the expensive stop/restart round-trip + // task #15 removed from stub dispatch by giving stubs a real BX LR, and + // this accelerator never got the same treatment. Counting before + // concluding. + if (kCountStubDispatches) { + static std::atomic calls{0}; + static std::atomic lastReportNs{0}; + uint64_t n = calls.fetch_add(1, std::memory_order_relaxed) + 1; + uint64_t now = (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); + uint64_t last = lastReportNs.load(std::memory_order_relaxed); + if (now - last > 2000000000ull && + lastReportNs.compare_exchange_strong(last, now, std::memory_order_relaxed)) { + static uint64_t prevCalls = 0; + double dt = last ? (now - last) / 1e9 : 0.0; + if (dt > 0) { + Log("GuestEngine: FNVRATE %.0f hash-hook calls/sec (total %llu) - each one does a " + "uc_emu_stop round-trip", (double)(n - prevCalls) / dt, (unsigned long long)n); + } + prevCalls = n; + } + } uint32_t r0 = 0, r1 = 0, r2 = 0, lr = 0; uc_reg_read(uc, UC_ARM_REG_R0, &r0); uc_reg_read(uc, UC_ARM_REG_R1, &r1); @@ -2903,6 +2979,18 @@ uc_engine* GuestEngine::CreateConfiguredEngine() { uc_hook_add(newUc, &memFaultHook, UC_HOOK_MEM_INVALID, (void*)mem_fault_hook_cb, nullptr, 1, 0); } + // See kCountTextWrites. A guest store into .text is what makes TCG throw + // away and re-translate a block, so this measures the actual source of + // tb_invalidate_phys_page_fast_arm rather than inferring it. Reporting by + // PAGE, because invalidation granularity is a page: a handful of hot + // pages would mean data sharing a page with code (fixable by layout), a + // wide spread would mean genuine self-modifying code (not fixable). + if (kCountTextWrites) { + uc_hook textWriteHook; + uc_hook_add(newUc, &textWriteHook, UC_HOOK_MEM_WRITE, (void*)TextWriteProbeHookCb, nullptr, + kTextStart, kTextEnd); + } + // Throwaway diagnostic (see profiler.h) - no-op unless EnableProfiling() // was called. Covers the loaded image's own real code range only // (arenas beyond image_end_ are stub addresses that redirect out via @@ -3178,6 +3266,32 @@ GuestAddr GuestEngine::CarveThreadStack() { void GuestEngine::MiscStubDispatch(uc_engine* uc, uint64_t address, uint32_t size, void* /*userData*/) { auto& eng = GuestEngine::Instance(); + // Task #48 follow-up measurement (2026-09-19, temporary). The in-race + // profile puts 41.66% of CPU in helper_uc_tracecode but only 0.04% in + // THIS function, which the simple "stub calls are hot" story cannot + // explain - tracecode would have to be entering far more often than it + // dispatches. Rather than assume, count. If this reports millions of + // calls/sec the stub boundary really is the cost; if it reports + // thousands, tracecode is firing on something else entirely and the + // profile's 41.66% needs a different explanation. + if (kCountStubDispatches) { + static std::atomic calls{0}; + static std::atomic lastReportNs{0}; + uint64_t n = calls.fetch_add(1, std::memory_order_relaxed) + 1; + uint64_t now = (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); + uint64_t last = lastReportNs.load(std::memory_order_relaxed); + if (now - last > 2000000000ull && + lastReportNs.compare_exchange_strong(last, now, std::memory_order_relaxed)) { + static uint64_t prevCalls = 0; + double dt = last ? (now - last) / 1e9 : 0.0; + if (dt > 0) { + Log("GuestEngine: STUBRATE %.0f dispatches/sec (total %llu)", + (double)(n - prevCalls) / dt, (unsigned long long)n); + } + prevCalls = n; + } + } if (address < eng.misc_stub_arena_start_) return; // shouldn't happen - registered range starts here size_t idx = (address - eng.misc_stub_arena_start_) / 4; GuestEngine::MiscStubEntry entry; @@ -3563,7 +3677,38 @@ uint32_t GuestEngine::CallGuestFunction(GuestAddr target, const uint32_t* args, uc_err err = UC_ERR_OK; int iterations = 0; for (; iterations < kMaxCallIterations; iterations++) { - err = uc_emu_start(eng, pc, kCallReturnSentinel, 0, 5000000); + // FIX (2026-09-19, task #50). The instruction-count argument was + // 5,000,000. ANY non-zero count makes Unicorn install a GLOBAL + // UC_HOOK_CODE internally (uc.c:1202) - registered as + // `uc_hook_add(..., hook_count_cb, NULL, 1, 0)`, i.e. begin=1 > end=0, + // which HOOK_BOUND_CHECK treats as matching EVERY address. The + // consequence is that helper_uc_tracecode plus a PC sync + // (gen_set_pc_im) plus check_exit_request are emitted and executed for + // EVERY GUEST INSTRUCTION, not per shim call. + // + // That is what the in-race profile was showing all along: + // helper_uc_tracecode 34.54% + // helper_check_exit_request_arm 5.33% + // against only 0.04% in MiscStubDispatch and ~65,000 stub dispatches + // per second - which worked out to an impossible ~5.4us per dispatch. + // The arithmetic never fit because tracecode was not being called per + // dispatch at all; it was being called per instruction. + // + // It also explains why removing 17 probe hooks (task #48) cut + // tracecode's share yet bought no frame rate: the hook LIST got + // shorter, but this global entry was still forcing the per-instruction + // call and the per-instruction PC sync that stops TCG chaining blocks. + // + // Passing 0 means "no instruction limit". What is lost: a runaway + // guest loop inside ONE call now hangs instead of returning after 5M + // instructions and being caught by kMaxCallIterations. That net was + // explicitly documented above as "not a security boundary", and after + // the 2026-09-05 stub fix a normal call already completes in a single + // uc_emu_start, so the budget was almost never the thing that ended a + // call. If a watchdog is wanted later, use ONE long-lived thread + // calling uc_emu_stop - not uc_emu_start's `timeout` argument, which + // spawns a fresh thread per call (uc.c:1036). + err = uc_emu_start(eng, pc, kCallReturnSentinel, 0, 0); if (err != UC_ERR_OK) break; // real fault - handled below uint32_t curPc = 0; uc_reg_read(eng, UC_ARM_REG_PC, &curPc);