[Perf] (MG_Remote): Frame time is accounted on both sides, down to the socket reads and the client's waits.

MobileGL/MG_Remote/Client/ClientSession.cpp

@@ -13,6 +13,7 @@
 #include <MG_Remote/FatalFunnel.h>
 #include <MG_Remote/Handshake.h>
 #include <MG_Remote/Transport/LinkMetrics.h>
+#include <MG_Remote/Transport/StreamLink.h>
 
 #include "../CapsCodec.h"
 #include "../Protocol/generated/protocol_generated.h"
@@ -2260,6 +2261,16 @@ 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;
+            // 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
+            // GL thread at 13% of the frame, the server's apply at 7%, and the server's io thread
+            // 97% blocked in recv waiting for this side. So the missing time is on the CLIENT, and
+            // this is the only per-frame wait the client is known to take - it blocks here until
+            // the server acknowledges the swap of (serial - credit). With it, the io thread's send
+            // side (is the socket full?) and the frame's own wall/CPU, the 80% has nowhere left to
+            // hide: it is either this wait, the send, or the game.
+            const auto paceStarted = std::chrono::steady_clock::now();
             const BarrierWaitScope waiting;
             Transport::SessionWait wait = Transport::SessionWait::TimedOut;
             for (;;) {
@@ -2286,6 +2297,17 @@ namespace MobileGL::MG_Remote::Client {
             // ShutDown is teardown and returns: the present did not happen, the same answer
             // the barrier gives on a dead doorbell.
             if (wait == Transport::SessionWait::Reached) DrainEventRing(*m_events);
+            const double creditMs =
+                static_cast<double>(std::chrono::duration_cast<std::chrono::nanoseconds>(
+                    std::chrono::steady_clock::now() - paceStarted).count()) / 1e6;
+            const auto io = Transport::StreamLink::TakeSendStats();
+            MGLOG_I("P65ClientPace present=%llu credit_wait_ms=%.1f | io: %llu B in %llu sendmsg "
+                    "send_ms=%.1f total_ms=%.1f",
+                    static_cast<unsigned long long>(serial), creditMs,
+                    static_cast<unsigned long long>(io.bytes),
+                    static_cast<unsigned long long>(io.calls),
+                    static_cast<double>(io.nsInRecv) / 1e6,
+                    static_cast<double>(io.nsTotal) / 1e6);
         }
         m_presentsSent = serial;
         return serial;

MobileGL/MG_Remote/Server/ServerLoop.cpp

@@ -10,6 +10,7 @@
 
 #include "ServerLoop.h"
 #include <MG_Remote/FatalFunnel.h>
+#include <MG_Remote/Transport/StreamLink.h>
 #include <MG_Backend/MGPipe/PipeInputs.h>
 
 #include <Config.h>
@@ -789,13 +790,30 @@ namespace MobileGL::MG_Remote::Server {
                                 .count());
                         const double applyMs = static_cast<double>(sFrameApplyNs) / 1e6;
                         const double wallMs = static_cast<double>(wallNs) / 1e6;
+                        // AND THE STAGE NOTHING ELSE COVERS: the io thread's socket reads, which
+                        // its own MGLOG_ lines cannot report (the phone's forwarded log carries
+                        // mgl-srv-apply and mgl-display-ser only). read_ms is wall time inside
+                        // recv - blocking included - so a frame that is 90% read_ms is a frame the
+                        // reader spent WAITING for bytes, and one that is mostly recv calls with
+                        // little read_ms is a reader that is copying.
+                        const auto read = Transport::StreamLink::TakeReadStats();
                         MGLOG_I("P65ServerFrame frame=%llu records=%llu apply_ms=%.1f wall_ms=%.1f "
-                                "outside_ms=%.1f - apply_ms is the sum of PipeApplier::ApplyOne, "
+                                "outside_ms=%.1f | read: %llu B in %llu recv(%llu reads) "
-                                "wall_ms is Present to Present on the apply thread, and the "
+                                "recv_ms=%.1f total_ms=%.1f (%.0f%% blocked, %.1f MB/s)",
-                                "difference is waiting for work plus retirement plus the socket",
                                 static_cast<unsigned long long>(++sFrameIndex),
                                 static_cast<unsigned long long>(sFrameRecords), applyMs, wallMs,
-                                wallMs - applyMs);
+                                wallMs - applyMs,
+                                static_cast<unsigned long long>(read.bytes),
+                                static_cast<unsigned long long>(read.calls),
+                                static_cast<unsigned long long>(read.reads),
+                                static_cast<double>(read.nsInRecv) / 1e6,
+                                static_cast<double>(read.nsTotal) / 1e6,
+                                read.nsTotal ? 100.0 * static_cast<double>(read.nsInRecv) /
+                                                   static_cast<double>(read.nsTotal)
+                                             : 0.0,
+                                read.nsTotal ? static_cast<double>(read.bytes) /
+                                                   (static_cast<double>(read.nsTotal) / 1e9) / 1e6
+                                             : 0.0);
                         sFrameWallStart = now;
                         sFrameApplyNs = 0;
                         sFrameRecords = 0;

