gsrunner: per-frame stats JSON, percentiles, and a generic -set override

gsrunner's textual output was run-aggregate only: totals for the whole run plus
min/avg/max frame time. A single spiky frame was invisible, and nothing was
machine-readable. The -perf block is also useless on short runs, because
PerformanceMetrics only updates about once a second -- an 8-frame replay reports
nan/inf for every field.

-stats-json <path> writes a per-frame series plus a run summary. Counters are
exact per-frame deltas (update_stat now returns the delta it accumulates, so the
series and the totals stay derived from one source), and frame_ms is measured
directly rather than taken from PerformanceMetrics' window averages. Adds
PerformanceMetrics::GetLastGPUTime for the same reason: OnGPUPresent already
receives a per-frame GPU time but only accumulated it, and an averaged value
hides the spike we are looking for.

Percentiles (p50/p95/p99) and the worst-frame index are reported over drawn
frames only; idle frames are present-only and would drag the distribution down.

-set <Section/Key>=<value> overrides any setting generically. Every experiment
previously needed a bespoke flag -- -accblend, -no-fb-fetch, -no-tex-barriers,
-no-vs-expand, -backthread -- which is a flag per question and makes a sweep
driver impossible. Verified equivalent: -accblend 3 and
-set EmuCore/GS/accurate_blending_unit=3 produce identical counters, and the
override demonstrably bites (accblend 0 -> 4 barriers, accblend 5 -> 365).

