PerformanceMetrics: count the GS back thread

Under GSBackThreadMode >= Lockstep roughly half the GS work moves to a second
thread, and every surface that reports GS cost -- OSD, PerfLog, the Qt status
bar, PINE stats, gsrunner's @HWSTAT@ block -- measured the MTGS thread alone.
So the split read as a large GS saving. It is not: on a Rogue Galaxy savestate
here, mode 0 costs 15.8% / 2.63 ms and mode 3 costs 17.0% / 2.84 ms plus
14.2% / 2.37 ms on the back thread -- about twice the total GS CPU time, bought
to halve the critical path. That is a real trade, but nobody could see it.

The back thread registers its own handle at entry, as the SW rasterizer workers
do; StopBackThread clears it after the join. Unlike every other handle here it
is written by a thread other than the one sampling it, so the handle and its
running total sit behind a mutex taken twice a second. Installing a handle
rebases the total off it, so the first window after a GSreopen respawn measures
the new thread rather than its difference against the retired one's.

The figure is omitted, not reported as zero, wherever a back thread does not
exist -- otherwise a mode 0 vs mode 3 comparison reads a permanent 0% as
meaningful. gsrunner latches the presence flag during the run because DumpStats
executes after VMManager::Shutdown, by which point the thread has joined.
This commit is contained in:
Brian Degenhardt
2026-07-30 21:55:58 -07:00
parent 975e408ed5
commit 7f93a80dd7
7 changed files with 122 additions and 3 deletions
+15
View File
@@ -182,6 +182,11 @@ static float s_perf_sum_cpu_thread_usage = 0.0f;
static float s_perf_sum_cpu_thread_time = 0.0f;
static float s_perf_sum_gs_thread_usage = 0.0f;
static float s_perf_sum_gs_thread_time = 0.0f;
static float s_perf_sum_gs_back_thread_usage = 0.0f;
static float s_perf_sum_gs_back_thread_time = 0.0f;
// Latched during the run: DumpStats() runs after VMManager::Shutdown(), by which point the
// back thread has joined and PerformanceMetrics would report it as never having existed.
static bool s_perf_saw_gs_back_thread = false;
static float s_perf_sum_gpu_time = 0.0f;
static float s_perf_sum_gpu_usage = 0.0f;
@@ -460,6 +465,9 @@ void Host::OnPerformanceMetricsUpdated()
s_perf_sum_cpu_thread_time += PerformanceMetrics::GetCPUThreadAverageTime();
s_perf_sum_gs_thread_usage += PerformanceMetrics::GetGSThreadUsage();
s_perf_sum_gs_thread_time += PerformanceMetrics::GetGSThreadAverageTime();
s_perf_sum_gs_back_thread_usage += PerformanceMetrics::GetGSBackThreadUsage();
s_perf_sum_gs_back_thread_time += PerformanceMetrics::GetGSBackThreadAverageTime();
s_perf_saw_gs_back_thread |= PerformanceMetrics::HasGSBackThread();
s_perf_sum_gpu_time += PerformanceMetrics::GetGPUAverageTime();
s_perf_sum_gpu_usage += PerformanceMetrics::GetGPUUsage();
}
@@ -1309,9 +1317,16 @@ void GSRunner::DumpStats()
Console.WriteLn(fmt::format("@HWSTAT@ Maximum Frame Time: {:.3f} ms ({:.3f} FPS)", PerformanceMetrics::GetMaximumFrameTime(), 1000.0f / PerformanceMetrics::GetMaximumFrameTime()));
Console.WriteLn(fmt::format("@HWSTAT@ CPU Thread Usage: {:.3f} %", s_perf_sum_cpu_thread_usage / s_perf_updates));
Console.WriteLn(fmt::format("@HWSTAT@ GS Thread Usage: {:.3f} %", s_perf_sum_gs_thread_usage / s_perf_updates));
// Only emitted under GSBackThreadMode >= Lockstep. Omitted rather than reported as a
// flat zero, so a comparison across the two configurations doesn't read as a GS win
// that is really work moved onto an unlisted thread.
if (s_perf_saw_gs_back_thread)
Console.WriteLn(fmt::format("@HWSTAT@ GS Back Thread Usage: {:.3f} %", s_perf_sum_gs_back_thread_usage / s_perf_updates));
Console.WriteLn(fmt::format("@HWSTAT@ GPU Usage: {:.3f} %", s_perf_sum_gpu_usage / s_perf_updates));
Console.WriteLn(fmt::format("@HWSTAT@ Average CPU Thread Time: {:.3f} ms", s_perf_sum_cpu_thread_time / s_perf_updates));
Console.WriteLn(fmt::format("@HWSTAT@ Average GS Thread Time: {:.3f} ms", s_perf_sum_gs_thread_time / s_perf_updates));
if (s_perf_saw_gs_back_thread)
Console.WriteLn(fmt::format("@HWSTAT@ Average GS Back Thread Time: {:.3f} ms", s_perf_sum_gs_back_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())
+5
View File
@@ -1011,6 +1011,11 @@ void EmuThread::updatePerformanceMetrics(bool force)
.arg(PerformanceMetrics::GetCPUThreadUsage(), 0, 'f', 0)
.arg(PerformanceMetrics::GetGSThreadUsage(), 0, 'f', 0);
}
// The GS figure above is the MTGS thread alone; under GSBackThreadMode >= Lockstep
// roughly half the GS work runs on a second thread this line would otherwise hide.
if (PerformanceMetrics::HasGSBackThread())
gs_stat += tr(" | GSB: %1%").arg(PerformanceMetrics::GetGSBackThreadUsage(), 0, 'f', 0);
}
QMetaObject::invokeMethod(g_main_window, "setStatusVerboseText", Qt::QueuedConnection, Q_ARG(const QString&, gs_stat));
+10 -1
View File
@@ -7,6 +7,7 @@
#include "GS/GSPerfMon.h"
#include "GS/GSUtil.h"
#include "GS/GSVertexKick.h"
#include "PerformanceMetrics.h"
#include "common/Console.h"
#include "common/BitUtils.h"
@@ -678,6 +679,7 @@ void GSState::StopBackThread()
m_back_thread_exit.store(true, std::memory_order_release);
m_chan->sema.NotifyOfWork();
m_back_thread.join();
PerformanceMetrics::SetGSBackThread({});
m_chan->consumer_running = false;
m_back_queued = false;
}
@@ -694,13 +696,20 @@ void GSState::BackThreadLoop()
{
Threading::SetNameOfCurrentThread("GS Back");
Threading::ThreadHandle handle(Threading::ThreadHandle::GetForCallingThread());
// A new thread inherits the spawner's affinity mask, and the spawner here is
// the MTGS thread — which EnableThreadPinning may have pinned to a single
// core (always the case when the back thread is respawned via GSreopen).
// Sharing that one core would time-slice front and back and silently
// re-serialize the split, so clear to all cores. VMManager owns any future
// explicit pinning policy for this thread.
Threading::ThreadHandle::GetForCallingThread().SetAffinity(0);
handle.SetAffinity(0);
// Half the GS work runs here under the split, and the OSD's "GS" figure is the MTGS
// thread alone — so without this the mode reads as a large GS saving that is really
// just work moved off the measured thread.
PerformanceMetrics::SetGSBackThread(std::move(handle));
for (;;)
{
+13
View File
@@ -72,6 +72,7 @@ SmallString s_hardware_info_gpu_line;
SmallString s_cpu_jit_line;
SmallString s_cpu_usage_ee_line;
SmallString s_cpu_usage_gs_line;
SmallString s_cpu_usage_gs_back_line;
SmallString s_cpu_usage_vu_line;
std::vector<SmallString> s_software_thread_lines;
SmallString s_capture_line;
@@ -638,6 +639,16 @@ __ri void ImGuiManager::DrawPerformanceOverlay(float& position_y, float scale, f
FormatProcessorStat(s_cpu_usage_gs_line, PerformanceMetrics::GetGSThreadUsage(), PerformanceMetrics::GetGSThreadAverageTime());
DRAW_LINE(osd_font, font_size, s_cpu_usage_gs_line.c_str(), OsdTextColor());
// Only exists under GSBackThreadMode >= Lockstep. The line above is the MTGS
// thread alone, so without this one the split's second half is invisible.
if (PerformanceMetrics::HasGSBackThread())
{
s_cpu_usage_gs_back_line.assign("GSB: ");
FormatProcessorStat(s_cpu_usage_gs_back_line, PerformanceMetrics::GetGSBackThreadUsage(),
PerformanceMetrics::GetGSBackThreadAverageTime());
DRAW_LINE(osd_font, font_size, s_cpu_usage_gs_back_line.c_str(), OsdTextColor());
}
if (THREAD_VU1)
{
s_cpu_usage_vu_line.assign("VU: ");
@@ -742,6 +753,8 @@ __ri void ImGuiManager::DrawPerformanceOverlay(float& position_y, float scale, f
#endif
DRAW_LINE(osd_font, font_size, s_cpu_usage_ee_line.c_str(), OsdTextColor());
DRAW_LINE(osd_font, font_size, s_cpu_usage_gs_line.c_str(), OsdTextColor());
if (PerformanceMetrics::HasGSBackThread())
DRAW_LINE(osd_font, font_size, s_cpu_usage_gs_back_line.c_str(), OsdTextColor());
if (THREAD_VU1)
DRAW_LINE(osd_font, font_size, s_cpu_usage_vu_line.c_str(), OsdTextColor());
+4
View File
@@ -358,6 +358,7 @@ namespace PINEServer
"\"frame_ms_avg\":{:.3f},\"frame_ms_min\":{:.3f},\"frame_ms_max\":{:.3f},"
"\"cpu_thread_pct\":{:.3f},\"cpu_thread_ms\":{:.3f},"
"\"gs_thread_pct\":{:.3f},\"gs_thread_ms\":{:.3f},"
"\"gs_back_thread_pct\":{:.3f},\"gs_back_thread_ms\":{:.3f},"
"\"vu_thread_pct\":{:.3f},\"vu_thread_ms\":{:.3f},"
"\"gpu_pct\":{:.3f},\"gpu_ms_avg\":{:.3f},\"gpu_ms_last\":{:.3f},"
"\"gpu_vs_invocations\":{:.0f},\"gpu_ps_invocations\":{:.0f},"
@@ -376,6 +377,9 @@ namespace PINEServer
PerformanceMetrics::GetMaximumFrameTime(),
PerformanceMetrics::GetCPUThreadUsage(), PerformanceMetrics::GetCPUThreadAverageTime(),
PerformanceMetrics::GetGSThreadUsage(), PerformanceMetrics::GetGSThreadAverageTime(),
// Zero unless GSBackThreadMode >= Lockstep. gs_thread_* is the MTGS thread only,
// so under the split the two have to be read together to see the GS cost.
PerformanceMetrics::GetGSBackThreadUsage(), PerformanceMetrics::GetGSBackThreadAverageTime(),
PerformanceMetrics::GetVUThreadUsage(), PerformanceMetrics::GetVUThreadAverageTime(),
PerformanceMetrics::GetGPUUsage(), PerformanceMetrics::GetGPUAverageTime(),
PerformanceMetrics::GetLastGPUTime(),
+64 -2
View File
@@ -2,6 +2,8 @@
// SPDX-License-Identifier: GPL-3.0+
#include <chrono>
#include <cstdio>
#include <mutex>
#include <vector>
#include "common/Console.h"
@@ -61,10 +63,31 @@ static u32 s_gs_privileged_register_writes_since_last_update = 0;
static Threading::ThreadHandle s_cpu_thread_handle;
static u64 s_last_cpu_time = 0;
static u64 s_last_gs_time = 0;
static u64 s_last_gs_back_time = 0;
static u64 s_last_vu_time = 0;
static u64 s_last_capture_time = 0;
static u64 s_last_ticks = 0;
// The GS back thread registers itself from its own entry point and is cleared from the MTGS
// thread after the join, so unlike every other handle here this one is written by a thread
// other than the one sampling it. Handle and running total are therefore both owned by the
// mutex, which is taken twice a second at most.
static std::mutex s_gs_back_thread_mutex;
static Threading::ThreadHandle s_gs_back_thread_handle;
/// CPU time consumed by the back thread since the last call, in Threading tick units.
/// A thread that started or stopped inside the window contributes only the part of it that
/// the handle was installed for; the alternative is a u64 subtraction that wraps into a
/// nonsense percentage on the first window after a GSreopen.
static u64 SampleGSBackThreadCPUTime()
{
std::unique_lock lock(s_gs_back_thread_mutex);
const u64 now = s_gs_back_thread_handle ? s_gs_back_thread_handle.GetCPUTime() : s_last_gs_back_time;
const u64 delta = (now > s_last_gs_back_time) ? (now - s_last_gs_back_time) : 0;
s_last_gs_back_time = now;
return delta;
}
#if defined(__ANDROID__)
// ---- Android ADPF (PerformanceHintManager) ---------------------------------
// Tells the OS "these threads produce a frame every N ns, clock them to hit it."
@@ -166,6 +189,8 @@ static double s_cpu_thread_usage = 0.0f;
static double s_cpu_thread_time = 0.0f;
static float s_gs_thread_usage = 0.0f;
static float s_gs_thread_time = 0.0f;
static float s_gs_back_thread_usage = 0.0f;
static float s_gs_back_thread_time = 0.0f;
static float s_vu_thread_usage = 0.0f;
static float s_vu_thread_time = 0.0f;
static float s_capture_thread_usage = 0.0f;
@@ -208,6 +233,8 @@ void PerformanceMetrics::Clear()
s_cpu_thread_time = 0.0f;
s_gs_thread_usage = 0.0f;
s_gs_thread_time = 0.0f;
s_gs_back_thread_usage = 0.0f;
s_gs_back_thread_time = 0.0f;
s_vu_thread_usage = 0.0f;
s_vu_thread_time = 0.0f;
s_capture_thread_usage = 0.0f;
@@ -255,6 +282,7 @@ void PerformanceMetrics::Reset()
s_last_cpu_time = s_cpu_thread_handle.GetCPUTime();
s_last_gs_time = MTGS::GetThreadHandle().GetCPUTime();
SampleGSBackThreadCPUTime(); // rebases the running total; the delta is deliberately dropped
s_last_vu_time = THREAD_VU1 ? vu1Thread.GetThreadHandle().GetCPUTime() : 0;
s_last_ticks = GetCPUTicks();
s_last_capture_time = GSCapture::IsCapturing() ? GSCapture::GetEncoderThreadHandle().GetCPUTime() : 0;
@@ -332,6 +360,7 @@ void PerformanceMetrics::Update(bool gs_register_write, bool fb_blit, bool is_sk
const u64 cpu_time = s_cpu_thread_handle.GetCPUTime();
const u64 gs_time = MTGS::GetThreadHandle().GetCPUTime();
const u64 gs_back_delta = SampleGSBackThreadCPUTime();
const u64 vu_time = THREAD_VU1 ? vu1Thread.GetThreadHandle().GetCPUTime() : 0;
const u64 capture_time = GSCapture::IsCapturing() ? GSCapture::GetEncoderThreadHandle().GetCPUTime() : 0;
@@ -346,10 +375,12 @@ void PerformanceMetrics::Update(bool gs_register_write, bool fb_blit, bool is_sk
s_cpu_thread_usage = static_cast<double>(cpu_delta) * pct_divider;
s_gs_thread_usage = static_cast<double>(gs_delta) * pct_divider;
s_gs_back_thread_usage = static_cast<double>(gs_back_delta) * pct_divider;
s_vu_thread_usage = static_cast<double>(vu_delta) * pct_divider;
s_capture_thread_usage = static_cast<double>(capture_delta) * pct_divider;
s_cpu_thread_time = static_cast<double>(cpu_delta) * time_divider;
s_gs_thread_time = static_cast<double>(gs_delta) * time_divider;
s_gs_back_thread_time = static_cast<double>(gs_back_delta) * time_divider;
s_vu_thread_time = static_cast<double>(vu_delta) * time_divider;
s_capture_thread_time = static_cast<double>(capture_delta) * time_divider;
@@ -367,9 +398,15 @@ void PerformanceMetrics::Update(bool gs_register_write, bool fb_blit, bool is_sk
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",
// The back thread only exists under GSBackThreadMode >= Lockstep, so the field is
// omitted rather than logged as a permanent 0% in the default configuration.
char gs_back[32] = {};
if (HasGSBackThread())
std::snprintf(gs_back, sizeof(gs_back), " GSB %.0f%%", s_gs_back_thread_usage);
Console.WriteLn("PerfLog: %.1f fps | EE %.0f%% GS %.0f%%%s 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,
s_gs_thread_usage, gs_back, 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;
@@ -530,6 +567,15 @@ void PerformanceMetrics::SetGSSWThread(u32 index, Threading::ThreadHandle thread
s_gs_sw_threads[index].handle = std::move(thread);
}
void PerformanceMetrics::SetGSBackThread(Threading::ThreadHandle thread)
{
std::unique_lock lock(s_gs_back_thread_mutex);
// Rebase off the incoming handle, so the first window after a GSreopen respawn measures
// this thread's time rather than its difference against the retired thread's total.
s_last_gs_back_time = thread ? thread.GetCPUTime() : 0;
s_gs_back_thread_handle = std::move(thread);
}
u64 PerformanceMetrics::GetFrameNumber()
{
return s_frame_number;
@@ -595,6 +641,22 @@ float PerformanceMetrics::GetGSThreadAverageTime()
return s_gs_thread_time;
}
bool PerformanceMetrics::HasGSBackThread()
{
std::unique_lock lock(s_gs_back_thread_mutex);
return static_cast<bool>(s_gs_back_thread_handle);
}
float PerformanceMetrics::GetGSBackThreadUsage()
{
return s_gs_back_thread_usage;
}
float PerformanceMetrics::GetGSBackThreadAverageTime()
{
return s_gs_back_thread_time;
}
float PerformanceMetrics::GetVUThreadUsage()
{
return s_vu_thread_usage;
+11
View File
@@ -55,6 +55,13 @@ namespace PerformanceMetrics
void SetGSSWThreadCount(u32 count);
void SetGSSWThread(u32 index, Threading::ThreadHandle thread);
/// Sets the timer for the GS back thread (GSBackThreadMode >= Lockstep). Registered by
/// the back thread itself at entry and cleared once it has joined; an empty handle means
/// no such thread exists, which is the default configuration. Under the pipelined split
/// the GS work is roughly halved between this thread and the MTGS thread, so the plain
/// "GS" figure alone reads as a ~50% drop in GS cost that never happened.
void SetGSBackThread(Threading::ThreadHandle thread);
u64 GetFrameNumber();
InternalFPSMethod GetInternalFPSMethod();
@@ -71,6 +78,10 @@ namespace PerformanceMetrics
double GetCPUThreadAverageTime();
float GetGSThreadUsage();
float GetGSThreadAverageTime();
/// True while a GS back thread is registered. Both figures below read zero when it is not.
bool HasGSBackThread();
float GetGSBackThreadUsage();
float GetGSBackThreadAverageTime();
float GetVUThreadUsage();
float GetVUThreadAverageTime();
float GetCaptureThreadUsage();