diff --git a/mpcore/src/main/cpp/emu/gles_shim.cpp b/mpcore/src/main/cpp/emu/gles_shim.cpp index bc884cd..f43846b 100644 --- a/mpcore/src/main/cpp/emu/gles_shim.cpp +++ b/mpcore/src/main/cpp/emu/gles_shim.cpp @@ -14,6 +14,12 @@ #include #include +// Defined in guest_engine.cpp at global scope - counts EVERY shim crossing +// (libc, JNI, GLES), which is what the PERF line needs to answer whether our +// shim boundary is what paces the frame. Declared here rather than in a +// header because it is temporary task #56 instrumentation. +extern std::atomic g_stubDispatchCount; + // 2026-09-18 (task #39): needs real external linkage, unlike everything else // in this file's anonymous namespace below, because guest_engine.cpp's // TextClipDispatchEntryProbeHookCb reads it via `extern` from a different @@ -91,6 +97,61 @@ void NoteDrawForSwapGate() { } } +// Task #56 live metrics (2026-09-19, temporary - flip off when the session +// ends). The user's observation is the whole reason this exists: after +// crashing into a wall with nothing ahead the game runs fast, and the moment +// objects or particles (motion blur, nitro, collision sparks) appear the +// speed drops at once. That points at per-DRAW cost on our side rather than +// at physics, race logic, or the GPU - the in-race profile had the Mali +// driver at only 1.3%. +// +// So: report draw calls and frames once a second, together, in ONE line, so +// the correlation can be read live while driving instead of joining two logs +// by timestamp afterwards. Frames are counted as synthesized-frame +// boundaries would be - here, default-framebuffer draws reset per swap - so +// drawsPerFrame is the number that matters. +constexpr bool kLogPerfMetrics = true; +std::atomic g_totalDraws{0}; +std::atomic g_totalIndices{0}; +std::atomic g_framesSeen{0}; + +void NotePerfDraw(GLsizei count) { + if (!kLogPerfMetrics) return; + g_totalDraws.fetch_add(1, std::memory_order_relaxed); + g_totalIndices.fetch_add((uint64_t)(count > 0 ? count : 0), std::memory_order_relaxed); + static std::atomic lastNs{0}; + uint64_t now = (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); + uint64_t last = lastNs.load(std::memory_order_relaxed); + if (now - last < 1000000000ull) return; + if (!lastNs.compare_exchange_strong(last, now, std::memory_order_relaxed)) return; + if (last == 0) return; + static uint64_t prevDraws = 0, prevIdx = 0, prevFrames = 0, prevGl = 0; + double dt = (now - last) / 1e9; + uint64_t d = g_totalDraws.load(std::memory_order_relaxed); + uint64_t ix = g_totalIndices.load(std::memory_order_relaxed); + uint64_t f = g_framesSeen.load(std::memory_order_relaxed); + double frames = (double)(f - prevFrames) / dt; + double draws = (double)(d - prevDraws) / dt; + // glCalls distinguishes the two candidate explanations for the drop the + // user demonstrated (task #56). If GLES shim calls per FRAME rise along + // with draws, the cost is on our side of the boundary - more state + // changes, each one a shim crossing. If calls per frame stay flat while + // fps collapses, our boundary is not what is pacing the frame, and the + // next suspect is the GPU: particles are blended overdraw, and a CPU + // profile cannot see a thread that is BLOCKED rather than busy (the + // lesson task #49 already charged us for once). + uint64_t gl = g_stubDispatchCount.load(std::memory_order_relaxed); + Log("gles_shim: PERF fps=%.1f draws/s=%.0f draws/frame=%.0f indices/draw=%.0f " + "shimCalls/s=%.0f shimCalls/frame=%.0f shimCalls/draw=%.1f", + frames, draws, frames > 0 ? draws / frames : 0.0, + (d - prevDraws) ? (double)(ix - prevIdx) / (double)(d - prevDraws) : 0.0, + (double)(gl - prevGl) / dt, frames > 0 ? (double)(gl - prevGl) / dt / frames : 0.0, + (d - prevDraws) ? (double)(gl - prevGl) / (double)(d - prevDraws) : 0.0); + prevGl = gl; + prevDraws = d; prevIdx = ix; prevFrames = f; +} + std::atomic g_textUploadTraceWindow{0}; bool LooksLikeTextOverlayUpload(GLsizei width, GLsizei height) { // 738x302 specifically, plus a little slack for other similarly-shaped @@ -538,11 +599,23 @@ uint32_t Shim_glClear(GuestEngine& eng, uint32_t r0, uint32_t r1, uint32_t r2, u // is found - that symptom was diagnosed under the false premise above and // its actual explanation is therefore still open. constexpr bool kSynthesizeSwap = false; - const bool frameBoundary = - kSynthesizeSwap && + // The boundary CONDITION is still worth evaluating even though we no + // longer present on it (task #47): it is the only per-frame signal this + // shim has natively, and task #56 needs draws-per-FRAME, not draws per + // second. Counting here also restores the g_drawsSinceSwap reset that the + // disabled swap block used to perform - without it "drew into screen" + // would latch true after the first draw and every later FBO clear would + // be counted as a frame. + const bool rawFrameBoundary = ((boundFb != 0 && drewIntoScreen) || (boundFb == 0 && clearsColor && drewIntoScreen && !sawFboClear.load(std::memory_order_relaxed))); + if (rawFrameBoundary && kLogPerfMetrics && !kSynthesizeSwap) { + if (g_drawsSinceSwap.exchange(0, std::memory_order_relaxed) > 0) { + g_framesSeen.fetch_add(1, std::memory_order_relaxed); + } + } + const bool frameBoundary = kSynthesizeSwap && rawFrameBoundary; if (frameBoundary) { static std::atomic hasClearedBefore{false}; // 2026-09-19: also require that SOMETHING was actually drawn into the @@ -814,6 +887,7 @@ uint32_t Shim_glDrawArrays(GuestEngine& eng, uint32_t r0, uint32_t r1, uint32_t glDrawArrays((GLenum)eng.ReadIncomingArg(0, r0, r1, r2, r3, sp), (GLint)eng.ReadIncomingArg(1, r0, r1, r2, r3, sp), count); g_drawArraysCalls.fetch_add(1, std::memory_order_relaxed); g_drawArraysVerts.fetch_add((uint64_t)(count > 0 ? count : 0), std::memory_order_relaxed); + NotePerfDraw(count); NoteDrawForSwapGate(); return 0; } @@ -986,6 +1060,7 @@ uint32_t Shim_glDrawElements(GuestEngine& eng, uint32_t r0, uint32_t r1, uint32_ : (a3_g ? eng.G2H(a3_g) : nullptr); glDrawElements((GLenum)eng.ReadIncomingArg(0, r0, r1, r2, r3, sp), count, (GLenum)eng.ReadIncomingArg(2, r0, r1, r2, r3, sp), indicesArg); g_drawElementsCalls.fetch_add(1, std::memory_order_relaxed); + NotePerfDraw(count); NoteDrawForSwapGate(); g_drawElementsIndices.fetch_add((uint64_t)(count > 0 ? count : 0), std::memory_order_relaxed); { diff --git a/mpcore/src/main/cpp/emu/guest_engine.cpp b/mpcore/src/main/cpp/emu/guest_engine.cpp index de30fdb..e521545 100644 --- a/mpcore/src/main/cpp/emu/guest_engine.cpp +++ b/mpcore/src/main/cpp/emu/guest_engine.cpp @@ -133,7 +133,7 @@ constexpr uint32_t kGuardPageSize = kPageSize; // 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 kCountStubDispatches = true; constexpr bool kCountTextWrites = false; // kCountArenaWrites - task #54. tb_invalidate_phys_page_fast_arm is 5.56% of // the in-race profile and its cause is open: the .text write counter above @@ -187,8 +187,26 @@ struct ImportStubEntry { std::string name; ImportShimFn shim; // nullptr if not implemented - see guest_engine's own unresolved-import log-once behavior bool loggedUnresolved = false; + // Task #56 instrumentation (2026-09-19, temporary). Live measurement on + // the Xiaomi 14 showed shim crossings/sec pinned near a ceiling (~170k) + // regardless of scene, with the frame rate falling out as + // ceiling / crossings-per-frame - 148350/4385 = 33.8fps fast, + // 167811/21665 = 7.7fps slow, both exact. Draw calls turned out NOT to + // be the driver (178 vs 149 per frame across a 4x fps gap). So the + // question is WHICH shims make up that flood. Counted per entry rather + // than in a shared map because a mutex on every crossing would tax the + // very thing being measured. + std::atomic calls{0}; + uint64_t prevCalls = 0; }; +// All entries ever created, for the per-second top-N report. Appended under +// the mutex at creation time (rare); read without one by the reporter, which +// is safe because entries are never destroyed and the vector only grows +// during startup. +std::mutex g_importStubEntriesMutex; +std::vector g_importStubEntries; + // Diagnostic only (see ARM64_TRANSLATION_LAYER.md's "why does the process // die" investigation) - fires on every UC_ERR_READ/WRITE/FETCH_UNMAPPED // fault AND every _PROT violation (registered as UC_HOOK_MEM_INVALID, not @@ -2215,14 +2233,60 @@ void RenderCrashProbeHookCb(uc_engine* uc, uint64_t, uint32_t, void*) { // executes the real `BX LR` immediately after, still inside the *same* // uc_emu_start() call, using LR exactly as it already stands (untouched by // this function) for correct ARM/Thumb interworking. +// Prints the busiest shims once a second. Time-gated with a CAS so only one +// thread does the work; everything else just returns after its increment. +void ReportTopShims() { + static std::atomic lastNs{0}; + uint64_t now = (uint64_t)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(); + uint64_t last = lastNs.load(std::memory_order_relaxed); + if (now - last < 1000000000ull) return; + if (!lastNs.compare_exchange_strong(last, now, std::memory_order_relaxed)) return; + if (last == 0) return; + double dt = (now - last) / 1e9; + std::vector> hot; + uint64_t total = 0; + { + std::lock_guard lock(g_importStubEntriesMutex); + for (auto* e : g_importStubEntries) { + uint64_t c = e->calls.load(std::memory_order_relaxed); + uint64_t delta = c - e->prevCalls; + e->prevCalls = c; + total += delta; + if (delta) hot.emplace_back(delta, e); + } + } + if (hot.empty()) return; + std::sort(hot.begin(), hot.end(), [](auto& a, auto& b) { return a.first > b.first; }); + std::string s; + for (size_t i = 0; i < hot.size() && i < 8; i++) { + char buf[128]; + snprintf(buf, sizeof(buf), " %s=%.0f/s(%.0f%%)", hot[i].second->name.c_str(), + (double)hot[i].first / dt, 100.0 * (double)hot[i].first / (double)total); + s += buf; + } + Log("GuestEngine: TOPSHIMS total=%.0f/s over %zu distinct |%s", (double)total / dt, hot.size(), + s.c_str()); +} + void import_stub_dispatch_cb(uc_engine* uc, uint64_t address, uint32_t /*size*/, void* user_data) { auto* entry = static_cast(user_data); + if (kCountStubDispatches) { + entry->calls.fetch_add(1, std::memory_order_relaxed); + ReportTopShims(); + } + // One batched read instead of five separate uc_reg_read calls (task #56). + // Each uc_reg_read is a full Unicorn API entry - argument checks plus a + // per-arch switch - and this runs on EVERY shim crossing, measured at + // ~170,000/sec during gameplay. uc_reg_read_batch does the same work + // behind a single entry. uint32_t r0 = 0, r1 = 0, r2 = 0, r3 = 0, sp = 0; - uc_reg_read(uc, UC_ARM_REG_R0, &r0); - uc_reg_read(uc, UC_ARM_REG_R1, &r1); - uc_reg_read(uc, UC_ARM_REG_R2, &r2); - uc_reg_read(uc, UC_ARM_REG_R3, &r3); - uc_reg_read(uc, UC_ARM_REG_SP, &sp); + { + static const int kRegs[5] = {UC_ARM_REG_R0, UC_ARM_REG_R1, UC_ARM_REG_R2, + UC_ARM_REG_R3, UC_ARM_REG_SP}; + void* vals[5] = {&r0, &r1, &r2, &r3, &sp}; + uc_reg_read_batch(uc, kRegs, vals, 5); + } uint32_t result = 0; if (entry->shim) { @@ -2863,6 +2927,10 @@ GuestAddr GuestEngine::ResolveOrCreateImportStub(const std::string& symbolName) auto* entry = new ImportStubEntry(); entry->name = symbolName; + { + std::lock_guard lock(g_importStubEntriesMutex); + g_importStubEntries.push_back(entry); + } auto shimIt = registered_shims_.find(symbolName); entry->shim = (shimIt != registered_shims_.end()) ? shimIt->second : nullptr; @@ -3350,7 +3418,15 @@ GuestAddr GuestEngine::CarveThreadStack() { return base + kStackSize; // top = highest usable address, same convention the old stack_top_ used } +// Task #56: every shim crossing (libc, JNI and GLES alike) passes through +// here, so one relaxed increment gives a total that gles_shim's PERF line can +// print alongside fps and draws in a SINGLE log line - which is the whole +// point, since the question is whether shim calls per FRAME rise when the +// frame rate collapses. At ~50-90k dispatches/sec a relaxed add is noise. +std::atomic g_stubDispatchCount{0}; + void GuestEngine::MiscStubDispatch(uc_engine* uc, uint64_t address, uint32_t size, void* /*userData*/) { + g_stubDispatchCount.fetch_add(1, std::memory_order_relaxed); 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 @@ -3380,16 +3456,16 @@ void GuestEngine::MiscStubDispatch(uc_engine* uc, uint64_t address, uint32_t siz } 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; - { - std::lock_guard lock(eng.misc_stub_dispatch_table_mutex_); - if (idx >= eng.misc_stub_dispatch_table_.size()) { - Log("GuestEngine::MiscStubDispatch: address 0x%llx -> index %zu out of range (table size %zu)", - (unsigned long long)address, idx, eng.misc_stub_dispatch_table_.size()); - return; - } - entry = eng.misc_stub_dispatch_table_[idx]; + // No lock here - see misc_stub_dispatch_table_'s own comment. Acquiring + // the published count pairs with the release store in AllocCodeStub, so + // any entry within `count` is fully written. + size_t count = eng.misc_stub_dispatch_count_.load(std::memory_order_acquire); + if (idx >= count) { + Log("GuestEngine::MiscStubDispatch: address 0x%llx -> index %zu out of range (table size %zu)", + (unsigned long long)address, idx, count); + return; } + const GuestEngine::MiscStubEntry& entry = eng.misc_stub_dispatch_table_[idx]; entry.callback(uc, address, size, entry.userData); } @@ -3435,7 +3511,15 @@ GuestAddr GuestEngine::AllocCodeStub(uc_cb_hookcode_t callback, void* userData) // since this is a pure sequential 4-byte bump allocator with no frees. { std::lock_guard lock(misc_stub_dispatch_table_mutex_); - misc_stub_dispatch_table_.push_back({callback, userData}); + size_t n = misc_stub_dispatch_count_.load(std::memory_order_relaxed); + if (n >= kMaxMiscStubs) { + Log("GuestEngine::AllocCodeStub: dispatch table full (%zu entries) - stub arena and " + "table are sized together, so this means kMiscStubArenaSize grew without " + "kMaxMiscStubs following it", n); + return 0; + } + misc_stub_dispatch_table_[n] = {callback, userData}; + misc_stub_dispatch_count_.store(n + 1, std::memory_order_release); } // Callers store this as a guest-visible, indirectly-callable code // pointer (GOT/PLT relocation targets, guest JNIEnv function-table @@ -3550,7 +3634,7 @@ uint32_t GuestEngine::CallGuestFunction(GuestAddr target, const uint32_t* args, if (plainTarget >= misc_stub_arena_start_ && plainTarget < misc_stub_end_) { size_t idx = (plainTarget - misc_stub_arena_start_) / 4; std::lock_guard lk(misc_stub_dispatch_table_mutex_); - if (idx < misc_stub_dispatch_table_.size()) { + if (idx < misc_stub_dispatch_count_.load(std::memory_order_acquire)) { const MiscStubEntry& e = misc_stub_dispatch_table_[idx]; if (e.callback == import_stub_dispatch_cb) { stubKind = "import stub"; diff --git a/mpcore/src/main/cpp/emu/guest_engine.h b/mpcore/src/main/cpp/emu/guest_engine.h index 4e35f4e..4046d0d 100644 --- a/mpcore/src/main/cpp/emu/guest_engine.h +++ b/mpcore/src/main/cpp/emu/guest_engine.h @@ -551,8 +551,21 @@ private: uc_cb_hookcode_t callback; void* userData; }; - std::vector misc_stub_dispatch_table_; - std::mutex misc_stub_dispatch_table_mutex_; + // Lock-free on the read side (2026-09-19, task #56). This table is hit on + // EVERY shim crossing - measured at ~170,000/sec during gameplay on the + // Xiaomi 14, from several threads - and taking a std::mutex there taxed + // the exact thing being measured. A fixed array plus an atomic published + // count removes it safely: the arena is only kMiscStubArenaSize/4 stubs + // wide by construction (AllocCodeStub bump-allocates 4 bytes each and + // refuses past the end), entries are appended and never removed or + // rewritten, and a writer fills its slot BEFORE publishing the new count + // with release ordering. A reader that acquires the count therefore sees + // a fully-written entry. The mutex stays for the append side, which runs + // a few hundred times at startup. + static constexpr size_t kMaxMiscStubs = 16 * 1024 / 4; + MiscStubEntry misc_stub_dispatch_table_[kMaxMiscStubs] = {}; + std::atomic misc_stub_dispatch_count_{0}; + std::mutex misc_stub_dispatch_table_mutex_; // append side only // See crashed()'s own comment. Global (not per-thread) on purpose - a // fault on ANY thread means the ONE shared host_region_ every thread's