From 170b789e7fa9bfd2751a1133fcb1e77c5c109c85 Mon Sep 17 00:00:00 2001 From: BZLZHH Date: Fri, 25 Sep 2026 20:45:18 +0800 Subject: [PATCH] [Perf] (MG_Remote/Transport): the per-op reply-wait split prints with every frame, because a whole-session total cannot name the rows behind one frame - The device run that motivated this made the point: 43,232 of a session's 43,629 reply waits were in ONE atlas frame, and the exit summary never appeared at all - a SIGTERM does not take the session's clean stop path, so LinkMetricsEnd is never reached. The split added one commit ago was therefore invisible on exactly the run that needed it. - Emit now writes a second line for any frame that bought a wait: `P65LinkMetrics kind=frame-op frame=N wait_replies=M by_op==,...`. The formatting is factored into FormatOpSplit and shared with the exit line. Frames that bought nothing stay quiet, so a steady-state session does not double its log. - Measured on the device (MC 26.2 into a world over TCP, MOBILEGL_PIPE_STATS=1): the steady state is one wait per frame and it is op 9 (Present); the upload-heavy startup frames are `2=50,3=68,47=62` - ResourceCreate / ResourceRespecify / SetTextureParams, with ResourceSubData (48) absent, which is item B working on the wire it was written for. --- MobileGL/MG_Remote/Transport/LinkMetrics.cpp | 43 ++++++++++++++------ 1 file changed, 31 insertions(+), 12 deletions(-) diff --git a/MobileGL/MG_Remote/Transport/LinkMetrics.cpp b/MobileGL/MG_Remote/Transport/LinkMetrics.cpp index a5da6b7d..37b2b4ac 100644 --- a/MobileGL/MG_Remote/Transport/LinkMetrics.cpp +++ b/MobileGL/MG_Remote/Transport/LinkMetrics.cpp @@ -47,6 +47,23 @@ namespace { } return 1ull << 31; } + // The per-op split, formatted into a caller buffer. Raw ids: this file includes only + // and friends, not the op table, and the reader names rows with WireOpName + // (2 ResourceCreate, 3 ResourceRespecify, 47 SetTextureParams, 48 ResourceSubData). + void FormatOpSplit(const Window& w, char* out, std::size_t outSize) { + std::size_t at = 0; + out[0] = '\0'; + for (std::uint32_t op = 1; op < LinkMetricsMaxOps && at + 24 < outSize; ++op) { + const std::uint64_t waits = w.waitRepliesByOp[op]; + if (waits == 0) continue; + const int n = std::snprintf(out + at, outSize - at, "%s%u=%llu", at == 0 ? "" : ",", + static_cast(op), + static_cast(waits)); + if (n < 0 || static_cast(n) >= outSize - at) break; + at += static_cast(n); + } + if (at == 0) std::snprintf(out, outSize, "(none)"); + } void Emit(const char* kind, const Window& w, std::uint64_t wallNs, std::uint64_t cpuNs) { char histogram[768]{}; std::size_t at = 0; @@ -66,6 +83,18 @@ namespace { static_cast(QuantileUpperUs(w, 99)), static_cast(w.stageBytes), static_cast(wallNs), static_cast(cpuNs), histogram); + // AND THE PER-OP SPLIT WITH EVERY FRAME. A whole-session total cannot name the rows behind + // ONE frame, and one frame is the whole shape of this problem: the device run that + // motivated this printed 43,232 of its 43,629 waits in a single atlas frame, and the exit + // summary never appeared at all because a SIGTERM does not take the session's clean stop + // path. Skipped when the frame bought nothing, so a steady-state session stays quiet. + if (w.waitReplies != 0) { + char split[1024]; + FormatOpSplit(w, split, sizeof(split)); + MGLOG_I("P65LinkMetrics kind=frame-op frame=%llu wait_replies=%llu by_op=%s", + static_cast(metrics.frame), + static_cast(w.waitReplies), split); + } } } void LinkMetricsBegin() { @@ -117,19 +146,9 @@ void LinkMetricsEnd() { // written from the one place a client that ends the ordinary way always reaches. `op` is raw - // this file does not include the op table - and the reader names rows with WireOpName. char split[1024]; - std::size_t at = 0; - for (std::uint32_t op = 1; op < LinkMetricsMaxOps && at < sizeof(split); ++op) { - const std::uint64_t waits = metrics.total.waitRepliesByOp[op]; - if (waits == 0) continue; - const int n = std::snprintf(split + at, sizeof(split) - at, "%s%u=%llu", at == 0 ? "" : ",", - static_cast(op), - static_cast(waits)); - if (n < 0 || static_cast(n) >= sizeof(split) - at) break; - at += static_cast(n); - } + FormatOpSplit(metrics.total, split, sizeof(split)); MGLOG_I("P65LinkMetrics kind=per-op wait_replies=%llu by_op=%s", - static_cast(metrics.total.waitReplies), - at == 0 ? "(none)" : split); + static_cast(metrics.total.waitReplies), split); metrics.active = false; } void LinkMetricsServerPresent(std::uint64_t serial) {