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 <noreply@anthropic.com>
This commit is contained in:
Claude
@@ -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<uint64_t, uint64_t> hitsByPage;
|
||||
static uint64_t total = 0, lastReportNs = 0;
|
||||
std::lock_guard<std::mutex> lock(mu);
|
||||
hitsByPage[address & ~0xFFFull]++;
|
||||
total++;
|
||||
uint64_t now = (uint64_t)std::chrono::duration_cast<std::chrono::nanoseconds>(
|
||||
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<std::pair<uint64_t, uint64_t>> 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<uint64_t> calls{0};
|
||||
static std::atomic<uint64_t> 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::nanoseconds>(
|
||||
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<uint64_t> calls{0};
|
||||
static std::atomic<uint64_t> 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::nanoseconds>(
|
||||
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);
|
||||
|
||||
Reference in New Issue
Block a user