mirror of
https://github.com/MobileGL-Dev/MobileGL
synced 2026-09-08 20:28:32 +09:00
[Feat] (Trace): record per-frame thread CPU time beside wall time so a paired A/B can be read as CPU cost
- The metric the disaggregation GO/NO-GO hangs on is per-thread CPU p50/p99, and the tree had no first-party collector for it: no CLOCK_THREAD_CPUTIME_ID, no getrusage, no RUSAGE_THREAD, no /proc/self/task anywhere under MobileGL/, tools/, android-plugin/ or scripts/. - The retrace loop is the cheapest honest place to take it. Retrace runs --singlethread and trace_benchmark states that Begin/OnFrameBoundary/End are only ever reached from that one thread, so that thread's CPU time IS the client-side CPU cost: one extra clock_gettime per frame, no root, no profiler, no debuggable build, no sampling - and no instrumentation committed to a hot path inside the library. - The CPU reading is taken before the wall reading at each boundary, so the syscall lands in the wall delta rather than hiding inside the CPU delta. An inflated wall number is visible; a deflated CPU number would not be. - Report::frameCpuMs is the same length as frameMs or it is EMPTY. A clock that started failing mid-run would otherwise be silently re-indexed and put frame N next to frame N+k, and an empty series and a series of zeroes are different claims about the platform. - SummarizeBenchmark is split into SummarizeSeries and reused verbatim for the CPU series rather than duplicated: same tail window, same even-count median rule, same nearest-rank p95, or the delta between the two series stops meaning anything. - benchmark.json gains meanFrameCpuMs / medianFrameCpuMs / p95FrameCpuMs and the WHOLE frameCpuTimesMs[] array beside frameTimesMs[]; result.json and the completion line gain the three headline numbers. p99 therefore needs no device change - it is a host-side reduction over an artefact that already exists, and run_android_retrace_local.py prints p50/p95/p99 off the same trailing window the device summarised. - Pre-flighted on the desktop CLI, which shares the same core: 2-frame run, cpu series aligned with the wall series and strictly below it (wall 1290.787/20.225 ms, cpu 535.271/8.261 ms).
This commit is contained in:
@@ -5,6 +5,16 @@
|
||||
#include <utility>
|
||||
#include <dlfcn.h>
|
||||
|
||||
// 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 <ctime>
|
||||
#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<double> gFrameMs;
|
||||
std::vector<double> 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<double>(now.tv_sec) * 1000.0 + static_cast<double>(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<double, std::milli>(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<double>(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;
|
||||
}
|
||||
|
||||
|
||||
@@ -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<double> 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<double> 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.
|
||||
|
||||
@@ -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<double>& series, std::size_t tail) {
|
||||
SeriesSummary summary;
|
||||
if (series.empty() || tail == 0 || tail > series.size()) {
|
||||
return summary;
|
||||
}
|
||||
std::vector<double> window(series.end() - static_cast<std::ptrdiff_t>(tail), series.end());
|
||||
double sum = 0.0;
|
||||
for (double value : window) {
|
||||
sum += value;
|
||||
}
|
||||
summary.meanMs = sum / static_cast<double>(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::size_t>(std::ceil(0.95 * static_cast<double>(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<std::size_t>(requestedTail), report.frameMs.size());
|
||||
result.benchmarkTailFrames = static_cast<int>(tail);
|
||||
|
||||
std::vector<double> window(report.frameMs.end() - static_cast<std::ptrdiff_t>(tail),
|
||||
report.frameMs.end());
|
||||
double sum = 0.0;
|
||||
for (double frameMs : window) {
|
||||
sum += frameMs;
|
||||
}
|
||||
result.benchmarkMeanMs = sum / static_cast<double>(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::size_t>(std::ceil(0.95 * static_cast<double>(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<bool>(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();
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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):
|
||||
|
||||
Reference in New Issue
Block a user