Add frametime logging for tracking performance over time

Co-Authored-By: jroweboy <jroweboy@gmail.com>

src/core/core.cpp

@@ -160,10 +160,6 @@ struct System::Impl {
 
         LOG_DEBUG(Core, "Initialized OK");
 
-        // Reset counters and set time origin to current frame
-        GetAndResetPerfStats();
-        perf_stats.BeginSystemFrame();
-
         return ResultStatus::Success;
     }
 
@@ -206,6 +202,16 @@ struct System::Impl {
         main_process->Run(load_parameters->main_thread_priority,
                           load_parameters->main_thread_stack_size);
 
+        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);
+        // Reset counters and set time origin to current frame
+        GetAndResetPerfStats();
+        perf_stats->BeginSystemFrame();
+
         status = ResultStatus::Success;
         return status;
     }
@@ -219,6 +225,8 @@ struct System::Impl {
                                     perf_results.game_fps);
         telemetry_session->AddField(Telemetry::FieldType::Performance, "Shutdown_Frametime",
                                     perf_results.frametime * 1000.0);
+        telemetry_session->AddField(Telemetry::FieldType::Performance, "Mean_Frametime_MS",
+                                    perf_stats->GetMeanFrametime());
 
         is_powered_on = false;
 
@@ -229,6 +237,7 @@ struct System::Impl {
         service_manager.reset();
         cheat_engine.reset();
         telemetry_session.reset();
+        perf_stats.reset();
         gpu_core.reset();
 
         // Close all CPU/threading state
@@ -286,7 +295,7 @@ struct System::Impl {
     }
 
     PerfStatsResults GetAndResetPerfStats() {
-        return perf_stats.GetAndResetStats(core_timing.GetGlobalTimeUs());
+        return perf_stats->GetAndResetStats(core_timing.GetGlobalTimeUs());
     }
 
     Timing::CoreTiming core_timing;
@@ -327,7 +336,7 @@ struct System::Impl {
     ResultStatus status = ResultStatus::Success;
     std::string status_details = "";
 
-    Core::PerfStats perf_stats;
+    std::unique_ptr<Core::PerfStats> perf_stats;
     Core::FrameLimiter frame_limiter;
 };
 
@@ -480,11 +489,11 @@ const Timing::CoreTiming& System::CoreTiming() const {
 }
 
 Core::PerfStats& System::GetPerfStats() {
-    return impl->perf_stats;
+    return *impl->perf_stats;
 }
 
 const Core::PerfStats& System::GetPerfStats() const {
-    return impl->perf_stats;
+    return *impl->perf_stats;
 }
 
 Core::FrameLimiter& System::FrameLimiter() {

src/core/perf_stats.cpp

@@ -4,8 +4,14 @@
 
 #include <algorithm>
 #include <chrono>
+#include <iterator>
 #include <mutex>
+#include <numeric>
+#include <sstream>
 #include <thread>
+#include <fmt/format.h>
+#include <fmt/time.h>
+#include "common/file_util.h"
 #include "common/math_util.h"
 #include "core/perf_stats.h"
 #include "core/settings.h"
@@ -15,8 +21,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 +56,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 +74,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);
+}
+
 PerfStatsResults 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 <chrono>
 #include <mutex>
 #include "common/common_types.h"
@@ -27,6 +28,10 @@ struct PerfStatsResults {
  */
 class PerfStats {
 public:
+    explicit PerfStats(u64 title_id);
+
+    ~PerfStats();
+
     using Clock = std::chrono::high_resolution_clock;
 
     void BeginSystemFrame();
@@ -35,6 +40,11 @@ public:
 
     PerfStatsResults 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.
@@ -42,7 +52,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

@@ -409,6 +409,7 @@ struct Values {
     float volume;
 
     // Debugging
+    bool record_frame_times;
     bool use_gdbstub;
     u16 gdbstub_port;
     std::string program_args;

src/yuzu/configuration/config.cpp

@@ -466,6 +466,9 @@ void Config::ReadDataStorageValues() {
 void Config::ReadDebuggingValues() {
     qt_config->beginGroup(QStringLiteral("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(QStringLiteral("record_frame_times"), false).toBool();
     Settings::values.use_gdbstub = ReadSetting(QStringLiteral("use_gdbstub"), false).toBool();
     Settings::values.gdbstub_port = ReadSetting(QStringLiteral("gdbstub_port"), 24689).toInt();
     Settings::values.program_args =
@@ -879,6 +882,8 @@ void Config::SaveDataStorageValues() {
 void Config::SaveDebuggingValues() {
     qt_config->beginGroup(QStringLiteral("Debugging"));
 
+    // Intentionally not using the QT default setting as this is intended to be changed in the ini
+    qt_config->setValue(QStringLiteral("record_frame_times"), Settings::values.record_frame_times);
     WriteSetting(QStringLiteral("use_gdbstub"), Settings::values.use_gdbstub, false);
     WriteSetting(QStringLiteral("gdbstub_port"), Settings::values.gdbstub_port, 24689);
     WriteSetting(QStringLiteral("program_args"),

src/yuzu_cmd/config.cpp

@@ -374,6 +374,8 @@ void Config::ReadValues() {
     Settings::values.use_dev_keys = sdl2_config->GetBoolean("Miscellaneous", "use_dev_keys", false);
 
     // 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/yuzu_cmd/default_ini.h

@@ -213,6 +213,8 @@ region_value =
 log_filter = *:Trace
 
 [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