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.
This commit is contained in:
James Rowe 2019-08-12 22:15:00 -06:00
parent 84b40f2da6
commit 62e6c147ae
11 changed files with 78 additions and 11 deletions

View file

@ -234,6 +234,8 @@ void Config::ReadValues() {
Settings::values.log_filter = sdl2_config->GetString("Miscellaneous", "log_filter", "*:Info"); Settings::values.log_filter = sdl2_config->GetString("Miscellaneous", "log_filter", "*:Info");
// 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

@ -261,6 +261,8 @@ camera_inner_flip =
log_filter = *:Info log_filter = *:Info
[Debugging] [Debugging]
# Record frame time data, can be found in the log directory
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

View file

@ -255,6 +255,7 @@ void Config::ReadValues() {
qt_config->endGroup(); qt_config->endGroup();
qt_config->beginGroup("Debugging"); 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.use_gdbstub = ReadSetting("use_gdbstub", false).toBool();
Settings::values.gdbstub_port = ReadSetting("gdbstub_port", 24689).toInt(); Settings::values.gdbstub_port = ReadSetting("gdbstub_port", 24689).toInt();
@ -544,6 +545,7 @@ void Config::SaveValues() {
qt_config->endGroup(); qt_config->endGroup();
qt_config->beginGroup("Debugging"); qt_config->beginGroup("Debugging");
WriteSetting("record_frame_times", Settings::values.record_frame_times, false);
WriteSetting("use_gdbstub", Settings::values.use_gdbstub, false); WriteSetting("use_gdbstub", Settings::values.use_gdbstub, false);
WriteSetting("gdbstub_port", Settings::values.gdbstub_port, 24689); WriteSetting("gdbstub_port", Settings::values.gdbstub_port, 24689);

View file

@ -146,6 +146,12 @@ System::ResultStatus System::Load(Frontend::EmuWindow& emu_window, const std::st
} }
} }
cheat_engine = std::make_unique<Cheats::CheatEngine>(*this); cheat_engine = std::make_unique<Cheats::CheatEngine>(*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<u32>(load_result));
}
perf_stats = std::make_unique<PerfStats>(title_id);
status = ResultStatus::Success; status = ResultStatus::Success;
m_emu_window = &emu_window; m_emu_window = &emu_window;
m_filepath = filepath; m_filepath = filepath;
@ -158,7 +164,7 @@ void System::PrepareReschedule() {
} }
PerfStats::Results System::GetAndResetPerfStats() { PerfStats::Results System::GetAndResetPerfStats() {
return perf_stats.GetAndResetStats(timing->GetGlobalTimeUs()); return perf_stats->GetAndResetStats(timing->GetGlobalTimeUs());
} }
void System::Reschedule() { void System::Reschedule() {
@ -177,8 +183,8 @@ System::ResultStatus System::Init(Frontend::EmuWindow& emu_window, u32 system_mo
timing = std::make_unique<Timing>(); timing = std::make_unique<Timing>();
kernel = std::make_unique<Kernel::KernelSystem>(*memory, *timing, kernel = std::make_unique<Kernel::KernelSystem>(
[this] { PrepareReschedule(); }, system_mode); *memory, *timing, [this] { PrepareReschedule(); }, system_mode);
if (Settings::values.use_cpu_jit) { if (Settings::values.use_cpu_jit) {
#ifdef ARCHITECTURE_x86_64 #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 // Reset counters and set time origin to current frame
GetAndResetPerfStats(); GetAndResetPerfStats();
perf_stats.BeginSystemFrame(); perf_stats->BeginSystemFrame();
return ResultStatus::Success; return ResultStatus::Success;
} }

View file

@ -216,7 +216,7 @@ public:
/// Gets a const reference to the video dumper backend /// Gets a const reference to the video dumper backend
const VideoDumper::Backend& VideoDumper() const; const VideoDumper::Backend& VideoDumper() const;
PerfStats perf_stats; std::unique_ptr<PerfStats> perf_stats = std::make_unique<PerfStats>(0);
FrameLimiter frame_limiter; FrameLimiter frame_limiter;
void SetStatus(ResultStatus new_status, const char* details = nullptr) { void SetStatus(ResultStatus new_status, const char* details = nullptr) {

View file

@ -307,7 +307,7 @@ ResultCode SetBufferSwap(u32 screen_id, const FrameBufferInfo& info) {
if (screen_id == 0) { if (screen_id == 0) {
MicroProfileFlip(); MicroProfileFlip();
Core::System::GetInstance().perf_stats.EndGameFrame(); Core::System::GetInstance().perf_stats->EndGameFrame();
} }
return RESULT_SUCCESS; return RESULT_SUCCESS;

View file

@ -228,7 +228,7 @@ void Module::UpdateGyroscopeCallback(u64 userdata, s64 cycles_late) {
Common::Vec3<float> gyro; Common::Vec3<float> gyro;
std::tie(std::ignore, gyro) = motion_device->GetStatus(); 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<float>(stretch); gyro *= gyroscope_coef * static_cast<float>(stretch);
gyroscope_entry.x = static_cast<s16>(gyro.x); gyroscope_entry.x = static_cast<s16>(gyro.x);
gyroscope_entry.y = static_cast<s16>(gyro.y); gyroscope_entry.y = static_cast<s16>(gyro.y);

View file

@ -4,8 +4,12 @@
#include <algorithm> #include <algorithm>
#include <chrono> #include <chrono>
#include <iterator>
#include <mutex> #include <mutex>
#include <numeric>
#include <thread> #include <thread>
#include <fmt/format.h>
#include "common/file_util.h"
#include "core/hw/gpu.h" #include "core/hw/gpu.h"
#include "core/perf_stats.h" #include "core/perf_stats.h"
#include "core/settings.h" #include "core/settings.h"
@ -15,8 +19,26 @@ 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 size_t IGNORE_FRAMES = 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) {
std::ostringstream stream;
std::copy(perf_history.begin() + IGNORE_FRAMES, perf_history.begin() + current_index,
std::ostream_iterator<double>(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() { void PerfStats::BeginSystemFrame() {
std::lock_guard lock{object_mutex}; std::lock_guard lock{object_mutex};
@ -27,7 +49,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 +67,15 @@ void PerfStats::EndGameFrame() {
game_frames += 1; 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) { PerfStats::Results PerfStats::GetAndResetStats(microseconds current_system_time_us) {
std::lock_guard lock(object_mutex); std::lock_guard lock(object_mutex);

View file

@ -4,6 +4,7 @@
#pragma once #pragma once
#include <array>
#include <atomic> #include <atomic>
#include <chrono> #include <chrono>
#include <mutex> #include <mutex>
@ -18,6 +19,10 @@ namespace Core {
*/ */
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;
struct Results { struct Results {
@ -37,6 +42,11 @@ public:
Results GetAndResetStats(std::chrono::microseconds current_system_time_us); 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 * 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.
@ -44,7 +54,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
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

@ -187,6 +187,7 @@ struct Values {
std::array<int, Service::CAM::NumCameras> camera_flip; std::array<int, Service::CAM::NumCameras> camera_flip;
// Debugging // Debugging
bool record_frame_times;
bool use_gdbstub; bool use_gdbstub;
u16 gdbstub_port; u16 gdbstub_port;
std::string log_filter; std::string log_filter;

View file

@ -239,7 +239,7 @@ void RendererOpenGL::SwapBuffers() {
DrawScreens(render_window.GetFramebufferLayout()); DrawScreens(render_window.GetFramebufferLayout());
m_current_frame++; m_current_frame++;
Core::System::GetInstance().perf_stats.EndSystemFrame(); Core::System::GetInstance().perf_stats->EndSystemFrame();
// Swap buffers // Swap buffers
render_window.PollEvents(); render_window.PollEvents();
@ -247,7 +247,7 @@ void RendererOpenGL::SwapBuffers() {
Core::System::GetInstance().frame_limiter.DoFrameLimiting( Core::System::GetInstance().frame_limiter.DoFrameLimiting(
Core::System::GetInstance().CoreTiming().GetGlobalTimeUs()); Core::System::GetInstance().CoreTiming().GetGlobalTimeUs());
Core::System::GetInstance().perf_stats.BeginSystemFrame(); Core::System::GetInstance().perf_stats->BeginSystemFrame();
prev_state.Apply(); prev_state.Apply();
RefreshRasterizerSetting(); RefreshRasterizerSetting();