From 62e6c147ae6e02cad3a892f05878f13c9fa596fe Mon Sep 17 00:00:00 2001 From: James Rowe Date: Mon, 12 Aug 2019 22:15:00 -0600 Subject: [PATCH 1/5] Add perf stat logging through ini setting For better tracking of performance regressions on incoming changes, this change adds a way to dump frametime to file by changing an ini config option. This is intentionally hidden as its only useful to a small number of individuals, and not really applicable to the general userbase. --- src/citra/config.cpp | 2 + src/citra/default_ini.h | 2 + src/citra_qt/configuration/config.cpp | 2 + src/core/core.cpp | 14 +++++-- src/core/core.h | 2 +- src/core/hle/service/gsp/gsp_gpu.cpp | 2 +- src/core/hle/service/hid/hid.cpp | 2 +- src/core/perf_stats.cpp | 38 ++++++++++++++++++- src/core/perf_stats.h | 20 +++++++++- src/core/settings.h | 1 + .../renderer_opengl/renderer_opengl.cpp | 4 +- 11 files changed, 78 insertions(+), 11 deletions(-) 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(); From 45be693f8c6e188d47ae64023db69b540f8c5e62 Mon Sep 17 00:00:00 2001 From: James Rowe Date: Mon, 12 Aug 2019 22:21:37 -0600 Subject: [PATCH 2/5] Add telemetry field for mean frametime Previously, telemetry results couldn't give a good estimate for performance over time, because it didn't include any fields related to performance. With this, devs should be able to query metabase for mean frametime to check for performance regressions after a change is made. --- src/core/telemetry_session.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/core/telemetry_session.cpp b/src/core/telemetry_session.cpp index 1049dd8c8..93a4136d7 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::Session, "Mean_Frametime_MS", + Core::System::GetInstance().perf_stats->GetMeanFrametime()); #ifdef ENABLE_WEB_SERVICE auto backend = std::make_unique(Settings::values.web_api_url, From 23e969dfdc5cf9a2c2099d3cbbb15ff546f1f38e Mon Sep 17 00:00:00 2001 From: James Rowe Date: Wed, 14 Aug 2019 21:03:11 -0600 Subject: [PATCH 3/5] Address review comments --- src/citra/default_ini.h | 2 +- src/citra_qt/configuration/config.cpp | 6 ++++-- src/core/core.cpp | 5 +++-- src/core/perf_stats.cpp | 25 +++++++++++++------------ src/core/perf_stats.h | 2 +- 5 files changed, 22 insertions(+), 18 deletions(-) diff --git a/src/citra/default_ini.h b/src/citra/default_ini.h index 4a17ad2d5..76996a0ea 100644 --- a/src/citra/default_ini.h +++ b/src/citra/default_ini.h @@ -261,7 +261,7 @@ camera_inner_flip = log_filter = *:Info [Debugging] -# Record frame time data, can be found in the log directory +# 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 diff --git a/src/citra_qt/configuration/config.cpp b/src/citra_qt/configuration/config.cpp index 1a56e96b2..8ee51b907 100644 --- a/src/citra_qt/configuration/config.cpp +++ b/src/citra_qt/configuration/config.cpp @@ -255,7 +255,8 @@ void Config::ReadValues() { qt_config->endGroup(); qt_config->beginGroup("Debugging"); - Settings::values.record_frame_times = ReadSetting("record_frame_times", false).toBool(); + // 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(); @@ -545,7 +546,8 @@ void Config::SaveValues() { qt_config->endGroup(); qt_config->beginGroup("Debugging"); - WriteSetting("record_frame_times", Settings::values.record_frame_times, false); + // 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 3aa26d456..56fd0798d 100644 --- a/src/core/core.cpp +++ b/src/core/core.cpp @@ -183,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 @@ -321,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/perf_stats.cpp b/src/core/perf_stats.cpp index c9769761d..21e33d753 100644 --- a/src/core/perf_stats.cpp +++ b/src/core/perf_stats.cpp @@ -21,22 +21,23 @@ 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; +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) { - 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()); + if (!Settings::values.record_frame_times || title_id == 0) { + return; } + 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); + std::string filename = fmt::format("{}/{:X}.csv", path, title_id); + FileUtil::IOFile file(filename, "w"); + file.WriteString(stream.str()); } void PerfStats::BeginSystemFrame() { @@ -68,12 +69,12 @@ void PerfStats::EndGameFrame() { } double PerfStats::GetMeanFrametime() { - if (current_index < 2) { + if (current_index <= IgnoreFrames) { return 0; } - double sum = std::accumulate(perf_history.begin() + IGNORE_FRAMES, + double sum = std::accumulate(perf_history.begin() + IgnoreFrames, perf_history.begin() + current_index, 0); - return sum / (current_index - 1 - IGNORE_FRAMES); + return sum / (current_index - IgnoreFrames); } PerfStats::Results PerfStats::GetAndResetStats(microseconds current_system_time_us) { diff --git a/src/core/perf_stats.h b/src/core/perf_stats.h index 39abaaa65..e0b023059 100644 --- a/src/core/perf_stats.h +++ b/src/core/perf_stats.h @@ -59,7 +59,7 @@ private: /// 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}; + 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 = {}; From a77cd00cbeaa455b6352134bcaa0777dcaf28430 Mon Sep 17 00:00:00 2001 From: James Rowe Date: Wed, 14 Aug 2019 21:15:52 -0600 Subject: [PATCH 4/5] Add current date/time to file path --- src/core/perf_stats.cpp | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/core/perf_stats.cpp b/src/core/perf_stats.cpp index 21e33d753..5309e4911 100644 --- a/src/core/perf_stats.cpp +++ b/src/core/perf_stats.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include "common/file_util.h" #include "core/hw/gpu.h" #include "core/perf_stats.h" @@ -31,11 +32,15 @@ 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); - std::string filename = fmt::format("{}/{:X}.csv", path, title_id); + // %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()); } From 135b054f7485a2805a14e3bbb2dfdd01e000786f Mon Sep 17 00:00:00 2001 From: James Rowe Date: Thu, 15 Aug 2019 19:36:02 -0600 Subject: [PATCH 5/5] Update telemetry_session.cpp Change Session -> Performance --- src/core/telemetry_session.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/telemetry_session.cpp b/src/core/telemetry_session.cpp index 93a4136d7..417cf2f7e 100644 --- a/src/core/telemetry_session.cpp +++ b/src/core/telemetry_session.cpp @@ -99,7 +99,7 @@ TelemetrySession::~TelemetrySession() { std::chrono::system_clock::now().time_since_epoch()) .count()}; AddField(Telemetry::FieldType::Session, "Shutdown_Time", shutdown_time); - AddField(Telemetry::FieldType::Session, "Mean_Frametime_MS", + AddField(Telemetry::FieldType::Performance, "Mean_Frametime_MS", Core::System::GetInstance().perf_stats->GetMeanFrametime()); #ifdef ENABLE_WEB_SERVICE