diff --git a/MobileGL/MG_Remote/Client/ClientSession.cpp b/MobileGL/MG_Remote/Client/ClientSession.cpp index d7ba99ab..2506e8de 100644 --- a/MobileGL/MG_Remote/Client/ClientSession.cpp +++ b/MobileGL/MG_Remote/Client/ClientSession.cpp @@ -13,6 +13,7 @@ #include #include #include +#include #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(std::chrono::duration_cast( + 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(serial), creditMs, + static_cast(io.bytes), + static_cast(io.calls), + static_cast(io.nsInRecv) / 1e6, + static_cast(io.nsTotal) / 1e6); } m_presentsSent = serial; return serial; diff --git a/MobileGL/MG_Remote/Server/ServerLoop.cpp b/MobileGL/MG_Remote/Server/ServerLoop.cpp index d24d64e6..3b75967f 100644 --- a/MobileGL/MG_Remote/Server/ServerLoop.cpp +++ b/MobileGL/MG_Remote/Server/ServerLoop.cpp @@ -10,6 +10,7 @@ #include "ServerLoop.h" #include +#include #include #include @@ -789,13 +790,30 @@ namespace MobileGL::MG_Remote::Server { .count()); const double applyMs = static_cast(sFrameApplyNs) / 1e6; const double wallMs = static_cast(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, " - "wall_ms is Present to Present on the apply thread, and the " - "difference is waiting for work plus retirement plus the socket", + "outside_ms=%.1f | read: %llu B in %llu recv(%llu reads) " + "recv_ms=%.1f total_ms=%.1f (%.0f%% blocked, %.1f MB/s)", static_cast(++sFrameIndex), static_cast(sFrameRecords), applyMs, wallMs, - wallMs - applyMs); + wallMs - applyMs, + static_cast(read.bytes), + static_cast(read.calls), + static_cast(read.reads), + static_cast(read.nsInRecv) / 1e6, + static_cast(read.nsTotal) / 1e6, + read.nsTotal ? 100.0 * static_cast(read.nsInRecv) / + static_cast(read.nsTotal) + : 0.0, + read.nsTotal ? static_cast(read.bytes) / + (static_cast(read.nsTotal) / 1e9) / 1e6 + : 0.0); sFrameWallStart = now; sFrameApplyNs = 0; sFrameRecords = 0; diff --git a/MobileGL/MG_Remote/Transport/StreamLink.cpp b/MobileGL/MG_Remote/Transport/StreamLink.cpp index 579dbf96..c0bc9699 100644 --- a/MobileGL/MG_Remote/Transport/StreamLink.cpp +++ b/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 gReadBytes{0}, gReadCalls{0}, gReadReads{0}; + static std::atomic 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 gSendBytes{0}, gSendCalls{0}, gSendNsInSend{0}; + static std::atomic 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(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::chrono::duration_cast( + 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(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::chrono::duration_cast( + 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::chrono::duration_cast( + 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::chrono::duration_cast( + 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(); diff --git a/MobileGL/MG_Remote/Transport/StreamLink.h b/MobileGL/MG_Remote/Transport/StreamLink.h index 0f8035f2..c6118db1 100644 --- a/MobileGL/MG_Remote/Transport/StreamLink.h +++ b/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.