#pragma once // Performance telemetry for the live client (--perf-log or MT_PERF_LOG=1). // // Every frame the host hands PerfLog the frame's wall times and the renderer's running totals; the // script thread's section times come from platform/EterBase/PerfCounters.h. Every interval (2 s) one CSV // row with the window's per-frame averages is appended to perf-YYYYMMDD-HHMMSS.csv and a short summary // goes to logcat (stderr on desktop). A frame over the hitch threshold additionally writes a "# hitch" // comment line with that frame's own breakdown. // // Files: Android /perf (/sdcard/Android/data//files/perf, pulled with // tools/pull_perf_logs.sh), desktop $MT_PERF_DIR or ./perf. The newest kKeepFiles files are kept. #include "platform/EterBase/PerfCounters.h" #include #include #include #include #include #include #include #include #include #include #include #if defined(__linux__) || defined(__ANDROID__) #include #include #endif #ifdef __ANDROID__ #include #endif namespace native_perf { // Running totals the renderer keeps (VulkanWindow::Timings and its upload counters); PerfLog differences // them itself, so they never need resetting. struct RendererTotals { double sync_ms = 0, fence_ms = 0, prepare_ms = 0, geometry_upload_ms = 0, texture_upload_ms = 0; double submit_ms = 0, present_ms = 0, gpu_ms = 0; std::uint64_t gpu_samples = 0; std::uint64_t uploads = 0, uploaded_bytes = 0, texture_uploads = 0, texture_bytes = 0; // The last frame's counts. std::uint64_t draws = 0, skinned_draws = 0, ui_batches = 0, vertices = 0; const std::string* last_texture = nullptr; // name of the texture uploaded last }; // One battery reading (android_perf::battery_power). power_mw < 0: unknown or on a charger. struct PowerSample { double current_ma = 0, voltage_mv = -1, power_mw = -1; bool plugged = false; }; struct FrameInput { double frame_ms = 0; // whole loop iteration double app_ms = 0; // PythonBoot::UIUpdate: the script thread's Process() plus the baton handoff double host_ms = 0; // cursor sync, UIRender, audio pump double render_ms = 0; // VulkanWindow::render double pace_ms = 0; // sleep of the frame-rate cap (--fps-cap), outside frame_ms RendererTotals renderer; }; class PerfLog { public: static constexpr double kIntervalS = 2.0; static constexpr double kHitchMs = 100.0; static constexpr int kKeepFiles = 10; static constexpr double kPowerSampleS = 0.25; static bool requested_by_env() { const char* env = std::getenv("MT_PERF_LOG"); return env && *env && std::string(env) != "0"; } bool enabled() const { return file_ != nullptr; } // Display refresh rate in Hz as the OS reports it now (Android Display.getRefreshRate), sampled // once per row; -1 when unknown. void set_refresh_rate_source(std::function source) { refresh_rate_ = std::move(source); } // The rate the system actually drives the app at (Android Choreographer); can be a divisor of refresh_hz. void set_render_rate_source(std::function source) { render_rate_ = std::move(source); } // Battery temperature in C (Android: the ACTION_BATTERY_CHANGED sticky intent; sysfs is SELinux-denied). void set_battery_source(std::function source) { battery_ = std::move(source); } // Sampled every kPowerSampleS and averaged over the row: one reading swings with each frame's burst. void set_power_source(std::function source) { power_ = std::move(source); } void set_fps_cap(int cap) { fps_cap_ = cap; } // The frame-rate setting (FrameRateMode.h) and whether the idle rate is in effect, as of the row's end. void set_frame_policy(int mode, bool idle) { fps_mode_ = mode; idle_ = idle; } const std::string& path() const { return path_; } // `context` goes into the file header (device, present mode, MSAA, size...). bool open(const std::string& context) { const std::string dir = directory(); std::error_code ec; std::filesystem::create_directories(dir, ec); prune(dir); char stamp[32]; const std::time_t now = std::time(nullptr); std::tm local{}; localtime_r(&now, &local); std::strftime(stamp, sizeof(stamp), "%Y%m%d-%H%M%S", &local); path_ = dir + "/perf-" + stamp + ".csv"; file_ = std::fopen(path_.c_str(), "w"); if (!file_) { log("perf log: cannot write %s", path_.c_str()); return false; } std::fprintf(file_, "# mt_native_render perf log %s\n# %s\n", stamp, context.c_str()); std::fprintf(file_, "# per-frame averages over each %.0f s window; *_ms game sections run on the script thread " "inside app_ms; py_ms includes update_game/render_game\n", kIntervalS); std::fprintf(file_, "t_s,map,actors,frames,fps,refresh_hz,render_hz,fps_cap,frame_ms,frame_p95_ms,frame_max_ms,jank33,jank50," "app_ms,process_ms,handoff_ms,net_ms,camera_ms,ui_update_ms,update_game_ms,render_begin_ms,ui_render_ms," "render_game_ms,shadow_raster_ms,py_ms,py_calls,py_missing,host_ms,render_ms,pace_ms,sync_ms,fence_ms," "prepare_ms,geo_upload_ms,tex_upload_ms," "submit_ms,present_ms,gpu_ms,draws,skinned_draws,ui_batches,vertices,geo_uploads,geo_kb,tex_uploads,tex_kb," "script_cpu,main_cpu,cpu_mhz,cpu_max_mhz,thermal,batt_c,rss_mb,batt_ma,batt_mv,power_mw,plugged,fps_mode,idle," "last_texture\n"); std::fflush(file_); MtPerf::Enabled() = true; MtPerf::Take(); start_ = window_start_ = std::chrono::steady_clock::now(); log("perf log: %s", path_.c_str()); return true; } ~PerfLog() { if (file_) std::fclose(file_); MtPerf::Enabled() = false; } // Call once per frame. `map_name` is only asked for when a row is written. template void frame(const FrameInput& in, MapName&& map_name) { if (!file_) return; const MtPerf::SCounters game = MtPerf::Take(); const RendererTotals& r = in.renderer; const RendererTotals& p = have_prev_ ? prev_ : r; Window f; f.frames = 1; f.frame_ms = in.frame_ms; f.app_ms = in.app_ms; f.host_ms = in.host_ms; f.render_ms = in.render_ms; f.pace_ms = in.pace_ms; for (int i = 0; i < MtPerf::SECTION_COUNT; ++i) f.game_ms[i] = game.ms[i]; f.py_calls = game.calls[MtPerf::SECTION_PYTHON]; f.py_missing = game.pyMissing; f.sync_ms = r.sync_ms - p.sync_ms; f.fence_ms = r.fence_ms - p.fence_ms; f.prepare_ms = r.prepare_ms - p.prepare_ms; f.geo_upload_ms = r.geometry_upload_ms - p.geometry_upload_ms; f.tex_upload_ms = r.texture_upload_ms - p.texture_upload_ms; f.submit_ms = r.submit_ms - p.submit_ms; f.present_ms = r.present_ms - p.present_ms; f.gpu_ms = r.gpu_ms - p.gpu_ms; f.gpu_samples = r.gpu_samples - p.gpu_samples; f.geo_uploads = r.uploads - p.uploads; f.geo_bytes = r.uploaded_bytes - p.uploaded_bytes; f.tex_uploads = r.texture_uploads - p.texture_uploads; f.tex_bytes = r.texture_bytes - p.texture_bytes; prev_ = r; have_prev_ = true; if (in.frame_ms >= kHitchMs) write_hitch(f, game); window_.add(f); frame_times_.push_back(in.frame_ms); draws_ = r.draws; skinned_draws_ = r.skinned_draws; ui_batches_ = r.ui_batches; vertices_ = r.vertices; if (f.tex_uploads && r.last_texture) last_texture_ = *r.last_texture; actors_ = game.actorCount; script_cpu_ = game.scriptCpu; const auto now = std::chrono::steady_clock::now(); if (power_ && std::chrono::duration(now - power_sampled_at_).count() >= kPowerSampleS) { power_sampled_at_ = now; const PowerSample sample = power_(); power_sum_.current_ma += sample.current_ma; power_sum_.voltage_mv += sample.voltage_mv; if (sample.power_mw >= 0) { power_sum_.power_mw += sample.power_mw; ++power_valid_; } power_sum_.plugged = power_sum_.plugged || sample.plugged; ++power_samples_; } const double elapsed = std::chrono::duration(now - window_start_).count(); if (elapsed < kIntervalS) return; write_row(elapsed, map_name()); power_sum_ = {}; power_sum_.voltage_mv = 0; power_sum_.power_mw = 0; power_samples_ = power_valid_ = 0; window_ = {}; frame_times_.clear(); window_start_ = now; } private: struct Window { std::uint64_t frames = 0; double frame_ms = 0, app_ms = 0, host_ms = 0, render_ms = 0, pace_ms = 0; double game_ms[MtPerf::SECTION_COUNT] = {}; std::uint64_t py_calls = 0, py_missing = 0; double sync_ms = 0, fence_ms = 0, prepare_ms = 0, geo_upload_ms = 0, tex_upload_ms = 0, submit_ms = 0; double present_ms = 0, gpu_ms = 0; std::uint64_t gpu_samples = 0; std::uint64_t geo_uploads = 0, geo_bytes = 0, tex_uploads = 0, tex_bytes = 0; void add(const Window& o) { frames += o.frames; frame_ms += o.frame_ms; app_ms += o.app_ms; host_ms += o.host_ms; render_ms += o.render_ms; pace_ms += o.pace_ms; fence_ms += o.fence_ms; for (int i = 0; i < MtPerf::SECTION_COUNT; ++i) game_ms[i] += o.game_ms[i]; py_calls += o.py_calls; py_missing += o.py_missing; sync_ms += o.sync_ms; prepare_ms += o.prepare_ms; geo_upload_ms += o.geo_upload_ms; tex_upload_ms += o.tex_upload_ms; submit_ms += o.submit_ms; present_ms += o.present_ms; gpu_ms += o.gpu_ms; gpu_samples += o.gpu_samples; geo_uploads += o.geo_uploads; geo_bytes += o.geo_bytes; tex_uploads += o.tex_uploads; tex_bytes += o.tex_bytes; } }; static std::string directory() { if (const char* env = std::getenv("MT_PERF_DIR"); env && *env) return env; #ifdef __ANDROID__ if (const char* ext = SDL_GetAndroidExternalStoragePath(); ext && *ext) return std::string(ext) + "/perf"; if (const char* internal = SDL_GetAndroidInternalStoragePath(); internal && *internal) return std::string(internal) + "/perf"; #endif return "perf"; } static void prune(const std::string& dir) { std::error_code ec; std::vector files; for (const auto& entry : std::filesystem::directory_iterator(dir, ec)) { const std::string name = entry.path().filename().string(); if (name.rfind("perf-", 0) == 0 && entry.path().extension() == ".csv") files.push_back(entry.path()); } std::sort(files.begin(), files.end()); // Leave room for the file about to be opened. for (std::size_t i = 0; i + kKeepFiles <= files.size(); ++i) std::filesystem::remove(files[i], ec); } template static void log(const char* format, Args... args) { #ifdef __ANDROID__ SDL_Log(format, args...); #else std::fprintf(stderr, format, args...); std::fputc('\n', stderr); #endif } static int current_cpu() { #if defined(__linux__) || defined(__ANDROID__) return sched_getcpu(); #else return -1; #endif } static long read_long(const char* path) { std::FILE* f = std::fopen(path, "r"); if (!f) return -1; long value = -1; if (std::fscanf(f, "%ld", &value) != 1) value = -1; std::fclose(f); return value; } // Current clock of every CPU in MHz, "cpu0/cpu1/...", or "" where sysfs is closed. static std::string cpu_mhz() { std::string out; #if defined(__linux__) || defined(__ANDROID__) for (int cpu = 0; cpu < 16; ++cpu) { char path[96]; std::snprintf(path, sizeof(path), "/sys/devices/system/cpu/cpu%d/cpufreq/scaling_cur_freq", cpu); const long khz = read_long(path); if (khz < 0) { if (cpu >= 8 || access(path, F_OK) != 0) break; continue; } if (!out.empty()) out += '/'; out += std::to_string(khz / 1000); } #endif return out; } // Each cpufreq policy's current ceiling (scaling_max_freq): the vendor's thermal throttling shows up // here long before AThermal reports anything. static std::string cpu_max_mhz() { std::string out; #if defined(__linux__) || defined(__ANDROID__) for (int policy = 0; policy < 16; ++policy) { char path[96]; std::snprintf(path, sizeof(path), "/sys/devices/system/cpu/cpufreq/policy%d/scaling_max_freq", policy); const long khz = read_long(path); if (khz < 0) continue; if (!out.empty()) out += '/'; out += std::to_string(khz / 1000); } #endif return out; } // AThermal_getCurrentThermalStatus (API 30+, looked up at run time since minSdk is lower): // 0 none, 1 light, 2 moderate, 3 severe, 4 critical, 5 emergency, 6 shutdown; -1 unknown. static int thermal_status() { #ifdef __ANDROID__ using Acquire = void* (*)(); using Status = int (*)(void*); static void* manager = nullptr; static Status status = nullptr; static bool looked_up = false; if (!looked_up) { looked_up = true; if (void* lib = dlopen("libandroid.so", RTLD_NOW)) { const auto acquire = reinterpret_cast(dlsym(lib, "AThermal_acquireManager")); status = reinterpret_cast(dlsym(lib, "AThermal_getCurrentThermalStatus")); if (acquire && status) manager = acquire(); } } if (manager && status) return status(manager); #endif return -1; } double battery_celsius() const { if (battery_) return battery_(); #if defined(__linux__) || defined(__ANDROID__) const long tenths = read_long("/sys/class/power_supply/battery/temp"); if (tenths > 0) return double(tenths) / 10.0; // -1: unreadable (SELinux on most phones) #endif return -1.0; } static double rss_mb() { #if defined(__linux__) || defined(__ANDROID__) std::FILE* f = std::fopen("/proc/self/statm", "r"); if (!f) return -1.0; long pages = 0, resident = 0; const int read = std::fscanf(f, "%ld %ld", &pages, &resident); std::fclose(f); if (read == 2) return double(resident) * double(sysconf(_SC_PAGESIZE)) / (1024.0 * 1024.0); #endif return -1.0; } static std::string csv_field(std::string text) { for (char& c : text) if (c == ',' || c == '\n' || c == '\r') c = ' '; return text; } void write_row(double elapsed_s, const std::string& map) { const Window& w = window_; if (!w.frames) return; const double n = double(w.frames); std::vector sorted = frame_times_; std::sort(sorted.begin(), sorted.end()); const double p95 = sorted[std::min(sorted.size() - 1, std::size_t(0.95 * double(sorted.size())))]; int jank33 = 0, jank50 = 0; for (double ms : frame_times_) { jank33 += ms > 33.4; jank50 += ms > 50.0; } const auto g = [&](MtPerf::ESection s) { return w.game_ms[s] / n; }; const double fps = n / elapsed_s; const double gpu = w.gpu_samples ? w.gpu_ms / double(w.gpu_samples) : 0.0; const double t = std::chrono::duration(std::chrono::steady_clock::now() - start_).count(); const std::string mhz = cpu_mhz(); const std::string max_mhz = cpu_max_mhz(); const int thermal = thermal_status(); const double batt = battery_celsius(); const double rss = rss_mb(); const int main_cpu = current_cpu(); const double refresh = refresh_rate_ ? refresh_rate_() : -1.0; const double render_rate = render_rate_ ? render_rate_() : -1.0; const double ns = double(power_samples_); const double batt_ma = power_samples_ ? power_sum_.current_ma / ns : -1.0; const double batt_mv = power_samples_ ? power_sum_.voltage_mv / ns : -1.0; // Only when every sample of the row was off the charger. const double power_mw = power_valid_ && power_valid_ == power_samples_ ? power_sum_.power_mw / ns : -1.0; std::fprintf(file_, "%.1f,%s,%d,%llu,%.1f,%.1f,%.1f,%d,%.2f,%.2f,%.2f,%d,%d," "%.2f,%.2f,%.2f,%.3f,%.3f,%.3f,%.3f,%.3f,%.3f," "%.3f,%.3f,%.3f,%.1f,%.1f,%.3f,%.2f,%.2f,%.2f,%.2f," "%.2f,%.3f,%.3f," "%.3f,%.3f,%.2f,%llu,%llu,%llu,%llu,%.2f,%.1f,%.2f,%.1f," "%d,%d,%s,%s,%d,%.1f,%.0f,%.0f,%.0f,%.0f,%d,%d,%d,%s\n", t, csv_field(map).c_str(), actors_, (unsigned long long)w.frames, fps, refresh, render_rate, fps_cap_, w.frame_ms / n, p95, sorted.back(), jank33, jank50, w.app_ms / n, g(MtPerf::SECTION_PROCESS), (w.app_ms - w.game_ms[MtPerf::SECTION_PROCESS]) / n, g(MtPerf::SECTION_NETWORK), g(MtPerf::SECTION_CAMERA), g(MtPerf::SECTION_UI_UPDATE), g(MtPerf::SECTION_UPDATE_GAME), g(MtPerf::SECTION_RENDER_BEGIN), g(MtPerf::SECTION_UI_RENDER), g(MtPerf::SECTION_RENDER_GAME), g(MtPerf::SECTION_SHADOW_RASTER), g(MtPerf::SECTION_PYTHON), double(w.py_calls) / n, double(w.py_missing) / n, w.host_ms / n, w.render_ms / n, w.pace_ms / n, w.sync_ms / n, w.fence_ms / n, w.prepare_ms / n, w.geo_upload_ms / n, w.tex_upload_ms / n, w.submit_ms / n, w.present_ms / n, gpu, (unsigned long long)draws_, (unsigned long long)skinned_draws_, (unsigned long long)ui_batches_, (unsigned long long)vertices_, double(w.geo_uploads) / n, double(w.geo_bytes) / 1024.0 / n, double(w.tex_uploads) / n, double(w.tex_bytes) / 1024.0 / n, script_cpu_, main_cpu, mhz.c_str(), max_mhz.c_str(), thermal, batt, rss, batt_ma, batt_mv, power_mw, int(power_sum_.plugged), fps_mode_, int(idle_), csv_field(last_texture_).c_str()); std::fflush(file_); if (!w.tex_uploads) last_texture_.clear(); log("perf fps=%.1f @%.0fHz/%.0f cap=%d frame=%.1f/p95 %.1f/max %.1f jank33=%d | app=%.1f (upd=%.1f rnd=%.1f " "shadow=%.1f py=%.1f) | render=%.1f (sync=%.1f fence=%.1f prep=%.1f up=%.1f/%.1f) pace=%.1f gpu=%.1f | " "draws=%llu actors=%d map=%s thermal=%d batt=%.1f cpu=%s max=%s tex_uploads=%.2f | pwr=%.0fmW %.0fmA%s mode=%d%s " "last_tex=%s", fps, refresh, render_rate, fps_cap_, w.frame_ms / n, p95, sorted.back(), jank33, w.app_ms / n, g(MtPerf::SECTION_UPDATE_GAME), g(MtPerf::SECTION_RENDER_GAME), g(MtPerf::SECTION_SHADOW_RASTER), g(MtPerf::SECTION_PYTHON), w.render_ms / n, w.sync_ms / n, w.fence_ms / n, w.prepare_ms / n, w.geo_upload_ms / n, w.tex_upload_ms / n, w.pace_ms / n, gpu, (unsigned long long)draws_, actors_, map.c_str(), thermal, batt, mhz.c_str(), max_mhz.c_str(), double(w.tex_uploads) / n, power_mw, batt_ma, power_sum_.plugged ? " plugged" : "", fps_mode_, idle_ ? " idle" : "", last_texture_.c_str()); } void write_hitch(const Window& f, const MtPerf::SCounters& game) { const double t = std::chrono::duration(std::chrono::steady_clock::now() - start_).count(); std::fprintf(file_, "# hitch t=%.2f frame=%.1f app=%.1f process=%.1f net=%.1f camera=%.1f ui_update=%.1f update_game=%.1f " "ui_render=%.1f render_game=%.1f shadow=%.1f py=%.1f host=%.1f render=%.1f sync=%.1f prepare=%.1f geo_upload=%.1f(%llu) " "tex_upload=%.1f(%llu, %.0f KB) submit=%.1f present=%.1f\n", t, f.frame_ms, f.app_ms, game.ms[MtPerf::SECTION_PROCESS], game.ms[MtPerf::SECTION_NETWORK], game.ms[MtPerf::SECTION_CAMERA], game.ms[MtPerf::SECTION_UI_UPDATE], game.ms[MtPerf::SECTION_UPDATE_GAME], game.ms[MtPerf::SECTION_UI_RENDER], game.ms[MtPerf::SECTION_RENDER_GAME], game.ms[MtPerf::SECTION_SHADOW_RASTER], game.ms[MtPerf::SECTION_PYTHON], f.host_ms, f.render_ms, f.sync_ms, f.prepare_ms, f.geo_upload_ms, (unsigned long long)f.geo_uploads, f.tex_upload_ms, (unsigned long long)f.tex_uploads, double(f.tex_bytes) / 1024.0, f.submit_ms, f.present_ms); } std::FILE* file_ = nullptr; std::string path_; std::chrono::steady_clock::time_point start_{}, window_start_{}; Window window_; std::vector frame_times_; RendererTotals prev_; bool have_prev_ = false; std::uint64_t draws_ = 0, skinned_draws_ = 0, ui_batches_ = 0, vertices_ = 0; int actors_ = 0, script_cpu_ = -1; int fps_cap_ = 0; std::function refresh_rate_; std::function render_rate_; std::function battery_; std::function power_; std::chrono::steady_clock::time_point power_sampled_at_{}; PowerSample power_sum_{0, 0, 0, false}; int power_samples_ = 0, power_valid_ = 0; int fps_mode_ = -1; bool idle_ = false; std::string last_texture_; }; } // namespace native_perf