core: log rolling fps every 30s and a session average at shutdown

Every -logfile / stdout-captured run now leaves a durable framerate
record: a "PerfLog:" line every ~30s (rolling fps + EE/GS/VU/GPU thread
utilization + frame number, so warmup separates from steady state) and a
"PerfLog session:" whole-session average at VM shutdown. Coarse
regression signal for A/B and capture runs on device; the rigorous gate
remains perf stat instructions+cycles with pinned clocks.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Brian Degenhardt
2026-07-05 14:24:22 -07:00
co-authored by Claude Fable 5
parent 375625d9dc
commit e1b3596364
3 changed files with 43 additions and 0 deletions
+37
View File
@@ -4,6 +4,7 @@
#include <chrono>
#include <vector>
#include "common/Console.h"
#include "common/Timer.h"
#include "common/Threading.h"
@@ -30,6 +31,15 @@ static u32 s_unskipped_frames_since_last_update = 0;
static Common::Timer s_last_update_time;
static Common::Timer s_last_frame_time;
// Session perf logging: a rolling emulog line every ~30s of presented
// frames, and a whole-session average at shutdown (LogSessionSummary).
// Gives every -logfile run a durable framerate record. Wall-clock based:
// paused time dilutes the session average but not the rolling lines.
static const float LOG_INTERVAL = 30.0f;
static Common::Timer s_session_timer;
static float s_log_accum_time = 0.0f;
static u32 s_log_accum_frames = 0;
// frame number, updated by the GS thread
static u64 s_frame_number = 0;
@@ -96,10 +106,24 @@ void PerformanceMetrics::Clear()
s_frame_number = 0;
s_session_timer.Reset();
s_log_accum_time = 0.0f;
s_log_accum_frames = 0;
s_frame_time_history.fill(0.0f);
s_frame_time_history_pos = 0;
}
void PerformanceMetrics::LogSessionSummary()
{
const double elapsed = s_session_timer.GetTimeSeconds();
if (s_frame_number == 0 || elapsed < 1.0)
return;
Console.WriteLn("PerfLog session: %llu frames in %.1fs wall = %.2f fps average",
static_cast<unsigned long long>(s_frame_number), elapsed,
static_cast<double>(s_frame_number) / elapsed);
}
void PerformanceMetrics::Reset()
{
s_frames_since_last_update = 0;
@@ -221,6 +245,19 @@ void PerformanceMetrics::Update(bool gs_register_write, bool fb_blit, bool is_sk
thread.time = static_cast<double>(delta) * time_divider;
}
// Rolling perf log (uses this window's frame count before it resets).
s_log_accum_time += time;
s_log_accum_frames += s_frames_since_last_update;
if (s_log_accum_time >= LOG_INTERVAL)
{
Console.WriteLn("PerfLog: %.1f fps | EE %.0f%% GS %.0f%% VU %.0f%% GPU %.0f%% | frame %llu",
static_cast<float>(s_log_accum_frames) / s_log_accum_time, s_cpu_thread_usage,
s_gs_thread_usage, s_vu_thread_usage, s_gpu_usage,
static_cast<unsigned long long>(s_frame_number));
s_log_accum_time = 0.0f;
s_log_accum_frames = 0;
}
s_frames_since_last_update = 0;
s_unskipped_frames_since_last_update = 0;
s_presents_since_last_update = 0;
+4
View File
@@ -23,6 +23,10 @@ namespace PerformanceMetrics
void Update(bool gs_register_write, bool fb_blit, bool is_skipping_present);
void OnGPUPresent(float gpu_time);
/// Logs the whole-session average framerate (frames since Clear() over
/// wall time). Called at VM shutdown so every -logfile run records it.
void LogSessionSummary();
/// Sets the EE thread for CPU usage calculations.
void SetCPUThread(Threading::ThreadHandle thread);
+2
View File
@@ -1663,6 +1663,8 @@ void VMManager::Shutdown(bool save_resume_state)
// but just in case, so any of the stuff we call here knows we don't have a valid VM.
s_state.store(VMState::Stopping, std::memory_order_release);
PerformanceMetrics::LogSessionSummary();
SetTimerResolutionIncreased(false);
// sync everything