Merge pull request #4882 from jroweboy/frametime-logging

Frametime logging for tracking performance over time

src/citra/config.cpp

@@ -234,6 +234,8 @@ void Config::ReadValues() {
     Settings::values.log_filter = sdl2_config->GetString("Miscellaneous", "log_filter", "*:Info");
 
     // Debugging
+    Settings::values.record_frame_times =
+        sdl2_config->GetBoolean("Debugging", "record_frame_times", false);
     Settings::values.use_gdbstub = sdl2_config->GetBoolean("Debugging", "use_gdbstub", false);
     Settings::values.gdbstub_port =
         static_cast<u16>(sdl2_config->GetInteger("Debugging", "gdbstub_port", 24689));

src/citra/default_ini.h

@@ -261,6 +261,8 @@ camera_inner_flip =
 log_filter = *:Info
 
 [Debugging]
+# Record frame time data, can be found in the log directory. Boolean value
+record_frame_times =
 # Port for listening to GDB connections.
 use_gdbstub=false
 gdbstub_port=24689

src/citra_qt/configuration/config.cpp

@@ -255,6 +255,8 @@ void Config::ReadValues() {
     qt_config->endGroup();
 
     qt_config->beginGroup("Debugging");
+    // Intentionally not using the QT default setting as this is intended to be changed in the ini
+    Settings::values.record_frame_times = qt_config->value("record_frame_times", false).toBool();
     Settings::values.use_gdbstub = ReadSetting("use_gdbstub", false).toBool();
     Settings::values.gdbstub_port = ReadSetting("gdbstub_port", 24689).toInt();
 
@@ -544,6 +546,8 @@ void Config::SaveValues() {
     qt_config->endGroup();
 
     qt_config->beginGroup("Debugging");
+    // Intentionally not using the QT default setting as this is intended to be changed in the ini
+    qt_config->setValue("record_frame_times", Settings::values.record_frame_times);
     WriteSetting("use_gdbstub", Settings::values.use_gdbstub, false);
     WriteSetting("gdbstub_port", Settings::values.gdbstub_port, 24689);
 

src/core/core.cpp

@@ -146,6 +146,12 @@ System::ResultStatus System::Load(Frontend::EmuWindow& emu_window, const std::st
         }
     }
     cheat_engine = std::make_unique<Cheats::CheatEngine>(*this);
+    u64 title_id{0};
+    if (app_loader->ReadProgramId(title_id) != Loader::ResultStatus::Success) {
+        LOG_ERROR(Core, "Failed to find title id for ROM (Error {})",
+                  static_cast<u32>(load_result));
+    }
+    perf_stats = std::make_unique<PerfStats>(title_id);
     status = ResultStatus::Success;
     m_emu_window = &emu_window;
     m_filepath = filepath;
@@ -158,7 +164,7 @@ void System::PrepareReschedule() {
 }
 
 PerfStats::Results System::GetAndResetPerfStats() {
-    return perf_stats.GetAndResetStats(timing->GetGlobalTimeUs());
+    return perf_stats->GetAndResetStats(timing->GetGlobalTimeUs());
 }
 
 void System::Reschedule() {
@@ -231,7 +237,7 @@ System::ResultStatus System::Init(Frontend::EmuWindow& emu_window, u32 system_mo
 
     // Reset counters and set time origin to current frame
     GetAndResetPerfStats();
-    perf_stats.BeginSystemFrame();
+    perf_stats->BeginSystemFrame();
 
     return ResultStatus::Success;
 }
@@ -315,6 +321,7 @@ void System::Shutdown() {
     VideoCore::Shutdown();
     HW::Shutdown();
     telemetry_session.reset();
+    perf_stats.reset();
     rpc_server.reset();
     cheat_engine.reset();
     service_manager.reset();

src/core/core.h

@@ -216,7 +216,7 @@ public:
     /// Gets a const reference to the video dumper backend
     const VideoDumper::Backend& VideoDumper() const;
 
-    PerfStats perf_stats;
+    std::unique_ptr<PerfStats> perf_stats = std::make_unique<PerfStats>(0);
     FrameLimiter frame_limiter;
 
     void SetStatus(ResultStatus new_status, const char* details = nullptr) {

src/core/hle/service/gsp/gsp_gpu.cpp

@@ -307,7 +307,7 @@ ResultCode SetBufferSwap(u32 screen_id, const FrameBufferInfo& info) {
 
     if (screen_id == 0) {
         MicroProfileFlip();
-        Core::System::GetInstance().perf_stats.EndGameFrame();
+        Core::System::GetInstance().perf_stats->EndGameFrame();
     }
 
     return RESULT_SUCCESS;

src/core/hle/service/hid/hid.cpp

@@ -228,7 +228,7 @@ void Module::UpdateGyroscopeCallback(u64 userdata, s64 cycles_late) {
 
     Common::Vec3<float> gyro;
     std::tie(std::ignore, gyro) = motion_device->GetStatus();
-    double stretch = system.perf_stats.GetLastFrameTimeScale();
+    double stretch = system.perf_stats->GetLastFrameTimeScale();
     gyro *= gyroscope_coef * static_cast<float>(stretch);
     gyroscope_entry.x = static_cast<s16>(gyro.x);
     gyroscope_entry.y = static_cast<s16>(gyro.y);

src/core/perf_stats.cpp

@@ -4,8 +4,13 @@
 
 #include <algorithm>
 #include <chrono>
+#include <iterator>
 #include <mutex>
+#include <numeric>
 #include <thread>
+#include <fmt/format.h>
+#include <fmt/time.h>
+#include "common/file_util.h"
 #include "core/hw/gpu.h"
 #include "core/perf_stats.h"
 #include "core/settings.h"
@@ -15,8 +20,31 @@ using DoubleSecs = std::chrono::duration<double, std::chrono::seconds::period>;
 using std::chrono::duration_cast;
 using std::chrono::microseconds;
 
+// Purposefully ignore the first five frames, as there's a significant amount of overhead in
+// booting that we shouldn't account for
+constexpr std::size_t IgnoreFrames = 5;
+
 namespace Core {
 
+PerfStats::PerfStats(u64 title_id) : title_id(title_id) {}
+
+PerfStats::~PerfStats() {
+    if (!Settings::values.record_frame_times || title_id == 0) {
+        return;
+    }
+
+    std::time_t t = std::time(nullptr);
+    std::ostringstream stream;
+    std::copy(perf_history.begin() + IgnoreFrames, perf_history.begin() + current_index,
+              std::ostream_iterator<double>(stream, "\n"));
+    std::string path = FileUtil::GetUserPath(FileUtil::UserPath::LogDir);
+    // %F Date format expanded is "%Y-%m-%d"
+    std::string filename =
+        fmt::format("{}/{:%F-%H-%M}_{:016X}.csv", path, *std::localtime(&t), title_id);
+    FileUtil::IOFile file(filename, "w");
+    file.WriteString(stream.str());
+}
+
 void PerfStats::BeginSystemFrame() {
     std::lock_guard lock{object_mutex};
 
@@ -27,7 +55,12 @@ void PerfStats::EndSystemFrame() {
     std::lock_guard lock{object_mutex};
 
     auto frame_end = Clock::now();
-    accumulated_frametime += frame_end - frame_begin;
+    const auto frame_time = frame_end - frame_begin;
+    if (current_index < perf_history.size()) {
+        perf_history[current_index++] =
+            std::chrono::duration<double, std::milli>(frame_time).count();
+    }
+    accumulated_frametime += frame_time;
     system_frames += 1;
 
     previous_frame_length = frame_end - previous_frame_end;
@@ -40,6 +73,15 @@ void PerfStats::EndGameFrame() {
     game_frames += 1;
 }
 
+double PerfStats::GetMeanFrametime() {
+    if (current_index <= IgnoreFrames) {
+        return 0;
+    }
+    double sum = std::accumulate(perf_history.begin() + IgnoreFrames,
+                                 perf_history.begin() + current_index, 0);
+    return sum / (current_index - IgnoreFrames);
+}
+
 PerfStats::Results PerfStats::GetAndResetStats(microseconds current_system_time_us) {
     std::lock_guard lock(object_mutex);
 

src/core/perf_stats.h

@@ -4,6 +4,7 @@
 
 #pragma once
 
+#include <array>
 #include <atomic>
 #include <chrono>
 #include <mutex>
@@ -18,6 +19,10 @@ namespace Core {
  */
 class PerfStats {
 public:
+    explicit PerfStats(u64 title_id);
+
+    ~PerfStats();
+
     using Clock = std::chrono::high_resolution_clock;
 
     struct Results {
@@ -37,6 +42,11 @@ public:
 
     Results GetAndResetStats(std::chrono::microseconds current_system_time_us);
 
+    /**
+     * Returns the Arthimetic Mean of all frametime values stored in the performance history.
+     */
+    double GetMeanFrametime();
+
     /**
      * Gets the ratio between walltime and the emulated time of the previous system frame. This is
      * useful for scaling inputs or outputs moving between the two time domains.
@@ -44,7 +54,15 @@ public:
     double GetLastFrameTimeScale();
 
 private:
-    std::mutex object_mutex;
+    std::mutex object_mutex{};
+
+    /// Title ID for the game that is running. 0 if there is no game running yet
+    u64 title_id{0};
+    /// Current index for writing to the perf_history array
+    std::size_t current_index{0};
+    /// Stores an hour of historical frametime data useful for processing and tracking performance
+    /// regressions with code changes.
+    std::array<double, 216000> perf_history = {};
 
     /// Point when the cumulative counters were reset
     Clock::time_point reset_point = Clock::now();

src/core/settings.h

@@ -187,6 +187,7 @@ struct Values {
     std::array<int, Service::CAM::NumCameras> camera_flip;
 
     // Debugging
+    bool record_frame_times;
     bool use_gdbstub;
     u16 gdbstub_port;
     std::string log_filter;

src/core/telemetry_session.cpp

@@ -99,6 +99,8 @@ TelemetrySession::~TelemetrySession() {
                                 std::chrono::system_clock::now().time_since_epoch())
                                 .count()};
     AddField(Telemetry::FieldType::Session, "Shutdown_Time", shutdown_time);
+    AddField(Telemetry::FieldType::Performance, "Mean_Frametime_MS",
+             Core::System::GetInstance().perf_stats->GetMeanFrametime());
 
 #ifdef ENABLE_WEB_SERVICE
     auto backend = std::make_unique<WebService::TelemetryJson>(Settings::values.web_api_url,

src/video_core/renderer_opengl/renderer_opengl.cpp

@@ -239,7 +239,7 @@ void RendererOpenGL::SwapBuffers() {
     DrawScreens(render_window.GetFramebufferLayout());
     m_current_frame++;
 
-    Core::System::GetInstance().perf_stats.EndSystemFrame();
+    Core::System::GetInstance().perf_stats->EndSystemFrame();
 
     // Swap buffers
     render_window.PollEvents();
@@ -247,7 +247,7 @@ void RendererOpenGL::SwapBuffers() {
 
     Core::System::GetInstance().frame_limiter.DoFrameLimiting(
         Core::System::GetInstance().CoreTiming().GetGlobalTimeUs());
-    Core::System::GetInstance().perf_stats.BeginSystemFrame();
+    Core::System::GetInstance().perf_stats->BeginSystemFrame();
 
     prev_state.Apply();
     RefreshRasterizerSetting();