MobileGL/MG_Remote/Transport/StreamLink.cpp

@@ -27,6 +27,16 @@
 #endif
 
 namespace MobileGL::MG_Remote::Transport {
+    // P65Read's counters: written by the server's io thread, drained by its apply thread (see
+    // StreamLink::TakeReadStats).
+    static std::atomic<std::uint64_t> gReadBytes{0}, gReadCalls{0}, gReadReads{0};
+    static std::atomic<std::uint64_t> gReadNsInRecv{0}, gReadNsTotal{0};
+    // P65CLIENTPACE's send half: the io thread's side of the same question. A sendmsg that blocks
+    // is the socket full, i.e. the WRITE side's back-pressure - and on a client whose frame is 80%
+    // waiting, "is it waiting to hand bytes over, or waiting for the game to make them" is the
+    // whole question. Time spent inside sendmsg, not calls made.
+    static std::atomic<std::uint64_t> gSendBytes{0}, gSendCalls{0}, gSendNsInSend{0};
+    static std::atomic<std::uint64_t> gSendNsTotal{0};
     namespace {
         constexpr std::uint64_t kDataEnvelopeBytes = 20;
         constexpr std::uint64_t kMaxDataPayload = kMaxFramePayloadSize - kDataEnvelopeBytes;
@@ -187,9 +197,32 @@ namespace MobileGL::MG_Remote::Transport {
         }
         bool Read(void* data, std::size_t size) {
 #if !defined(_WIN32)
+            // P65Read: THE SERVER'S SOCKET-READ PATH, WHICH NOTHING MEASURED. The per-frame
+            // clocks say the frame's time is NOT in the client's GL thread (13%) and NOT in
+            // PipeApplier::ApplyOne (11%) - 76% of a 105-185 ms frame is outside both, and the
+            // only stage between them is this loop. Two different worlds look identical from
+            // outside it and need opposite fixes:
+            //   * few BIG recvs with little time blocked -> the reader is copying, i.e. one
+            //     thread's throughput is the ceiling;
+            //   * many SMALL recvs, most of the wall spent blocked -> the reader is STARVED and
+            //     the client (or the batching on its side) sets the pace.
+            // Counted here rather than sampled from /proc because the question is per-call, not
+            // per-thread. Printed every kReadMarkBytes so a frame's worth of traffic yields
+            // several lines and no line can be lost to a quiet period.
+            constexpr std::uint64_t kReadMarkBytes = 8ull * 1024ull * 1024ull;
+            (void)kReadMarkBytes;
+            const auto readStarted = std::chrono::steady_clock::now();
+            std::uint64_t calls = 0;
             auto* p = static_cast<std::uint8_t*>(data);
+            const auto wanted = size;
             while (size) {
+                const auto recvStarted = std::chrono::steady_clock::now();
                 const auto n = ::recv(fd, p, size, 0);
+                gReadNsInRecv.fetch_add(static_cast<std::uint64_t>(
+                    std::chrono::duration_cast<std::chrono::nanoseconds>(
+                        std::chrono::steady_clock::now() - recvStarted).count()),
+                    std::memory_order_relaxed);
+                ++calls;
                 if (n < 0 && errno == EINTR) continue;
                 if (n <= 0) {
                     Die(!stopping.load(std::memory_order_acquire));
@@ -198,6 +231,13 @@ namespace MobileGL::MG_Remote::Transport {
                 p += n;
                 size -= static_cast<std::size_t>(n);
             }
+            gReadCalls.fetch_add(calls, std::memory_order_relaxed);
+            gReadReads.fetch_add(1, std::memory_order_relaxed);
+            gReadBytes.fetch_add(wanted, std::memory_order_relaxed);
+            gReadNsTotal.fetch_add(static_cast<std::uint64_t>(
+                std::chrono::duration_cast<std::chrono::nanoseconds>(
+                    std::chrono::steady_clock::now() - readStarted).count()),
+                std::memory_order_relaxed);
             return true;
 #else
             (void)data;
@@ -221,8 +261,16 @@ namespace MobileGL::MG_Remote::Transport {
             msghdr message{};
             message.msg_iov = vectors;
             message.msg_iovlen = size ? 2 : 1;
+            const auto sendStarted = std::chrono::steady_clock::now();
+            std::uint64_t sendCalls = 0;
             while (message.msg_iovlen) {
+                const auto syscallStarted = std::chrono::steady_clock::now();
                 const auto sent = ::sendmsg(fd, &message, MSG_NOSIGNAL);
+                gSendNsInSend.fetch_add(static_cast<std::uint64_t>(
+                    std::chrono::duration_cast<std::chrono::nanoseconds>(
+                        std::chrono::steady_clock::now() - syscallStarted).count()),
+                    std::memory_order_relaxed);
+                ++sendCalls;
                 if (sent < 0 && errno == EINTR) continue;
                 if (sent <= 0) {
                     Die(!stopping.load(std::memory_order_acquire));
@@ -239,6 +287,12 @@ namespace MobileGL::MG_Remote::Transport {
                     message.msg_iov->iov_len -= consumed;
                 }
             }
+            gSendCalls.fetch_add(sendCalls, std::memory_order_relaxed);
+            gSendBytes.fetch_add(size, std::memory_order_relaxed);
+            gSendNsTotal.fetch_add(static_cast<std::uint64_t>(
+                std::chrono::duration_cast<std::chrono::nanoseconds>(
+                    std::chrono::steady_clock::now() - sendStarted).count()),
+                std::memory_order_relaxed);
             return true;
 #else
             (void)payload;
@@ -425,6 +479,25 @@ namespace MobileGL::MG_Remote::Transport {
         }
     };
 
+    StreamLink::ReadStats StreamLink::TakeSendStats() {
+        ReadStats out;
+        out.bytes = gSendBytes.exchange(0, std::memory_order_relaxed);
+        out.calls = gSendCalls.exchange(0, std::memory_order_relaxed);
+        out.nsInRecv = gSendNsInSend.exchange(0, std::memory_order_relaxed);
+        out.nsTotal = gSendNsTotal.exchange(0, std::memory_order_relaxed);
+        return out;
+    }
+
+    StreamLink::ReadStats StreamLink::TakeReadStats() {
+        ReadStats out;
+        out.bytes = gReadBytes.exchange(0, std::memory_order_relaxed);
+        out.calls = gReadCalls.exchange(0, std::memory_order_relaxed);
+        out.reads = gReadReads.exchange(0, std::memory_order_relaxed);
+        out.nsInRecv = gReadNsInRecv.exchange(0, std::memory_order_relaxed);
+        out.nsTotal = gReadNsTotal.exchange(0, std::memory_order_relaxed);
+        return out;
+    }
+
     StreamLink::StreamLink() : m_impl(new Impl) {}
     StreamLink::~StreamLink() {
         Detach();

MobileGL/MG_Remote/Transport/StreamLink.h

@@ -11,6 +11,23 @@ namespace MobileGL::MG_Remote::Transport {
     public:
         StreamLink();
         ~StreamLink() override;
+        // P65READ: THE SERVER'S SOCKET-READ PATH, ACCOUNTED WHERE IT CAN BE SEEN. The counters are
+        // published from the io thread's recv loop and read by the APPLY thread, because the io
+        // thread's own MGLOG_ lines never reach the phone's forwarded log (only mgl-srv-apply and
+        // mgl-display-ser do - measured, not assumed). Taking them RESETS them, so one call is one
+        // frame's worth of the stage nothing else measures: the frame's time is not the client's GL
+        // thread (13%) and not PipeApplier::ApplyOne (11%), and this is what sits between them.
+        struct ReadStats {
+            std::uint64_t bytes = 0;     // payload bytes taken off the socket
+            std::uint64_t calls = 0;     // recv() calls it took
+            std::uint64_t reads = 0;     // Link::Read() calls (one per header, envelope or chunk)
+            std::uint64_t nsInRecv = 0;  // wall time inside recv - blocking included
+            std::uint64_t nsTotal = 0;   // wall time inside Read
+        };
+        static ReadStats TakeReadStats();
+        // The client's half: bytes handed to the io thread's sendmsg, the calls it took, and the
+        // wall time inside sendmsg (blocking included). nsInRecv carries the send time.
+        static ReadStats TakeSendStats();
         MobileGLResult Attach(int dataFd, SessionSegments& mirrors, TransportRoleTag role);
         MobileGLResult AttachOwned(int dataFd, const struct SessionSegmentSizes& sizes, TransportRoleTag role);
         // PH-7 (4), ID-P7-3. The SERVER's half of a nonce-bound data connection, in two steps.