From 7acf3ea8e158ddd139f30a103850d32661332ffa Mon Sep 17 00:00:00 2001 From: Swung0x48 Date: Thu, 8 Oct 2026 18:01:50 -0400 Subject: [PATCH] Transport: MOBILEGL_IPC_WAIT_STATS logs the run-ahead client's waits per frame by record op, quiesce reason and barriered verb; the per-frame P65ClientPace line drops to debug. --- MobileGL/Config.h | 4 ++ MobileGL/ConfigLoader.cpp | 1 + MobileGL/MG_Impl/Pipe/PipeFill.cpp | 1 + MobileGL/MG_Remote/Client/ClientSession.cpp | 61 ++++++++++++++++++++- MobileGL/MG_Remote/Client/ClientSession.h | 3 + 5 files changed, 69 insertions(+), 1 deletion(-) diff --git a/MobileGL/Config.h b/MobileGL/Config.h index 043187e1..a7f3128a 100644 --- a/MobileGL/Config.h +++ b/MobileGL/Config.h @@ -708,6 +708,10 @@ namespace MobileGL::MG_Config { // client that is already CPU-bound and costs a frame of latency, which is why the // default is 1 and not "as deep as the ring". Uint32 PresentCredit = 1; + // MOBILEGL_IPC_WAIT_STATS (P15, diagnostic): every 600 presents, log how many times per + // frame the run-ahead client waited, by record op (applied/reply), by quiesce reason and + // barriered verb, for ring space and for the present credit. Off by default. + Bool WaitStats = false; // MOBILEGL_IPC_CONTROL_TIMEOUT_MS (CONTRACT-P6 §5.4 D5b): how long a spawn/tcp client // waits for the SurfaceReply to one surface-control op (eglCreate*Surface, MakeCurrent, // ...) once the server's backend is up. Its expiry is NOT fatal: the doorbell's death diff --git a/MobileGL/ConfigLoader.cpp b/MobileGL/ConfigLoader.cpp index ae6002f1..ff44f945 100644 --- a/MobileGL/ConfigLoader.cpp +++ b/MobileGL/ConfigLoader.cpp @@ -617,6 +617,7 @@ namespace MobileGL::MG_ConfigLoader { ipc.ControlTimeoutMs = QueryEnvUint32("MOBILEGL_IPC_CONTROL_TIMEOUT_MS", 5000, 100, 600000); ipc.ColdStartMs = QueryEnvUint32("MOBILEGL_IPC_COLD_START_MS", 20000, 100, 600000); ipc.StrictErrors = QueryEnvFlag("MOBILEGL_IPC_STRICT_ERRORS"); + ipc.WaitStats = QueryEnvFlag("MOBILEGL_IPC_WAIT_STATS"); ipc.Audit = QueryEnvFlag("MOBILEGL_IPC_AUDIT"); QueryEnvVariable("MOBILEGL_IPC_SERVER_AFFINITY", ipc.ServerAffinity, "auto"); // P5f f1: the dual-block rehearsal (P5F-WIRE-COMPLETENESS.md §4). Forced OFF by the diff --git a/MobileGL/MG_Impl/Pipe/PipeFill.cpp b/MobileGL/MG_Impl/Pipe/PipeFill.cpp index a1433b4a..b09cb5eb 100644 --- a/MobileGL/MG_Impl/Pipe/PipeFill.cpp +++ b/MobileGL/MG_Impl/Pipe/PipeFill.cpp @@ -3463,6 +3463,7 @@ namespace MobileGL::MG_Pipe { // delete it and the guard below aborts with Fatal{RoleViolation, "gPipeInputs"} // naming MGPipeValidateForVerb, because the guard now tests the fact rather than // taking the claim. + if (runAhead) MG_Remote::Client::ClientSession::NoteBarrieredVerbForStats(kMGPipeVerbNames[static_cast(verb)]); QuiesceApplierBeforeFill("MGPipeValidateForVerb"); MG_Remote::Client::ClientSession::RefusePipeInputsTouchWhileApplierOwnsIt( "MGPipeValidateForVerb", /*isBarrieredFill=*/barriered); diff --git a/MobileGL/MG_Remote/Client/ClientSession.cpp b/MobileGL/MG_Remote/Client/ClientSession.cpp index 36d1f887..91b90d1b 100644 --- a/MobileGL/MG_Remote/Client/ClientSession.cpp +++ b/MobileGL/MG_Remote/Client/ClientSession.cpp @@ -24,6 +24,7 @@ #include "../Transport/FdPassing.h" #include "../Transport/InProcessTransport.h" #include "WireTables.h" +#include "../Wire/PipeWireCodec.h" #include "EmitTables.h" #include #include "ServerProbe.h" @@ -270,6 +271,53 @@ namespace MobileGL::MG_Remote::Client { BarrierWaitScope& operator=(const BarrierWaitScope&) = delete; }; + // P15: THE WAIT CENSUS (MOBILEGL_IPC_WAIT_STATS=1). Run-ahead records and replays + // asynchronously by default, so in steady state the only per-frame wait should be the + // present credit; this counts every other one so a sync point cannot hide. GL-thread + // only (the client's waits all happen there), so plain counters. + struct WaitCensus { + static constexpr SizeT kReasons = 32; + Array(MG_Pipe::MGPWireOp::kOpCount)> recordWaits{}; + Array reasonNames{}; + Array reasonCounts{}; + Uint32 ringSpace = 0; + Uint32 presentCredit = 0; + Uint32 frames = 0; + + void Reason(const char* why) { + for (SizeT i = 0; i < kReasons; ++i) { + if (reasonNames[i] == nullptr) reasonNames[i] = why; + if (reasonNames[i] == why || std::strcmp(reasonNames[i], why) == 0) { + ++reasonCounts[i]; + return; + } + } + } + void FrameEnd() { + if (++frames < 600) return; + String line; + char item[160]; + const double f = static_cast(frames); + for (SizeT i = 0; i < recordWaits.size(); ++i) { + if (recordWaits[i] == 0) continue; + std::snprintf(item, sizeof(item), " wait[%s]=%.2f", + Wire::WireOpName(static_cast(i)), recordWaits[i] / f); + line += item; + } + for (SizeT i = 0; i < kReasons && reasonNames[i] != nullptr; ++i) { + if (reasonCounts[i] == 0) continue; + std::snprintf(item, sizeof(item), " quiesce[%s]=%.2f", reasonNames[i], reasonCounts[i] / f); + line += item; + } + MGLOG_I("MGPIPE-WAITS frames=%u per-frame:%s ringSpace=%.2f presentCredit=%.2f", frames, + line.empty() ? " (none)" : line.c_str(), ringSpace / f, presentCredit / f); + recordWaits.fill(0); + reasonCounts.fill(0); + ringSpace = presentCredit = frames = 0; + } + }; + WaitCensus g_waitCensus; + // A DEADLOCK DETECTOR, NOT A PERFORMANCE GATE. The barrier exists so that a record the // applier never retires is reported instead of hanging: a lost record never completes at // all, while a slow apply completes late. The bound only has to sit far above the slowest @@ -2187,6 +2235,7 @@ namespace MobileGL::MG_Remote::Client { Wire::MGPipeWireRecordLayout(op, payload, layout); const Uint64 toEnd = m_cmd->Capacity() - m_cmd->LocalHead() % m_cmd->Capacity(); const Uint64 needed = layout.TotalBytes + (toEnd < layout.TotalBytes ? toEnd : 0); + if (MG_Config::Ipc.WaitStats) ++g_waitCensus.ringSpace; const BarrierWaitScope waiting; const auto wait = m_producer.WaitForCmdSpace(needed, kBarrierTimeoutMs); if (wait == Transport::SessionWait::ShutDown) { @@ -2359,6 +2408,7 @@ namespace MobileGL::MG_Remote::Client { return seq; } + if (MG_Config::Ipc.WaitStats && RunAheadArmed()) ++g_waitCensus.recordWaits[static_cast(op)]; const BarrierWaitScope waiting; const Uint64 waitBudgetMs = AppliedWaitBudgetMs(op, payload); const Transport::SessionWait wait = @@ -2509,6 +2559,10 @@ namespace MobileGL::MG_Remote::Client { #endif } + void ClientSession::NoteBarrieredVerbForStats(const char* verb) { + if (MG_Config::Ipc.WaitStats) g_waitCensus.Reason(verb); + } + void ClientSession::WaitForApplyToCatchUp(const char* why) { #if MOBILEGL_BUILD_DISAGGREGATED // A NO-OP WITHOUT RUN-AHEAD, and that is not an optimisation: under lockstep the @@ -2517,6 +2571,7 @@ namespace MobileGL::MG_Remote::Client { // watermark that is already reached. if (!m_runAheadArmed || !m_started) return; if (m_producer.LastPublishedSeq() == 0) return; + if (MG_Config::Ipc.WaitStats) g_waitCensus.Reason(why); const auto deadline = std::chrono::steady_clock::now() + std::chrono::milliseconds(kBarrierTimeoutMs); const BarrierWaitScope waiting; for (;;) { @@ -2612,6 +2667,7 @@ namespace MobileGL::MG_Remote::Client { // overlap and at most one frame of added latency (ruling 4 / ID-92). const Uint64 awaited = serial - credit; ++m_presentCreditWaits; + if (MG_Config::Ipc.WaitStats) ++g_waitCensus.presentCredit; // P65CLIENTPACE: WHERE THE CLIENT'S FRAME GOES, ONE LINE PER FRAME. // // The frame is a lockstep ping-pong and every stage measured so far is IDLE: the client @@ -2652,7 +2708,9 @@ namespace MobileGL::MG_Remote::Client { static_cast(std::chrono::duration_cast( std::chrono::steady_clock::now() - paceStarted).count()) / 1e6; const auto io = Transport::LinkMetricsTakeSendStats(); - MGLOG_I("P65ClientPace present=%llu credit_wait_ms=%.1f | io: %llu B in %llu sendmsg " + // P15: MGLOG_D - an INFO line per frame on the GL thread cost a format and a + // logd write every present on the shipped build. + MGLOG_D("P65ClientPace present=%llu credit_wait_ms=%.1f | io: %llu B in %llu sendmsg " "send_ms=%.1f total_ms=%.1f", static_cast(serial), creditMs, static_cast(io.bytes), @@ -2661,6 +2719,7 @@ namespace MobileGL::MG_Remote::Client { static_cast(io.nsTotal) / 1e6); } m_presentsSent = serial; + if (MG_Config::Ipc.WaitStats) g_waitCensus.FrameEnd(); return serial; #else return ++m_presentsSent; diff --git a/MobileGL/MG_Remote/Client/ClientSession.h b/MobileGL/MG_Remote/Client/ClientSession.h index 064b33d3..663e2625 100644 --- a/MobileGL/MG_Remote/Client/ClientSession.h +++ b/MobileGL/MG_Remote/Client/ClientSession.h @@ -372,6 +372,9 @@ namespace MobileGL::MG_Remote::Client { // in the timeout Fatal, because "which forced wait wedged" is the whole diagnostic. // A no-op when run-ahead is not armed (the client is already in step by construction). void WaitForApplyToCatchUp(const char* why); + // P15 wait census (MOBILEGL_IPC_WAIT_STATS): the validate point names the verb whose + // barriered fill is about to quiesce the applier. + static void NoteBarrieredVerbForStats(const char* verb); // glFinish. Flush and Finish stay no-ops ON THE WIRE (ARCHITECTURE §11, :415) - there // is no record to emit - but "the GL commands issued so far have completed" cannot be