mtgodot-poc/native_render/perf_log.h

#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 <external files dir>/perf (/sdcard/Android/data/<package>/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 <SDL3/SDL.h>

#include <algorithm>
#include <chrono>
#include <cstdint>
#include <cstdio>
#include <cstdlib>
#include <ctime>
#include <filesystem>
#include <functional>
#include <string>
#include <vector>

#if defined(__linux__) || defined(__ANDROID__)
#include <sched.h>
#include <unistd.h>
#endif
#ifdef __ANDROID__
#include <dlfcn.h>
#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<double()> 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<double()> 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<double()> 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<PowerSample()> 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 <typename MapName>
    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<double>(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<double>(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<std::filesystem::path> 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 <typename... Args>
    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<Acquire>(dlsym(lib, "AThermal_acquireManager"));
                status = reinterpret_cast<Status>(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<double> 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<double>(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<double>(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<double> 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<double()> refresh_rate_;
    std::function<double()> render_rate_;
    std::function<double()> battery_;
    std::function<PowerSample()> 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