Also prints the previously-accumulated-but-never-printed PS2-level draw count,
adds prim accounting, and surfaces the new texture-cache hit/miss counters.
This commit is contained in:
Brian Degenhardt
2026-07-22 21:16:45 -07:00
parent 6b079a4e12
commit 1edbeb1fbb
3 changed files with 258 additions and 13 deletions
+247 -13
View File
@@ -25,6 +25,7 @@
#include "common/ProgressCallback.h"
#include "common/SettingsWrapper.h"
#include "common/StringUtil.h"
#include "common/Timer.h"
#include "pcsx2/PrecompiledHeader.h"
@@ -108,6 +109,52 @@ static u32 s_total_frames = 0;
static u32 s_total_drawn_frames = 0;
static std::vector<std::string> s_extended_stats_snapshot;
// Per-frame statistics series. Run-aggregate min/avg/max cannot locate a spike, so
// every presented frame is recorded and written out as JSON at the end of the run.
// Counters are exact per-frame deltas; frame_ms is measured here rather than taken
// from PerformanceMetrics, whose values are window averages.
struct FrameSample
{
u32 frame;
bool idle;
float frame_ms;
float gpu_ms;
u64 prims;
u64 draws; // PS2-level (GSPerfMon::Draw)
u64 draw_calls;
u64 render_passes;
u64 barriers;
u64 copies;
u64 uploads;
u64 readbacks;
u64 copies_rov;
u64 draw_calls_rov;
u64 barriers_rov;
u64 tc_source_hit;
u64 tc_source_miss;
u64 tc_target_hit;
u64 tc_target_miss;
u64 hash_cache_hit;
u64 hash_cache_miss;
};
static std::string s_stats_json_path;
static std::vector<FrameSample> s_frame_samples;
static u64 s_frame_timer_last = 0;
static double s_last_prims = 0;
static double s_last_tc_source_hit = 0;
static double s_last_tc_source_miss = 0;
static double s_last_tc_target_hit = 0;
static double s_last_tc_target_miss = 0;
static double s_last_hash_cache_hit = 0;
static double s_last_hash_cache_miss = 0;
static u64 s_total_prims = 0;
static u64 s_total_tc_source_hit = 0;
static u64 s_total_tc_source_miss = 0;
static u64 s_total_tc_target_hit = 0;
static u64 s_total_tc_target_miss = 0;
static u64 s_total_hash_cache_hit = 0;
static u64 s_total_hash_cache_miss = 0;
static bool s_perf_enable = false;
static bool s_force_vsync = false;
static float s_perf_updates = 0.0f;
@@ -286,23 +333,36 @@ void Host::BeginPresentFrame()
const u32 last_draws = s_total_internal_draws;
const u32 last_uploads = s_total_uploads;
static constexpr auto update_stat = [](GSPerfMon::counter_t counter, u64& dst, double& last) {
// perfmon resets every 30 frames to zero
// Returns this frame's delta as well as accumulating it, so the per-frame
// series and the run totals stay derived from one source.
static constexpr auto update_stat = [](GSPerfMon::counter_t counter, u64& dst, double& last) -> u64 {
// perfmon resets every 32 frames to zero
const double val = g_perfmon.GetCounter(counter);
dst += static_cast<u64>((val < last) ? val : (val - last));
const u64 delta = static_cast<u64>((val < last) ? val : (val - last));
dst += delta;
last = val;
return delta;
};
update_stat(GSPerfMon::Draw, s_total_internal_draws, s_last_internal_draws);
update_stat(GSPerfMon::DrawCalls, s_total_draws, s_last_draws);
update_stat(GSPerfMon::RenderPasses, s_total_render_passes, s_last_render_passes);
update_stat(GSPerfMon::Barriers, s_total_barriers, s_last_barriers);
update_stat(GSPerfMon::TextureCopies, s_total_copies, s_last_copies);
update_stat(GSPerfMon::TextureUploads, s_total_uploads, s_last_uploads);
update_stat(GSPerfMon::Readbacks, s_total_readbacks, s_last_readbacks);
update_stat(GSPerfMon::TextureCopiesROV, s_total_copies_rov, s_last_depth_copies_rov);
update_stat(GSPerfMon::DrawCallsROV, s_total_draws_rov, s_last_draws_rov);
update_stat(GSPerfMon::BarriersROV, s_total_barriers_rov, s_last_barriers_rov);
FrameSample sample = {};
sample.frame = s_total_frames;
sample.prims = update_stat(GSPerfMon::Prim, s_total_prims, s_last_prims);
sample.draws = update_stat(GSPerfMon::Draw, s_total_internal_draws, s_last_internal_draws);
sample.draw_calls = update_stat(GSPerfMon::DrawCalls, s_total_draws, s_last_draws);
sample.render_passes = update_stat(GSPerfMon::RenderPasses, s_total_render_passes, s_last_render_passes);
sample.barriers = update_stat(GSPerfMon::Barriers, s_total_barriers, s_last_barriers);
sample.copies = update_stat(GSPerfMon::TextureCopies, s_total_copies, s_last_copies);
sample.uploads = update_stat(GSPerfMon::TextureUploads, s_total_uploads, s_last_uploads);
sample.readbacks = update_stat(GSPerfMon::Readbacks, s_total_readbacks, s_last_readbacks);
sample.copies_rov = update_stat(GSPerfMon::TextureCopiesROV, s_total_copies_rov, s_last_depth_copies_rov);
sample.draw_calls_rov = update_stat(GSPerfMon::DrawCallsROV, s_total_draws_rov, s_last_draws_rov);
sample.barriers_rov = update_stat(GSPerfMon::BarriersROV, s_total_barriers_rov, s_last_barriers_rov);
sample.tc_source_hit = update_stat(GSPerfMon::TCSourceHit, s_total_tc_source_hit, s_last_tc_source_hit);
sample.tc_source_miss = update_stat(GSPerfMon::TCSourceMiss, s_total_tc_source_miss, s_last_tc_source_miss);
sample.tc_target_hit = update_stat(GSPerfMon::TCTargetHit, s_total_tc_target_hit, s_last_tc_target_hit);
sample.tc_target_miss = update_stat(GSPerfMon::TCTargetMiss, s_total_tc_target_miss, s_last_tc_target_miss);
sample.hash_cache_hit = update_stat(GSPerfMon::HashCacheHit, s_total_hash_cache_hit, s_last_hash_cache_hit);
sample.hash_cache_miss = update_stat(GSPerfMon::HashCacheMiss, s_total_hash_cache_miss, s_last_hash_cache_miss);
const bool idle_frame = s_total_frames && (last_draws == s_total_internal_draws && last_uploads == s_total_uploads);
@@ -311,6 +371,19 @@ void Host::BeginPresentFrame()
s_total_frames++;
if (!s_stats_json_path.empty())
{
const u64 now = Common::Timer::GetCurrentValue();
sample.idle = idle_frame;
// First frame has no predecessor to measure against.
sample.frame_ms = s_frame_timer_last ?
static_cast<float>(Common::Timer::ConvertValueToMilliseconds(now - s_frame_timer_last)) :
0.0f;
s_frame_timer_last = now;
sample.gpu_ms = PerformanceMetrics::GetLastGPUTime();
s_frame_samples.push_back(sample);
}
std::atomic_thread_fence(std::memory_order_release);
}
}
@@ -514,6 +587,10 @@ static void PrintCommandLineHelp(const char* progname)
std::fprintf(stderr, " -logfile <filename>: Writes emu log to filename.\n");
std::fprintf(stderr, " -noshadercache: Disables the shader cache (useful for parallel runs).\n");
std::fprintf(stderr, " -perf: Enable frame timing performance stats.\n");
std::fprintf(stderr, " -stats-json <path>: Write per-frame and run-summary statistics as JSON. Combine with -perf "
"for frame/GPU timing.\n");
std::fprintf(stderr, " -set <Section/Key>=<value>: Override any setting, e.g. -set EmuCore/GS/AccurateBlendingUnit=3. "
"Repeatable.\n");
std::fprintf(stderr, " -vsync: Force vsync on (FIFO present mode). Workaround for libmali Wayland WSI which "
"advertises MAILBOX support but errors VK_ERROR_INITIALIZATION_FAILED on swapchain create.\n");
std::fprintf(stderr, " -no-fb-fetch: Disable Vulkan framebuffer fetch (VK_EXT_rasterization_order_attachment_access). "
@@ -829,6 +906,40 @@ bool GSRunner::ParseCommandLineArgs(int argc, char* argv[], VMBootParameters& pa
s_perf_enable = true;
continue;
}
else if (CHECK_ARG_PARAM("-stats-json"))
{
s_stats_json_path = argv[++i];
Console.WriteLn(fmt::format("Writing per-frame stats to {}", s_stats_json_path));
continue;
}
else if (CHECK_ARG_PARAM("-set"))
{
// Generic settings override: -set <Section/Key>=<value>. Retires the need
// for a bespoke flag per experiment and makes a sweep driver trivial.
const std::string_view arg(argv[++i]);
const std::string_view::size_type eq = arg.find('=');
const std::string_view::size_type slash = arg.rfind('/', eq);
if (eq == std::string_view::npos || slash == std::string_view::npos || slash == 0)
{
Console.Error(fmt::format("Malformed -set '{}', expected <Section/Key>=<value>", arg));
return false;
}
const std::string section(arg.substr(0, slash));
const std::string key(arg.substr(slash + 1, eq - slash - 1));
const std::string value(arg.substr(eq + 1));
if (key.empty())
{
Console.Error(fmt::format("Malformed -set '{}', empty key", arg));
return false;
}
// Stored as a string; SettingsWrapper coerces on read, so this works for
// bool/int/float keys alike.
s_settings_interface.SetStringValue(section.c_str(), key.c_str(), value.c_str());
Console.WriteLn(fmt::format("Override: [{}] {} = {}", section, key, value));
continue;
}
else if (CHECK_ARG("-vsync"))
{
Console.WriteLn("Forcing vsync on (FIFO present mode). Use on libmali Wayland where MAILBOX errors VK_ERROR_INITIALIZATION_FAILED.");
@@ -973,10 +1084,108 @@ void GSRunner::SettingsOverride()
}
}
static double Ratio(u64 num, u64 den)
{
return den ? (100.0 * static_cast<double>(num) / static_cast<double>(den)) : 0.0;
}
// Nearest-rank percentile over an already-sorted vector.
static float Percentile(const std::vector<float>& sorted, double p)
{
if (sorted.empty())
return 0.0f;
const size_t idx = std::min(sorted.size() - 1,
static_cast<size_t>(std::ceil(p * static_cast<double>(sorted.size())) - 1.0));
return sorted[idx];
}
// Writes the per-frame series plus a run summary. Emitted by hand rather than via a
// JSON library because gsrunner links none, and the schema is fixed.
static void WriteStatsJson(const std::string& path)
{
auto fp = FileSystem::OpenManagedCFile(path.c_str(), "wb");
if (!fp)
{
Console.Error(fmt::format("Failed to open '{}' for writing stats", path));
return;
}
// Percentiles are computed over drawn frames only; idle frames are present-only
// and would drag the distribution toward zero.
std::vector<float> frame_times;
frame_times.reserve(s_frame_samples.size());
for (const FrameSample& s : s_frame_samples)
{
if (!s.idle && s.frame_ms > 0.0f)
frame_times.push_back(s.frame_ms);
}
std::sort(frame_times.begin(), frame_times.end());
u32 worst_frame = 0;
float worst_ms = 0.0f;
for (const FrameSample& s : s_frame_samples)
{
if (!s.idle && s.frame_ms > worst_ms)
{
worst_ms = s.frame_ms;
worst_frame = s.frame;
}
}
std::fprintf(fp.get(), "{\n \"run\": {\n");
std::fprintf(fp.get(), " \"frames\": %u,\n \"drawn_frames\": %u,\n", s_total_frames, s_total_drawn_frames);
std::fprintf(fp.get(), " \"prims\": %" PRIu64 ",\n \"draws\": %" PRIu64 ",\n \"draw_calls\": %" PRIu64 ",\n",
s_total_prims, s_total_internal_draws, s_total_draws);
std::fprintf(fp.get(), " \"render_passes\": %" PRIu64 ",\n \"barriers\": %" PRIu64 ",\n", s_total_render_passes, s_total_barriers);
std::fprintf(fp.get(), " \"copies\": %" PRIu64 ",\n \"uploads\": %" PRIu64 ",\n \"readbacks\": %" PRIu64 ",\n",
s_total_copies, s_total_uploads, s_total_readbacks);
std::fprintf(fp.get(), " \"copies_rov\": %" PRIu64 ",\n \"draw_calls_rov\": %" PRIu64 ",\n \"barriers_rov\": %" PRIu64 ",\n",
s_total_copies_rov, s_total_draws_rov, s_total_barriers_rov);
std::fprintf(fp.get(), " \"tc_source_hit\": %" PRIu64 ",\n \"tc_source_miss\": %" PRIu64 ",\n",
s_total_tc_source_hit, s_total_tc_source_miss);
std::fprintf(fp.get(), " \"tc_target_hit\": %" PRIu64 ",\n \"tc_target_miss\": %" PRIu64 ",\n",
s_total_tc_target_hit, s_total_tc_target_miss);
std::fprintf(fp.get(), " \"hash_cache_hit\": %" PRIu64 ",\n \"hash_cache_miss\": %" PRIu64 ",\n",
s_total_hash_cache_hit, s_total_hash_cache_miss);
std::fprintf(fp.get(), " \"frame_ms_p50\": %.3f,\n \"frame_ms_p95\": %.3f,\n \"frame_ms_p99\": %.3f,\n",
Percentile(frame_times, 0.50), Percentile(frame_times, 0.95), Percentile(frame_times, 0.99));
std::fprintf(fp.get(), " \"frame_ms_worst\": %.3f,\n \"frame_worst_index\": %u\n },\n", worst_ms, worst_frame);
std::fprintf(fp.get(), " \"frames\": [\n");
for (size_t i = 0; i < s_frame_samples.size(); i++)
{
const FrameSample& s = s_frame_samples[i];
std::fprintf(fp.get(),
" {\"frame\":%u,\"idle\":%s,\"frame_ms\":%.3f,\"gpu_ms\":%.3f,"
"\"prims\":%" PRIu64 ",\"draws\":%" PRIu64 ",\"draw_calls\":%" PRIu64 ","
"\"render_passes\":%" PRIu64 ",\"barriers\":%" PRIu64 ",\"copies\":%" PRIu64 ","
"\"uploads\":%" PRIu64 ",\"readbacks\":%" PRIu64 ","
"\"copies_rov\":%" PRIu64 ",\"draw_calls_rov\":%" PRIu64 ",\"barriers_rov\":%" PRIu64 ","
"\"tc_source_hit\":%" PRIu64 ",\"tc_source_miss\":%" PRIu64 ","
"\"tc_target_hit\":%" PRIu64 ",\"tc_target_miss\":%" PRIu64 ","
"\"hash_cache_hit\":%" PRIu64 ",\"hash_cache_miss\":%" PRIu64 "}%s\n",
s.frame, s.idle ? "true" : "false", s.frame_ms, s.gpu_ms,
s.prims, s.draws, s.draw_calls,
s.render_passes, s.barriers, s.copies,
s.uploads, s.readbacks,
s.copies_rov, s.draw_calls_rov, s.barriers_rov,
s.tc_source_hit, s.tc_source_miss,
s.tc_target_hit, s.tc_target_miss,
s.hash_cache_hit, s.hash_cache_miss,
(i + 1 < s_frame_samples.size()) ? "," : "");
}
std::fprintf(fp.get(), " ]\n}\n");
Console.WriteLn(fmt::format("Wrote {} frame samples to {}", s_frame_samples.size(), path));
}
void GSRunner::DumpStats()
{
std::atomic_thread_fence(std::memory_order_acquire);
Console.WriteLn(fmt::format("======= HW STATISTICS FOR {} ({}) FRAMES ========", s_total_frames, s_total_drawn_frames));
Console.WriteLn(fmt::format("@HWSTAT@ Prims: {} (avg {})", s_total_prims, static_cast<u64>(std::ceil(s_total_prims / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Draws: {} (avg {})", s_total_internal_draws, static_cast<u64>(std::ceil(s_total_internal_draws / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Draw Calls: {} (avg {})", s_total_draws, static_cast<u64>(std::ceil(s_total_draws / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Render Passes: {} (avg {})", s_total_render_passes, static_cast<u64>(std::ceil(s_total_render_passes / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Barriers: {} (avg {})", s_total_barriers, static_cast<u64>(std::ceil(s_total_barriers / static_cast<double>(s_total_drawn_frames)))));
@@ -986,6 +1195,12 @@ void GSRunner::DumpStats()
Console.WriteLn(fmt::format("@HWSTAT@ Copies (ROV): {} (avg {})", s_total_copies_rov, static_cast<u64>(std::ceil(s_total_copies_rov / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Draws Calls (ROV): {} (avg {})", s_total_draws_rov, static_cast<u64>(std::ceil(s_total_draws_rov / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ Barriers (ROV): {} (avg {})", s_total_barriers_rov, static_cast<u64>(std::ceil(s_total_barriers_rov / static_cast<double>(s_total_drawn_frames)))));
Console.WriteLn(fmt::format("@HWSTAT@ TC Source Hit/Miss: {}/{} ({:.1f}% hit)", s_total_tc_source_hit, s_total_tc_source_miss,
Ratio(s_total_tc_source_hit, s_total_tc_source_hit + s_total_tc_source_miss)));
Console.WriteLn(fmt::format("@HWSTAT@ TC Target Hit/Miss: {}/{} ({:.1f}% hit)", s_total_tc_target_hit, s_total_tc_target_miss,
Ratio(s_total_tc_target_hit, s_total_tc_target_hit + s_total_tc_target_miss)));
Console.WriteLn(fmt::format("@HWSTAT@ Hash Cache Hit/Miss: {}/{} ({:.1f}% hit)", s_total_hash_cache_hit, s_total_hash_cache_miss,
Ratio(s_total_hash_cache_hit, s_total_hash_cache_hit + s_total_hash_cache_miss)));
if (s_perf_enable)
{
Console.WriteLn(fmt::format("@HWSTAT@ Minimum Frame Time: {:.3f} ms ({:.3f} FPS)", PerformanceMetrics::GetMinimumFrameTime(), 1000.0f / PerformanceMetrics::GetMinimumFrameTime()));
@@ -998,9 +1213,28 @@ void GSRunner::DumpStats()
Console.WriteLn(fmt::format("@HWSTAT@ Average GS Thread Time: {:.3f} ms", s_perf_sum_gs_thread_time / s_perf_updates));
Console.WriteLn(fmt::format("@HWSTAT@ Average GPU Time: {:.3f} ms", s_perf_sum_gpu_time / s_perf_updates));
}
if (!s_stats_json_path.empty())
{
// Percentiles come from the measured per-frame series, which only exists when
// -stats-json is active. Run-aggregate min/avg/max cannot locate a spike.
std::vector<float> frame_times;
frame_times.reserve(s_frame_samples.size());
for (const FrameSample& s : s_frame_samples)
{
if (!s.idle && s.frame_ms > 0.0f)
frame_times.push_back(s.frame_ms);
}
std::sort(frame_times.begin(), frame_times.end());
Console.WriteLn(fmt::format("@HWSTAT@ Frame Time p50/p95/p99: {:.3f} / {:.3f} / {:.3f} ms",
Percentile(frame_times, 0.50), Percentile(frame_times, 0.95), Percentile(frame_times, 0.99)));
}
for (const std::string& line : s_extended_stats_snapshot)
Console.WriteLn(fmt::format("@HWSTAT@ {}", line));
Console.WriteLn("============================================");
if (!s_stats_json_path.empty())
WriteStatsJson(s_stats_json_path);
}
#ifdef _WIN32
+8
View File
@@ -77,6 +77,7 @@ struct GSSWThreadStats
std::vector<GSSWThreadStats> s_gs_sw_threads;
static float s_average_gpu_time = 0.0f;
static float s_last_gpu_time = 0.0f;
static float s_accumulated_gpu_time = 0.0f;
static float s_gpu_usage = 0.0f;
static u32 s_presents_since_last_update = 0;
@@ -106,6 +107,7 @@ void PerformanceMetrics::Clear()
s_capture_thread_time = 0.0f;
s_average_gpu_time = 0.0f;
s_last_gpu_time = 0.0f;
s_gpu_usage = 0.0f;
s_frame_number = 0;
@@ -275,6 +277,7 @@ void PerformanceMetrics::Update(bool gs_register_write, bool fb_blit, bool is_sk
void PerformanceMetrics::OnGPUPresent(float gpu_time, u64 vs_invocations, u64 ps_invocations)
{
s_last_gpu_time = gpu_time;
s_accumulated_gpu_time += gpu_time;
s_accumulated_gpu_vs_invocations += vs_invocations;
s_accumulated_gpu_ps_invocations += ps_invocations;
@@ -409,6 +412,11 @@ float PerformanceMetrics::GetGPUAverageTime()
return s_average_gpu_time;
}
float PerformanceMetrics::GetLastGPUTime()
{
return s_last_gpu_time;
}
double PerformanceMetrics::GetGPUAverageVSInvocations()
{
return s_average_gpu_vs_invocations;
+3
View File
@@ -61,6 +61,9 @@ namespace PerformanceMetrics
float GetGPUUsage();
float GetGPUAverageTime();
/// GPU time for the most recent present only, not a window average. Used by the
/// per-frame stats series, where an averaged value would hide the spike.
float GetLastGPUTime();
double GetGPUAverageVSInvocations();
double GetGPUAveragePSInvocations();