diff --git a/src/citra/config.cpp b/src/citra/config.cpp index 20e0bddbf..00ca2df65 100644 --- a/src/citra/config.cpp +++ b/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(sdl2_config->GetInteger("Debugging", "gdbstub_port", 24689)); diff --git a/src/citra/default_ini.h b/src/citra/default_ini.h index bd8681c8b..4a17ad2d5 100644 --- a/src/citra/default_ini.h +++ b/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 +record_frame_times = # Port for listening to GDB connections. use_gdbstub=false gdbstub_port=24689 diff --git a/src/citra_qt/configuration/config.cpp b/src/citra_qt/configuration/config.cpp index 0201b3d3c..1a56e96b2 100644 --- a/src/citra_qt/configuration/config.cpp +++ b/src/citra_qt/configuration/config.cpp @@ -255,6 +255,7 @@ void Config::ReadValues() { qt_config->endGroup(); qt_config->beginGroup("Debugging"); + Settings::values.record_frame_times = ReadSetting("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 +545,7 @@ void Config::SaveValues() { qt_config->endGroup(); qt_config->beginGroup("Debugging"); + WriteSetting("record_frame_times", Settings::values.record_frame_times, false); WriteSetting("use_gdbstub", Settings::values.use_gdbstub, false); WriteSetting("gdbstub_port", Settings::values.gdbstub_port, 24689); diff --git a/src/core/core.cpp b/src/core/core.cpp index c7445efec..3aa26d456 100644 --- a/src/core/core.cpp +++ b/src/core/core.cpp @@ -146,6 +146,12 @@ System::ResultStatus System::Load(Frontend::EmuWindow& emu_window, const std::st } } cheat_engine = std::make_unique(*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(load_result)); + } + perf_stats = std::make_unique(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() { @@ -177,8 +183,8 @@ System::ResultStatus System::Init(Frontend::EmuWindow& emu_window, u32 system_mo timing = std::make_unique(); - kernel = std::make_unique(*memory, *timing, - [this] { PrepareReschedule(); }, system_mode); + kernel = std::make_unique( + *memory, *timing, [this] { PrepareReschedule(); }, system_mode); if (Settings::values.use_cpu_jit) { #ifdef ARCHITECTURE_x86_64 @@ -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; } diff --git a/src/core/core.h b/src/core/core.h index 183a5f2f5..ac5f2274e 100644 --- a/src/core/core.h +++ b/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 perf_stats = std::make_unique(0); FrameLimiter frame_limiter; void SetStatus(ResultStatus new_status, const char* details = nullptr) { diff --git a/src/core/hle/service/gsp/gsp_gpu.cpp b/src/core/hle/service/gsp/gsp_gpu.cpp index 1eb4aae52..33558fe10 100644 --- a/src/core/hle/service/gsp/gsp_gpu.cpp +++ b/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; diff --git a/src/core/hle/service/hid/hid.cpp b/src/core/hle/service/hid/hid.cpp index 667ee12c4..ded1809b1 100644 --- a/src/core/hle/service/hid/hid.cpp +++ b/src/core/hle/service/hid/hid.cpp @@ -228,7 +228,7 @@ void Module::UpdateGyroscopeCallback(u64 userdata, s64 cycles_late) { Common::Vec3 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(stretch); gyroscope_entry.x = static_cast(gyro.x); gyroscope_entry.y = static_cast(gyro.y); diff --git a/src/core/perf_stats.cpp b/src/core/perf_stats.cpp index 8f14d1763..c9769761d 100644 --- a/src/core/perf_stats.cpp +++ b/src/core/perf_stats.cpp @@ -4,8 +4,12 @@ #include #include +#include #include +#include #include +#include +#include "common/file_util.h" #include "core/hw/gpu.h" #include "core/perf_stats.h" #include "core/settings.h" @@ -15,8 +19,26 @@ using DoubleSecs = std::chrono::duration; 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 size_t IGNORE_FRAMES = 5; + namespace Core { +PerfStats::PerfStats(u64 title_id) : title_id(title_id) {} + +PerfStats::~PerfStats() { + if (Settings::values.record_frame_times && title_id != 0) { + std::ostringstream stream; + std::copy(perf_history.begin() + IGNORE_FRAMES, perf_history.begin() + current_index, + std::ostream_iterator(stream, "\n")); + std::string path = FileUtil::GetUserPath(FileUtil::UserPath::LogDir); + std::string filename = fmt::format("{}/{:X}.csv", path, title_id); + FileUtil::IOFile file(filename, "w"); + file.WriteString(stream.str()); + } +} + void PerfStats::BeginSystemFrame() { std::lock_guard lock{object_mutex}; @@ -27,7 +49,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(frame_time).count(); + } + accumulated_frametime += frame_time; system_frames += 1; previous_frame_length = frame_end - previous_frame_end; @@ -40,6 +67,15 @@ void PerfStats::EndGameFrame() { game_frames += 1; } +double PerfStats::GetMeanFrametime() { + if (current_index < 2) { + return 0; + } + double sum = std::accumulate(perf_history.begin() + IGNORE_FRAMES, + perf_history.begin() + current_index, 0); + return sum / (current_index - 1 - IGNORE_FRAMES); +} + PerfStats::Results 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 888250e77..39abaaa65 100644 --- a/src/core/perf_stats.h +++ b/src/core/perf_stats.h @@ -4,6 +4,7 @@ #pragma once +#include #include #include #include @@ -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 + size_t current_index{0}; + /// Stores an hour of historical frametime data useful for processing and tracking performance + /// regressions with code changes. + std::array 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 d18953694..00e81f3c9 100644 --- a/src/core/settings.h +++ b/src/core/settings.h @@ -187,6 +187,7 @@ struct Values { std::array camera_flip; // Debugging + bool record_frame_times; bool use_gdbstub; u16 gdbstub_port; std::string log_filter; diff --git a/src/video_core/renderer_opengl/renderer_opengl.cpp b/src/video_core/renderer_opengl/renderer_opengl.cpp index 4740ae86b..8de06a7d2 100644 --- a/src/video_core/renderer_opengl/renderer_opengl.cpp +++ b/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();