diff --git a/src/core/core.cpp b/src/core/core.cpp
index 3d0978cbf..9ab174de2 100644
--- a/src/core/core.cpp
+++ b/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() {
diff --git a/src/core/perf_stats.cpp b/src/core/perf_stats.cpp
index 4afd6c8a3..bfab77abb 100644
--- a/src/core/perf_stats.cpp
+++ b/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};
diff --git a/src/core/perf_stats.h b/src/core/perf_stats.h
index 222ac1a63..2db290c09 100644
--- a/src/core/perf_stats.h
+++ b/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();
diff --git a/src/core/settings.h b/src/core/settings.h
index 6638ce8f9..d4b70ec4c 100644
--- a/src/core/settings.h
+++ b/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;
diff --git a/src/yuzu/configuration/config.cpp b/src/yuzu/configuration/config.cpp
index f594106bf..3f54f54fb 100644
--- a/src/yuzu/configuration/config.cpp
+++ b/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"),
diff --git a/src/yuzu_cmd/config.cpp b/src/yuzu_cmd/config.cpp
index 067d58d80..5cadfd191 100644
--- a/src/yuzu_cmd/config.cpp
+++ b/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));
diff --git a/src/yuzu_cmd/default_ini.h b/src/yuzu_cmd/default_ini.h
index 0cfc111a6..f9f244522 100644
--- a/src/yuzu_cmd/default_ini.h
+++ b/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