From 684b616f0d6445b753dded31554e0b006b6d2c3e Mon Sep 17 00:00:00 2001 From: fearlessTobi Date: Mon, 26 Aug 2019 17:29:08 +0200 Subject: Add frametime logging for tracking performance over time Co-Authored-By: jroweboy --- src/core/core.cpp | 25 +++++++++++++++------- src/core/perf_stats.cpp | 45 ++++++++++++++++++++++++++++++++++++++- src/core/perf_stats.h | 20 ++++++++++++++++- src/core/settings.h | 1 + src/yuzu/configuration/config.cpp | 5 +++++ src/yuzu_cmd/config.cpp | 2 ++ src/yuzu_cmd/default_ini.h | 2 ++ 7 files changed, 90 insertions(+), 10 deletions(-) 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(load_result)); + } + perf_stats = std::make_unique(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 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 #include +#include #include +#include +#include #include +#include +#include +#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; 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 +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(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 #include #include #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 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(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 -- cgit v1.2.3