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..76996a0ea 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. Boolean value +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..8ee51b907 100644 --- a/src/citra_qt/configuration/config.cpp +++ b/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); diff --git a/src/core/core.cpp b/src/core/core.cpp index c7445efec..56fd0798d 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() { @@ -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(); 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..5309e4911 100644 --- a/src/core/perf_stats.cpp +++ b/src/core/perf_stats.cpp @@ -4,8 +4,13 @@ #include #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 +20,31 @@ 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 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(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(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); diff --git a/src/core/perf_stats.h b/src/core/perf_stats.h index 888250e77..e0b023059 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 + 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 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/core/telemetry_session.cpp b/src/core/telemetry_session.cpp index 1049dd8c8..417cf2f7e 100644 --- a/src/core/telemetry_session.cpp +++ b/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(Settings::values.web_api_url, 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();