diff --git a/android-plugin/app/src/trace/cpp/trace_benchmark.cpp b/android-plugin/app/src/trace/cpp/trace_benchmark.cpp index 669023ef..fb67d0aa 100644 --- a/android-plugin/app/src/trace/cpp/trace_benchmark.cpp +++ b/android-plugin/app/src/trace/cpp/trace_benchmark.cpp @@ -5,6 +5,16 @@ #include #include +// CLOCK_THREAD_CPUTIME_ID is POSIX and present on Linux and on every Android API this replays +// on; the guard exists so the desktop CLI still builds where it is not, and so that "no CPU +// series" is a compile-time fact rather than a silently-zero column. +#if defined(__unix__) || defined(__linux__) || defined(__ANDROID__) || defined(__APPLE__) +#include +#define MOBILEGL_TRACE_HAVE_THREAD_CPU_CLOCK 1 +#else +#define MOBILEGL_TRACE_HAVE_THREAD_CPU_CLOCK 0 +#endif + namespace mobilegl_trace { namespace benchmark { namespace { @@ -21,6 +31,23 @@ GlFinishFn gGlFinish = nullptr; Clock::time_point gStart; Clock::time_point gLastBoundary; std::vector gFrameMs; +std::vector gFrameCpuMs; +double gLastBoundaryCpuMs = 0.0; + +// Milliseconds of CPU time this thread has consumed, or -1 where the clock does not exist. +// Negative once means negative always, so End() reports an EMPTY cpu series rather than a +// column of zeroes. +double ThreadCpuMs() { +#if MOBILEGL_TRACE_HAVE_THREAD_CPU_CLOCK + struct timespec now; + if (clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now) != 0) { + return -1.0; + } + return static_cast(now.tv_sec) * 1000.0 + static_cast(now.tv_nsec) / 1e6; +#else + return -1.0; +#endif +} // Same resolution order the glws layers use for MobileGL's entry points: the replay driver // already dlopen()ed the library with RTLD_GLOBAL before retrace started, so RTLD_NOLOAD @@ -49,6 +76,9 @@ GlFinishFn ResolveGlFinish() { void Begin(bool finishEachFrame) { gFrameMs.clear(); gFrameMs.reserve(kFrameReserve); + gFrameCpuMs.clear(); + gFrameCpuMs.reserve(kFrameReserve); + gLastBoundaryCpuMs = ThreadCpuMs(); gFinishEachFrame = finishEachFrame; gResolvedGlFinish = false; gGlFinish = nullptr; @@ -72,8 +102,16 @@ void OnFrameBoundary() { gGlFinish(); } } + // The CPU reading is taken FIRST and the wall reading second, so the wall delta contains the + // cost of the extra syscall rather than the CPU delta hiding inside it: an inflated wall + // number is visible, a deflated CPU number is not. + const double cpuNow = ThreadCpuMs(); const Clock::time_point now = Clock::now(); gFrameMs.push_back(std::chrono::duration(now - gLastBoundary).count()); + if (cpuNow >= 0.0 && gLastBoundaryCpuMs >= 0.0) { + gFrameCpuMs.push_back(cpuNow - gLastBoundaryCpuMs); + } + gLastBoundaryCpuMs = cpuNow; gLastBoundary = now; } @@ -87,6 +125,13 @@ Report End() { report.totalSeconds = std::chrono::duration(Clock::now() - gStart).count(); report.frameMs = std::move(gFrameMs); gFrameMs.clear(); + // Only hand back a CPU series that lines up frame-for-frame with the wall series. A short + // one would be a clock that started failing mid-run, and silently re-indexing it against + // frameMs would put frame N's wall time next to frame N+k's CPU time. + if (gFrameCpuMs.size() == report.frameMs.size()) { + report.frameCpuMs = std::move(gFrameCpuMs); + } + gFrameCpuMs.clear(); return report; } diff --git a/android-plugin/app/src/trace/cpp/trace_benchmark.hpp b/android-plugin/app/src/trace/cpp/trace_benchmark.hpp index 39410e70..9672a885 100644 --- a/android-plugin/app/src/trace/cpp/trace_benchmark.hpp +++ b/android-plugin/app/src/trace/cpp/trace_benchmark.hpp @@ -11,6 +11,23 @@ namespace benchmark { // // Retrace runs --singlethread, so all of this is deliberately plain globals: Begin(), // OnFrameBoundary() and End() are only ever reached from the one retrace thread. +// +// That single-threadedness is also what makes the SECOND series below sound. Beside the wall +// clock, every frame boundary reads CLOCK_THREAD_CPUTIME_ID - the CPU time consumed by THIS +// thread - and because the retrace loop is the only thread that ever gets here, that number is +// the client-side CPU cost of the frame and nothing else. It is the metric the disaggregation +// GO/NO-GO hangs on (ROADMAP.md: per-thread CPU p50/p99, not wall time), and before P2 the tree +// had no first-party collector for it at all: no CLOCK_THREAD_CPUTIME_ID, no getrusage, no +// /proc/self/task anywhere under MobileGL/, tools/, android-plugin/ or scripts/. Collecting it +// here costs one extra clock_gettime per frame, needs no root, no profiler, no debuggable build +// and no sampling, and - unlike a timer inside the library - commits no instrumentation to a hot +// path. +// +// Wall time and CPU time answer different questions and both are kept: with --benchmark-no-finish +// the wall series still contains everything the thread WAITED for (driver submit, the compositor, +// a fence), while the CPU series contains only what it EXECUTED. A change that moves work off the +// retrace thread shows up as the two series diverging, which is exactly the confusion a single +// number invites. // Arms timing for the retrace that is about to run. // @@ -32,6 +49,12 @@ void OnFrameBoundary(); struct Report { // Wall time of every completed frame, in milliseconds. std::vector frameMs; + // Thread CPU time of every completed frame, in milliseconds, in the SAME ORDER and with the + // same length as frameMs - the two are pushed together at one frame boundary, so index i is + // one frame in both. Empty when the platform has no CLOCK_THREAD_CPUTIME_ID, which is the + // one honest reading of "this run collected no CPU series"; a vector of zeroes would be + // indistinguishable from a frame that genuinely burned no CPU. + std::vector frameCpuMs; // Begin() to End(), in seconds. Covers trace parsing and the leading partial frame too, // which is why it is reported next to the per-frame statistics rather than derived from // them. diff --git a/android-plugin/app/src/trace/cpp/trace_replay_core.cpp b/android-plugin/app/src/trace/cpp/trace_replay_core.cpp index f36d9b40..cce92e55 100644 --- a/android-plugin/app/src/trace/cpp/trace_replay_core.cpp +++ b/android-plugin/app/src/trace/cpp/trace_replay_core.cpp @@ -827,6 +827,42 @@ std::string BenchmarkResultPath(const Request& request) { : request.benchmarkResultPath; } +// mean / median / nearest-rank p95 over the trailing `tail` entries of one per-frame series. +// +// Split out of SummarizeBenchmark rather than duplicated, because the wall series and the CPU +// series have to be reduced IDENTICALLY or the delta between them stops meaning anything: the same +// tail window, the same median rule for an even count, the same nearest-rank p95 (so the reported +// value is always an observed frame, never an interpolation). +struct SeriesSummary { + double meanMs = -1.0; + double medianMs = -1.0; + double p95Ms = -1.0; +}; + +SeriesSummary SummarizeSeries(const std::vector& series, std::size_t tail) { + SeriesSummary summary; + if (series.empty() || tail == 0 || tail > series.size()) { + return summary; + } + std::vector window(series.end() - static_cast(tail), series.end()); + double sum = 0.0; + for (double value : window) { + sum += value; + } + summary.meanMs = sum / static_cast(tail); + + std::sort(window.begin(), window.end()); + summary.medianMs = + (tail % 2 == 1) ? window[tail / 2] : 0.5 * (window[tail / 2 - 1] + window[tail / 2]); + // Nearest-rank p95, so the reported value is always an observed frame time. + std::size_t rank = static_cast(std::ceil(0.95 * static_cast(tail))); + if (rank == 0) { + rank = 1; + } + summary.p95Ms = window[rank - 1]; + return summary; +} + // Folds the recorded frame times into the headline numbers. Everything but totalSeconds and // the frame count is computed over the trailing benchmarkTailFrames frames only. void SummarizeBenchmark(const Request& request, const benchmark::Report& report, Result& result) { @@ -843,25 +879,20 @@ void SummarizeBenchmark(const Request& request, const benchmark::Report& report, std::min(static_cast(requestedTail), report.frameMs.size()); result.benchmarkTailFrames = static_cast(tail); - std::vector window(report.frameMs.end() - static_cast(tail), - report.frameMs.end()); - double sum = 0.0; - for (double frameMs : window) { - sum += frameMs; - } - result.benchmarkMeanMs = sum / static_cast(tail); - - std::sort(window.begin(), window.end()); - result.benchmarkMedianMs = (tail % 2 == 1) - ? window[tail / 2] - : 0.5 * (window[tail / 2 - 1] + window[tail / 2]); - // Nearest-rank p95, so the reported value is always an observed frame time. - std::size_t rank = static_cast(std::ceil(0.95 * static_cast(tail))); - if (rank == 0) { - rank = 1; - } - result.benchmarkP95Ms = window[rank - 1]; + const SeriesSummary wall = SummarizeSeries(report.frameMs, tail); + result.benchmarkMeanMs = wall.meanMs; + result.benchmarkMedianMs = wall.medianMs; + result.benchmarkP95Ms = wall.p95Ms; result.benchmarkFps = result.benchmarkMeanMs > 0.0 ? 1000.0 / result.benchmarkMeanMs : -1.0; + + // The CPU series is the same length as the wall series or it is empty (trace_benchmark.cpp + // refuses to hand back a partial one), so the same tail window applies unchanged. When it is + // empty the three CPU fields stay at -1, which is what the platform having no per-thread CPU + // clock looks like - and is not the same reading as a genuine 0.0. + const SeriesSummary cpu = SummarizeSeries(report.frameCpuMs, tail); + result.benchmarkMeanCpuMs = cpu.meanMs; + result.benchmarkMedianCpuMs = cpu.medianMs; + result.benchmarkP95CpuMs = cpu.p95Ms; } bool WriteBenchmarkJson(const Request& request, @@ -886,6 +917,9 @@ bool WriteBenchmarkJson(const Request& request, file << " \"medianFrameMs\": " << result.benchmarkMedianMs << ",\n"; file << " \"p95FrameMs\": " << result.benchmarkP95Ms << ",\n"; file << " \"fps\": " << result.benchmarkFps << ",\n"; + file << " \"meanFrameCpuMs\": " << result.benchmarkMeanCpuMs << ",\n"; + file << " \"medianFrameCpuMs\": " << result.benchmarkMedianCpuMs << ",\n"; + file << " \"p95FrameCpuMs\": " << result.benchmarkP95CpuMs << ",\n"; file << " \"frameTimesMs\": ["; for (std::size_t i = 0; i < report.frameMs.size(); ++i) { if (i > 0) { @@ -893,6 +927,18 @@ bool WriteBenchmarkJson(const Request& request, } file << report.frameMs[i]; } + file << "],\n"; + // The WHOLE per-frame CPU array, beside the whole per-frame wall array. This is what makes + // p99 - and any other percentile a later question wants - a host-side computation over an + // artefact that already exists, instead of a device change. Empty when this platform has no + // per-thread CPU clock; an empty array and an array of zeroes are different claims. + file << " \"frameCpuTimesMs\": ["; + for (std::size_t i = 0; i < report.frameCpuMs.size(); ++i) { + if (i > 0) { + file << ", "; + } + file << report.frameCpuMs[i]; + } file << "]\n"; file << "}\n"; return static_cast(file); @@ -965,6 +1011,9 @@ bool WriteResultJson(const Request& request, const Result& result) { file << " \"benchmarkMeanFrameMs\": " << result.benchmarkMeanMs << ",\n"; file << " \"benchmarkMedianFrameMs\": " << result.benchmarkMedianMs << ",\n"; file << " \"benchmarkP95FrameMs\": " << result.benchmarkP95Ms << ",\n"; + file << " \"benchmarkMeanFrameCpuMs\": " << result.benchmarkMeanCpuMs << ",\n"; + file << " \"benchmarkMedianFrameCpuMs\": " << result.benchmarkMedianCpuMs << ",\n"; + file << " \"benchmarkP95FrameCpuMs\": " << result.benchmarkP95CpuMs << ",\n"; file << " \"benchmarkFps\": " << result.benchmarkFps << "\n"; } else { file << "\n"; @@ -1045,6 +1094,9 @@ Result RunTraceReplay(const Request& request) { << ", meanMs=" << result.benchmarkMeanMs << ", medianMs=" << result.benchmarkMedianMs << ", p95Ms=" << result.benchmarkP95Ms + << ", meanCpuMs=" << result.benchmarkMeanCpuMs + << ", medianCpuMs=" << result.benchmarkMedianCpuMs + << ", p95CpuMs=" << result.benchmarkP95CpuMs << ", fps=" << result.benchmarkFps << ", benchmarkResultPath=" << result.benchmarkResultPath; result.message = message.str(); diff --git a/android-plugin/app/src/trace/cpp/trace_replay_core.hpp b/android-plugin/app/src/trace/cpp/trace_replay_core.hpp index 0f95c039..0cbdca91 100644 --- a/android-plugin/app/src/trace/cpp/trace_replay_core.hpp +++ b/android-plugin/app/src/trace/cpp/trace_replay_core.hpp @@ -90,6 +90,17 @@ struct Result { double benchmarkMedianMs = -1.0; double benchmarkP95Ms = -1.0; double benchmarkFps = -1.0; + // The same three statistics over the retrace thread's CPU time instead of wall time, and the + // reason the CPU series is collected at all: the disaggregation GO/NO-GO is a per-thread CPU + // question, not a frame-rate one. Left at -1 when the platform has no per-thread CPU clock, + // which is distinguishable from a real 0.0. + // + // Only mean/median/p95 stop here. p99 - which is half of what the paired A/B publishes - is + // computed HOST-SIDE from the full frameCpuTimesMs[] array in benchmark.json, so asking for a + // different percentile later needs no device change and no reflash. + double benchmarkMeanCpuMs = -1.0; + double benchmarkMedianCpuMs = -1.0; + double benchmarkP95CpuMs = -1.0; }; Result RunTraceReplay(const Request& request); diff --git a/tools/trace_replay/run_android_retrace_local.py b/tools/trace_replay/run_android_retrace_local.py index 30337748..22c15c7d 100644 --- a/tools/trace_replay/run_android_retrace_local.py +++ b/tools/trace_replay/run_android_retrace_local.py @@ -1,6 +1,7 @@ #!/usr/bin/env python3 import argparse import json +import math import shutil import subprocess import sys @@ -225,8 +226,42 @@ def read_benchmark(case, backend, run_index): return report +def nearest_rank_percentile(values, fraction): + """Nearest-rank percentile, the same rule SummarizeSeries uses on the device. + + Nearest rank rather than an interpolating percentile so that every number printed here is a + frame that was actually observed, and so that a p95 computed on this side agrees exactly with + the p95 the device reported for the same window. + """ + if not values: + return -1.0 + ordered = sorted(values) + rank = math.ceil(fraction * len(ordered)) + if rank < 1: + rank = 1 + return ordered[rank - 1] + + +def cpu_tail(report): + """The trailing window of the per-frame CPU series, or [] when the run collected none. + + benchmark.json carries the WHOLE frameCpuTimesMs[] array precisely so that percentiles the + device does not compute - p50 and p99, which are what the paired A/B publishes - are a + host-side reduction over an artefact that already exists. The window is the same trailing + tailFrames the device summarised, so the numbers below sit beside the device's own without + being about a different set of frames. + """ + series = report.get("frameCpuTimesMs") or [] + if not series: + return [] + tail = report.get("tailFrames", 0) + if not isinstance(tail, int) or tail <= 0 or tail > len(series): + tail = len(series) + return series[-tail:] + + def format_benchmark(report): - return ( + line = ( f"frames={report.get('totalFrames', -1)}" f" total={report.get('totalSeconds', -1):.1f}s" f" tail={report.get('tailFrames', -1)}" @@ -235,6 +270,22 @@ def format_benchmark(report): f" p95={report.get('p95FrameMs', -1):.3f}ms" f" fps={report.get('fps', -1):.1f}" ) + # The CPU half. It is what the disaggregation A/B is actually read on - wall time under + # --benchmark-no-finish still contains everything the retrace thread waited for - so it is + # printed on the same line rather than left to whoever remembers to open the JSON. + window = cpu_tail(report) + if window: + line += ( + f" | cpu mean={report.get('meanFrameCpuMs', -1):.3f}ms" + f" p50={nearest_rank_percentile(window, 0.50):.3f}ms" + f" p95={report.get('p95FrameCpuMs', -1):.3f}ms" + f" p99={nearest_rank_percentile(window, 0.99):.3f}ms" + ) + else: + # Not "cpu=0": a run with no per-thread CPU clock and a run that burned no CPU are + # different claims, and only one of them is possible. + line += " | cpu unavailable (no per-thread CPU clock in this run)" + return line def run_benchmark_case(case, backend, args):