swung0x48/MobileGL
1
0
Fork 0
mirror of https://github.com/MobileGL-Dev/MobileGL synced 2026-11-07 01:53:24 +09:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source
This commit is contained in:
BZLZHH
2026-09-26 17:57:48 +08:00
parent 3a6c5c7f04
commit 6bccf98d7f
4 changed files with 134 additions and 4 deletions
Download Patch File Download Diff File Expand all files Collapse all files
MobileGL/MG_Remote/Client/ClientSession.cpp
+22
View File
@@ -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
+22 -4
View File
@@ -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, "
"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<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
+73
View File
@@ -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
+17
View File
@@ -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.