diff --git a/app/src/main/java/com/ea/ironmonkey/GameRenderer.java b/app/src/main/java/com/ea/ironmonkey/GameRenderer.java index 1586ef2..b76c2ad 100644 --- a/app/src/main/java/com/ea/ironmonkey/GameRenderer.java +++ b/app/src/main/java/com/ea/ironmonkey/GameRenderer.java @@ -43,12 +43,35 @@ public class GameRenderer implements GLSurfaceView.Renderer { this._height = i2; } + // Task #47 instrumentation (2026-09-19, temporary). Settles a premise that + // has been reasoned from since 2026-09-18 without ever being re-verified + // live: that nativeOnResume runs the guest's persistent loop synchronously + // here and NEVER returns, so GLSurfaceView's own automatic + // post-onDrawFrame eglSwapBuffers stops firing. If that premise holds, + // this logs exactly one line reading entries=1 exits=0 and then stays + // silent forever. If the lines keep coming instead, onDrawFrame IS + // returning, the framework IS also swapping, and that is the second + // present of each observed pair. + // System.nanoTime() is CLOCK_MONOTONIC on Android - the same clock the + // native SWAPMARK lines use - so the two logs correlate directly. + private static int drawEntries = 0; + private static int drawExits = 0; + private static long lastDrawReport = 0; + @Override // android.opengl.GLSurfaceView.Renderer public void onDrawFrame(GL10 gl10) { + drawEntries++; + long now = System.nanoTime(); + if (now - lastDrawReport > 1000000000L) { + lastDrawReport = now; + android.util.Log.i("mpcore_log", "GameRenderer: onDrawFrame entries=" + drawEntries + + " exits=" + drawExits + " t=" + now); + } if (this.drawFrameListener != null) { this.drawFrameListener.onDrawFrame(gl10); } else { this.activity.getRunLoop().onRunLoopTick(); } + drawExits++; } } diff --git a/mpcore/src/main/cpp/emu/gles_shim.cpp b/mpcore/src/main/cpp/emu/gles_shim.cpp index d8d2762..13de449 100644 --- a/mpcore/src/main/cpp/emu/gles_shim.cpp +++ b/mpcore/src/main/cpp/emu/gles_shim.cpp @@ -502,10 +502,42 @@ uint32_t Shim_glClear(GuestEngine& eng, uint32_t r0, uint32_t r1, uint32_t r2, u if (boundFb != 0) sawFboClear.store(true, std::memory_order_relaxed); const bool drewIntoScreen = g_drawsSinceSwap.load(std::memory_order_relaxed) > 0; + // FIX (2026-09-19, task #47). Synthesizing a swap here is WRONG and always + // was: it duplicates the present Android's GLSurfaceView already performs + // after every onDrawFrame return, so every frame reached the screen twice. + // + // The whole mechanism rested on a premise recorded on 2026-09-18 - that + // nativeOnResume runs the guest's persistent loop synchronously on the + // GLThread and NEVER returns to onDrawFrame, leaving the framework unable + // to present. That premise was never verified live. It is false. An + // entry/exit counter in GameRenderer.onDrawFrame shows it returning every + // single frame (entries=698 exits=697 - the one gap is the call in + // progress), and the rates match 1:1: + // synthetic swaps 12.98/s (SWAPMARK, one line per swap) + // onDrawFrame 12.69/s (so the framework swaps 12.69/s too) + // = 25.67 presents/s for ~12.8 rendered frames. The measured symptom was + // presents arriving in pairs 10-20ms apart with the SECOND showing the + // PREVIOUS simulation step (race clock stepping 1:10.06 -> 1:10.03 -> + // 1:10.09 -> 1:10.06), which the user saw as the car jumping forward and + // then back along its path. + // + // Letting the framework be the only presenter is also exactly what the + // real game does: libapp.so cannot present at all - its only EGL import is + // eglGetProcAddress and the string "eglSwapBuffers" does not appear + // anywhere in the binary. On the A9 all 2,736 eglSwapBuffers calls in 46s + // came from Android's own framework code. + // + // Kept as a flag rather than deleted: if the 2026-09-18 symptom (screen + // cycling between the stale loading screen, black, and the real scene) + // ever returns, this is the first thing to flip back while the real cause + // 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 = - (boundFb != 0 && drewIntoScreen) || - (boundFb == 0 && clearsColor && drewIntoScreen && - !sawFboClear.load(std::memory_order_relaxed)); + kSynthesizeSwap && + ((boundFb != 0 && drewIntoScreen) || + (boundFb == 0 && clearsColor && drewIntoScreen && + !sawFboClear.load(std::memory_order_relaxed))); if (frameBoundary) { static std::atomic hasClearedBefore{false}; // 2026-09-19: also require that SOMETHING was actually drawn into the @@ -564,6 +596,18 @@ uint32_t Shim_glClear(GuestEngine& eng, uint32_t r0, uint32_t r1, uint32_t r2, u GLfloat curClearColor[4] = {-1, -1, -1, -1}; if (sample) glGetFloatv(GL_COLOR_CLEAR_VALUE, curClearColor); EGLBoolean ok = eglSwapBuffers(dpy, surf); + // Task #47 instrumentation (2026-09-19, temporary). One line per + // swap, not every 100th: the sampled counter said 4.59 swaps/s + // while a screen recording showed 9.03 presents/s, so the presents + // have a second source. steady_clock is CLOCK_MONOTONIC on bionic, + // matching GameRenderer's System.nanoTime(), so these timestamps + // line up with the onDrawFrame counter AND with screenrecord frame + // PTS - which is what tells us whether the extra present lands + // between our swaps or right on top of them. + Log("gles_shim: SWAPMARK n=%llu t=%lld ok=%d", (unsigned long long)n, + (long long)std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()).count(), + (int)ok); if (sample) { GLenum err = glGetError(); // 2026-09-18: also log the CURRENT glClearColor right here