Merge pull request #2806 from FearlessTobi/port-4882

Port citra-emu/citra#4882: "Add frametime logging for tracking performance over time"
This commit is contained in:
David 2019-09-21 20:09:55 +10:00 committed by GitHub
commit 183c445c30
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 93 additions and 10 deletions

View File

@ -160,10 +160,6 @@ struct System::Impl {
LOG_DEBUG(Core, "Initialized OK"); LOG_DEBUG(Core, "Initialized OK");
// Reset counters and set time origin to current frame
GetAndResetPerfStats();
perf_stats.BeginSystemFrame();
return ResultStatus::Success; return ResultStatus::Success;
} }
@ -206,6 +202,16 @@ struct System::Impl {
main_process->Run(load_parameters->main_thread_priority, main_process->Run(load_parameters->main_thread_priority,
load_parameters->main_thread_stack_size); 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; status = ResultStatus::Success;
return status; return status;
} }
@ -219,6 +225,8 @@ struct System::Impl {
perf_results.game_fps); perf_results.game_fps);
telemetry_session->AddField(Telemetry::FieldType::Performance, "Shutdown_Frametime", telemetry_session->AddField(Telemetry::FieldType::Performance, "Shutdown_Frametime",
perf_results.frametime * 1000.0); perf_results.frametime * 1000.0);
telemetry_session->AddField(Telemetry::FieldType::Performance, "Mean_Frametime_MS",
perf_stats->GetMeanFrametime());
is_powered_on = false; is_powered_on = false;
@ -229,6 +237,7 @@ struct System::Impl {
service_manager.reset(); service_manager.reset();
cheat_engine.reset(); cheat_engine.reset();
telemetry_session.reset(); telemetry_session.reset();
perf_stats.reset();
gpu_core.reset(); gpu_core.reset();
// Close all CPU/threading state // Close all CPU/threading state
@ -286,7 +295,7 @@ struct System::Impl {
} }
PerfStatsResults GetAndResetPerfStats() { PerfStatsResults GetAndResetPerfStats() {
return perf_stats.GetAndResetStats(core_timing.GetGlobalTimeUs()); return perf_stats->GetAndResetStats(core_timing.GetGlobalTimeUs());
} }
Timing::CoreTiming core_timing; Timing::CoreTiming core_timing;
@ -327,7 +336,7 @@ struct System::Impl {
ResultStatus status = ResultStatus::Success; ResultStatus status = ResultStatus::Success;
std::string status_details = ""; std::string status_details = "";
Core::PerfStats perf_stats; std::unique_ptr<Core::PerfStats> perf_stats;
Core::FrameLimiter frame_limiter; Core::FrameLimiter frame_limiter;
}; };
@ -480,11 +489,11 @@ const Timing::CoreTiming& System::CoreTiming() const {
} }
Core::PerfStats& System::GetPerfStats() { Core::PerfStats& System::GetPerfStats() {
return impl->perf_stats; return *impl->perf_stats;
} }
const Core::PerfStats& System::GetPerfStats() const { const Core::PerfStats& System::GetPerfStats() const {
return impl->perf_stats; return *impl->perf_stats;
} }
Core::FrameLimiter& System::FrameLimiter() { Core::FrameLimiter& System::FrameLimiter() {

View File

@ -4,8 +4,14 @@
#include <algorithm> #include <algorithm>
#include <chrono> #include <chrono>
#include <iterator>
#include <mutex> #include <mutex>
#include <numeric>
#include <sstream>
#include <thread> #include <thread>
#include <fmt/chrono.h>
#include <fmt/format.h>
#include "common/file_util.h"
#include "common/math_util.h" #include "common/math_util.h"
#include "core/perf_stats.h" #include "core/perf_stats.h"
#include "core/settings.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::duration_cast;
using std::chrono::microseconds; 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 { namespace Core {
PerfStats::PerfStats(u64 title_id) : title_id(title_id) {}
PerfStats::~PerfStats() {
if (!Settings::values.record_frame_times || title_id == 0) {
return;
}
const 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"));
const std::string& path = FileUtil::GetUserPath(FileUtil::UserPath::LogDir);
// %F Date format expanded is "%Y-%m-%d"
const 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() { void PerfStats::BeginSystemFrame() {
std::lock_guard lock{object_mutex}; std::lock_guard lock{object_mutex};
@ -27,7 +56,12 @@ void PerfStats::EndSystemFrame() {
std::lock_guard lock{object_mutex}; std::lock_guard lock{object_mutex};
auto frame_end = Clock::now(); 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; system_frames += 1;
previous_frame_length = frame_end - previous_frame_end; previous_frame_length = frame_end - previous_frame_end;
@ -40,6 +74,17 @@ void PerfStats::EndGameFrame() {
game_frames += 1; game_frames += 1;
} }
double PerfStats::GetMeanFrametime() {
std::lock_guard lock{object_mutex};
if (current_index <= IgnoreFrames) {
return 0;
}
const 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) { PerfStatsResults PerfStats::GetAndResetStats(microseconds current_system_time_us) {
std::lock_guard lock{object_mutex}; std::lock_guard lock{object_mutex};

View File

@ -4,7 +4,9 @@
#pragma once #pragma once
#include <array>
#include <chrono> #include <chrono>
#include <cstddef>
#include <mutex> #include <mutex>
#include "common/common_types.h" #include "common/common_types.h"
@ -27,6 +29,10 @@ struct PerfStatsResults {
*/ */
class PerfStats { class PerfStats {
public: public:
explicit PerfStats(u64 title_id);
~PerfStats();
using Clock = std::chrono::high_resolution_clock; using Clock = std::chrono::high_resolution_clock;
void BeginSystemFrame(); void BeginSystemFrame();
@ -35,6 +41,11 @@ public:
PerfStatsResults GetAndResetStats(std::chrono::microseconds current_system_time_us); 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 * 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. * useful for scaling inputs or outputs moving between the two time domains.
@ -42,7 +53,15 @@ public:
double GetLastFrameTimeScale(); double GetLastFrameTimeScale();
private: 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 /// Point when the cumulative counters were reset
Clock::time_point reset_point = Clock::now(); Clock::time_point reset_point = Clock::now();

View File

@ -409,6 +409,7 @@ struct Values {
float volume; float volume;
// Debugging // Debugging
bool record_frame_times;
bool use_gdbstub; bool use_gdbstub;
u16 gdbstub_port; u16 gdbstub_port;
std::string program_args; std::string program_args;

View File

@ -466,6 +466,9 @@ void Config::ReadDataStorageValues() {
void Config::ReadDebuggingValues() { void Config::ReadDebuggingValues() {
qt_config->beginGroup(QStringLiteral("Debugging")); 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.use_gdbstub = ReadSetting(QStringLiteral("use_gdbstub"), false).toBool();
Settings::values.gdbstub_port = ReadSetting(QStringLiteral("gdbstub_port"), 24689).toInt(); Settings::values.gdbstub_port = ReadSetting(QStringLiteral("gdbstub_port"), 24689).toInt();
Settings::values.program_args = Settings::values.program_args =
@ -879,6 +882,8 @@ void Config::SaveDataStorageValues() {
void Config::SaveDebuggingValues() { void Config::SaveDebuggingValues() {
qt_config->beginGroup(QStringLiteral("Debugging")); 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("use_gdbstub"), Settings::values.use_gdbstub, false);
WriteSetting(QStringLiteral("gdbstub_port"), Settings::values.gdbstub_port, 24689); WriteSetting(QStringLiteral("gdbstub_port"), Settings::values.gdbstub_port, 24689);
WriteSetting(QStringLiteral("program_args"), WriteSetting(QStringLiteral("program_args"),

View File

@ -374,6 +374,8 @@ void Config::ReadValues() {
Settings::values.use_dev_keys = sdl2_config->GetBoolean("Miscellaneous", "use_dev_keys", false); Settings::values.use_dev_keys = sdl2_config->GetBoolean("Miscellaneous", "use_dev_keys", false);
// Debugging // 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.use_gdbstub = sdl2_config->GetBoolean("Debugging", "use_gdbstub", false);
Settings::values.gdbstub_port = Settings::values.gdbstub_port =
static_cast<u16>(sdl2_config->GetInteger("Debugging", "gdbstub_port", 24689)); static_cast<u16>(sdl2_config->GetInteger("Debugging", "gdbstub_port", 24689));

View File

@ -213,6 +213,8 @@ region_value =
log_filter = *:Trace log_filter = *:Trace
[Debugging] [Debugging]
# Record frame time data, can be found in the log directory. Boolean value
record_frame_times =
# Port for listening to GDB connections. # Port for listening to GDB connections.
use_gdbstub=false use_gdbstub=false
gdbstub_port=24689 gdbstub_port=24689