IR JIT: Time compilation, and log frames that spend long compiling

Totals per phase (frontend, passes, backend, finalize/linking, invalidation and
full clears) go in the JIT stats overlay, and the frame graph draws each frame's
compile time in orange at the bottom of its bar. A frame that spends 2 ms or
more compiling logs a "JIT stall" line with the breakdown.

Each phase boundary reads the clock once, since that costs around 0.3 us on a
Galaxy S8.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Common/TimeUtil.cpp

@@ -164,6 +164,10 @@ int64_t Instant::ElapsedNanos() const {
 	return (int64_t)(ElapsedSeconds() * 1000000000.0);
 }
 
+int64_t Instant::NanosSince(const Instant &earlier) const {
+	return (int64_t)((double)(int64_t)(nativeStart_ - earlier.nativeStart_) * frequencyMult * 1000000000.0);
+}
+
 #else
 
 // Monotonic, in nanoseconds, and the clock VK_GOOGLE_display_timing reports in.
@@ -242,6 +246,10 @@ int64_t Instant::ElapsedNanos() const {
 	return (int64_t)(time_now_raw() - nativeStart_);
 }
 
+int64_t Instant::NanosSince(const Instant &earlier) const {
+	return (int64_t)(nativeStart_ - earlier.nativeStart_);
+}
+
 double Instant::ElapsedSeconds() const {
 	return (double)ElapsedNanos() * (1.0 / nanos);
 }

Common/TimeUtil.h

@@ -49,6 +49,8 @@ public:
 	double ElapsedSeconds() const;
 	double ElapsedMs() const { return ElapsedSeconds() * 1000.0; }
 	int64_t ElapsedNanos() const;
+	// From an earlier Instant to this one, without reading the clock again.
+	int64_t NanosSince(const Instant &earlier) const;
 private:
 	// Windows: raw QPC ticks. Everything else: nanoseconds, from time_now_raw().
 	uint64_t nativeStart_;

Core/HW/Display.cpp

@@ -21,6 +21,7 @@
 #include <mutex>
 #include <vector>
 #include "Common/CommonTypes.h"
+#include "Common/Log.h"
 #include "Common/Serialize/SerializeFuncs.h"
 #include "Common/System/System.h"
 #include "Common/TimeUtil.h"
@@ -28,6 +29,7 @@
 #include "Core/Config.h"
 #include "Core/System.h"
 #include "Core/MIPS/MIPS.h"
+#include "Core/MIPS/JitCommon/JitCommon.h"
 #include "Core/CoreTiming.h"
 #include "Core/HLE/sceKernel.h"
 #include "Core/HLE/sceCtrl.h"
@@ -71,13 +73,39 @@ static int fpsHistoryValid = 0;
 // Frame time stats.
 static float frameTimeHistory[600];
 static float frameSleepHistory[600];
+static float frameJitHistory[600];
 static constexpr int frameTimeHistorySize = (int)ARRAY_SIZE(frameTimeHistory);
 static int frameTimeHistoryPos = 0;
 static int frameTimeHistoryValid = 0;
 static double lastFrameTimeHistory = 0.0;
 
+// JIT compile time in the frame since the last flip, from the running totals.
+static MIPSComp::JitCompileTimes lastFlipJitTimes;
+static double lastFlipTime = 0.0;
+// Frames that spend this long compiling are logged.
+static constexpr double JIT_STALL_LOG_SECONDS = 0.002;
+
+static double CheckJitStall(double now) {
+	const MIPSComp::JitCompileTimes &cur = MIPSComp::g_jitCompileTimes;
+	const MIPSComp::JitCompileTimes &last = lastFlipJitTimes;
+	const double jitSeconds = (cur.TotalNanos() - last.TotalNanos()) * 1e-9;
+	if (jitSeconds >= JIT_STALL_LOG_SECONDS && lastFlipTime != 0.0) {
+		INFO_LOG(Log::JIT, "JIT stall: %0.2f ms compiling in a %0.2f ms frame (%d blocks, %d MIPS instructions; frontend %0.2f, passes %0.2f, backend %0.2f, finalize %0.2f, invalidate %0.2f, %d clears %0.2f ms)",
+			jitSeconds * 1000.0, (now - lastFlipTime) * 1000.0,
+			(int)(cur.blocks - last.blocks), (int)(cur.mipsInstructions - last.mipsInstructions),
+			(cur.frontendNanos - last.frontendNanos) * 1e-6, (cur.passNanos - last.passNanos) * 1e-6,
+			(cur.backendNanos - last.backendNanos) * 1e-6, (cur.finalizeNanos - last.finalizeNanos) * 1e-6,
+			(cur.invalidateNanos - last.invalidateNanos) * 1e-6,
+			cur.clears - last.clears, (cur.clearNanos - last.clearNanos) * 1e-6);
+	}
+	lastFlipJitTimes = cur;
+	lastFlipTime = now;
+	return jitSeconds;
+}
+
 static void CalculateFPS() {
 	double now = time_now_d();
+	const double jitSeconds = CheckJitStall(now);
 
 	if (now >= lastFpsTime + 1.0) {
 		double frames = (numVBlanks - lastFpsFrame);
@@ -99,6 +127,7 @@ static void CalculateFPS() {
 	}
 
 	if ((DebugOverlay)g_Config.iDebugOverlay == DebugOverlay::FRAME_GRAPH || g_coreCollectDebugStats) {
+		frameJitHistory[frameTimeHistoryPos] = (float)jitSeconds;
 		frameTimeHistory[frameTimeHistoryPos++] = (float)(now - lastFrameTimeHistory);
 		lastFrameTimeHistory = now;
 		frameTimeHistoryPos = frameTimeHistoryPos % frameTimeHistorySize;
@@ -183,6 +212,10 @@ float *__DisplayGetFrameTimes(int *out_valid, int *out_pos, float **out_sleep) {
 	return frameTimeHistory;
 }
 
+const float *__DisplayGetFrameJitTimes() {
+	return frameJitHistory;
+}
+
 int DisplayGetSleepPos() {
 	return frameTimeHistoryPos;
 }
@@ -305,6 +338,8 @@ void DisplayHWInit() {
 	frameTimeHistoryValid = 0;
 	frameTimeHistoryPos = 0;
 	lastFrameTimeHistory = 0.0;
+	lastFlipJitTimes = MIPSComp::g_jitCompileTimes;
+	lastFlipTime = 0.0;
 }
 
 void DisplayHWShutdown() {

Core/HW/Display.h

@@ -41,6 +41,8 @@ void __DisplayGetAveragedFPS(float *out_vps, float *out_fps);
 void __DisplayGetFPS(float *out_vps, float *out_fps, float *out_actual_fps);
 void __DisplayGetVPS(float *out_vps);
 float *__DisplayGetFrameTimes(int *out_valid, int *out_pos, float **out_sleep);
+// Seconds spent in the JIT compiler each frame, indexed like __DisplayGetFrameTimes.
+const float *__DisplayGetFrameJitTimes();
 int DisplayGetSleepPos();
 void DisplayNotifySleep(double t, int pos = -1);
 bool DisplayIsRunningSlow();

Core/MIPS/IR/IRFrontend.cpp

@@ -318,6 +318,7 @@ MIPSOpcode IRFrontend::GetOffsetInstruction(int offset) {
 }
 
 void IRFrontend::DoJit(u32 em_address, std::vector<IRInst> &instructions, u32 &mipsBytes) {
+	const Instant start = Instant::Now();
 	js.cancel = false;
 	js.blockStart = em_address;
 	js.compilerPC = em_address;
@@ -354,6 +355,7 @@ void IRFrontend::DoJit(u32 em_address, std::vector<IRInst> &instructions, u32 &m
 
 	IRWriter simplified;
 	IRWriter *code = &ir;
+	Instant passStart = Instant::Now();
 	if (!js.hadBreakpoints) {
 		std::vector<IRPassFunc> passes{
 			&ApplyMemoryValidation,
@@ -392,6 +394,9 @@ void IRFrontend::DoJit(u32 em_address, std::vector<IRInst> &instructions, u32 &m
 		instructions.push_back({ IROp::LogIRBlock, {0}, 0, 0, INVALID_TRACE_INDEX });
 		std::copy(block_instructions.begin() + 1, block_instructions.end(), std::back_inserter(instructions));
 	}
+	lastEnd_ = Instant::Now();
+	lastFrontendNanos_ = passStart.NanosSince(start);
+	lastPassNanos_ = lastEnd_.NanosSince(passStart);
 
 	if (logBlocks > 0 && dontLogBlocks == 0) {
 		char temp2[256];

Core/MIPS/IR/IRFrontend.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include "Common/CommonTypes.h"
+#include "Common/TimeUtil.h"
 #include "Core/MIPS/JitCommon/JitCommon.h"
 #include "Core/MIPS/JitCommon/JitState.h"
 #include "Core/MIPS/MIPSVFPUUtils.h"
@@ -102,6 +103,10 @@ public:
 	bool CheckRounding(u32 blockAddress);  // returns true if we need a do-over
 
 	void DoJit(u32 em_address, std::vector<IRInst> &instructions, u32 &mipsBytes);
+	// How long the last DoJit spent making the IR, and running the passes over it, and when it ended.
+	int64_t LastFrontendNanos() const { return lastFrontendNanos_; }
+	int64_t LastPassNanos() const { return lastPassNanos_; }
+	const Instant &LastEnd() const { return lastEnd_; }
 
 	void EatPrefix() override {
 		js.EatPrefix();
@@ -181,6 +186,10 @@ private:
 	int dontLogBlocks = 0;
 	int logBlocks = 0;
 
+	int64_t lastFrontendNanos_ = 0;
+	int64_t lastPassNanos_ = 0;
+	Instant lastEnd_;
+
 private:
 	bool IsMediaEngine() const;
 	MIPSOpcode ReadOp(u32 addr) const;

Core/MIPS/IR/IRJit.cpp

@@ -172,8 +172,10 @@ void IRInterpreterJit::WriteProfileReport() {
 }
 
 void IRJit::InvalidateCacheAt(u32 em_address, int length) {
+	const Instant start = Instant::Now();
 	std::vector<int> numbers = blocks_.FindInvalidatedBlockNumbers(em_address, length);
 	if (numbers.empty()) {
+		g_jitCompileTimes.invalidateNanos += start.ElapsedNanos();
 		return;
 	}
 
@@ -185,6 +187,7 @@ void IRJit::InvalidateCacheAt(u32 em_address, int length) {
 		// TODO: We are invalidating a lot of blocks that are already invalid (yu gi oh).
 		InvalidateBlock(block_num);
 	}
+	g_jitCompileTimes.invalidateNanos += start.ElapsedNanos();
 }
 
 void IRJit::InvalidateBlock(int block_num) {
@@ -245,23 +248,37 @@ void IRJit::Compile(u32 em_address) {
 			ERROR_LOG(Log::JIT, "Native code space full (%d blocks), clearing cache", blocks_.GetNumBlocks());
 			codeFullClears_++;
 		}
-		ClearCache();
+		TimedClearCache();
 		CompileBlock(em_address, instructions, mipsBytes);
 	}
 
 	if (frontend_.CheckRounding(em_address)) {
 		// Our assumptions are all wrong so it's clean-slate time.
-		ClearCache();
+		TimedClearCache();
 		CompileBlock(em_address, instructions, mipsBytes);
 	}
 }
 
+void IRJit::TimedClearCache() {
+	const Instant start = Instant::Now();
+	ClearCache();
+	g_jitCompileTimes.clearNanos += start.ElapsedNanos();
+	g_jitCompileTimes.clears++;
+}
+
 // WARNING! This can be called from IRInterpret / the JIT, through the function preload stuff!
 IRJit::CompileResult IRJit::CompileBlock(u32 em_address, std::vector<IRInst> &instructions, u32 &mipsBytes) {
 	_dbg_assert_(compilerEnabled_);
 
+	JitCompileTimes &times = g_jitCompileTimes;
 	frontend_.DoJit(em_address, instructions, mipsBytes);
 	_dbg_assert_(!instructions.empty());
+	times.frontendNanos += frontend_.LastFrontendNanos();
+	times.passNanos += frontend_.LastPassNanos();
+	times.mipsInstructions += mipsBytes / 4;
+	times.irInstructions += instructions.size();
+	// Reading the clock isn't free (around 0.3us on a Galaxy S8), so each phase ends where the next starts.
+	const Instant &backendStart = frontend_.LastEnd();
 
 	if (mipsTracer.tracing_enabled && instructions.size() > 1 && instructions[1].op == IROp::LogIRBlock) {
 		// Before the IR interpreter's block cache takes its copy.
@@ -278,12 +295,20 @@ IRJit::CompileResult IRJit::CompileBlock(u32 em_address, std::vector<IRInst> &in
 
 	// Caller handles a full arena or code space.
 	const CompileResult result = CompileTargetBlock(block_num, instructions);
+	const Instant finalizeStart = Instant::Now();
+	const int64_t backendNanos = finalizeStart.NanosSince(backendStart);
+	times.backendNanos += backendNanos;
 	if (result != CompileResult::OK)
 		return result;
 
 	// Updates stats, also enters the block in the block shadow.
 	blocks_.FinalizeBlock(block_num);
 	FinalizeTargetBlock(block_num);
+	const int64_t finalizeNanos = finalizeStart.ElapsedNanos();
+	times.finalizeNanos += finalizeNanos;
+	times.blocks++;
+	const int64_t blockNanos = frontend_.LastFrontendNanos() + frontend_.LastPassNanos() + backendNanos + finalizeNanos;
+	times.maxBlockNanos = std::max(times.maxBlockNanos, blockNanos);
 	return CompileResult::OK;
 }
 

Core/MIPS/IR/IRJit.h

@@ -208,6 +208,7 @@ protected:
 		CODE_FULL,
 	};
 	CompileResult CompileBlock(u32 em_address, std::vector<IRInst> &instructions, u32 &mipsBytes);
+	void TimedClearCache();
 	// Makes the allocated block runnable, and sets its entry.
 	virtual CompileResult CompileTargetBlock(int block_num, const std::vector<IRInst> &instructions) = 0;
 	// For the debugger: the IR the block was compiled from, the size of what it compiled to (for the

Core/MIPS/JitCommon/JitCommon.cpp

@@ -51,6 +51,8 @@
 #endif
 
 namespace MIPSComp {
+	JitCompileTimes g_jitCompileTimes;
+
 	void JitAt(MIPSState *mips) {
 		// TODO: We could probably check for a bad pc here, and fire an exception. Could spare us from some crashes.
 		// Although, we just tried to load from this address to check for a JIT block, and if we're here, that succeeded..

Core/MIPS/JitCommon/JitCommon.h

@@ -134,6 +134,26 @@ namespace MIPSComp {
 		int invalidatedBlocks = 0;
 	};
 
+	// Time spent compiling, totalled since startup. The IR JITs fill it in.
+	struct JitCompileTimes {
+		int64_t frontendNanos = 0;  // MIPS to IR
+		int64_t passNanos = 0;  // The IR passes
+		int64_t backendNanos = 0;  // IR to host code, or into the IR arena
+		int64_t finalizeNanos = 0;  // The block table and linking
+		int64_t clearNanos = 0;  // Clearing the whole cache
+		int64_t invalidateNanos = 0;
+		int64_t maxBlockNanos = 0;
+		int64_t blocks = 0;
+		int64_t mipsInstructions = 0;
+		int64_t irInstructions = 0;  // After the passes
+		int clears = 0;
+
+		int64_t TotalNanos() const {
+			return frontendNanos + passNanos + backendNanos + finalizeNanos + clearNanos + invalidateNanos;
+		}
+	};
+	extern JitCompileTimes g_jitCompileTimes;
+
 	class JitInterface {
 	public:
 		virtual ~JitInterface() {}

UI/DebugOverlay.cpp

@@ -86,6 +86,18 @@ static void DrawJitStats(UIContext *ctx, const Bounds &bounds) {
 			w.F("Cleared because full: %d\n", stats.irArenaFullClears);
 		}
 		w.F("Invalidations: %d (%d blocks)\n", stats.invalidations, stats.invalidatedBlocks);
+
+		const MIPSComp::JitCompileTimes &t = MIPSComp::g_jitCompileTimes;
+		if (t.blocks > 0) {
+			const double perBlock = 1e-3 / t.blocks;  // ns -> us per block
+			w.F("Compiled %lld blocks, %lld MIPS -> %lld IR instructions, %0.1f ms\n",
+				(long long)t.blocks, (long long)t.mipsInstructions, (long long)t.irInstructions, t.TotalNanos() * 1e-6);
+			w.F("Per block (us): frontend %0.1f, passes %0.1f, backend %0.1f, finalize %0.1f, slowest %0.1f\n",
+				t.frontendNanos * perBlock, t.passNanos * perBlock, t.backendNanos * perBlock, t.finalizeNanos * perBlock,
+				t.maxBlockNanos * 1e-3);
+			w.F("Per MIPS instruction: %0.2f us\n", t.TotalNanos() * 1e-3 / std::max<int64_t>(1, t.mipsInstructions));
+			w.F("Invalidation: %0.1f ms, full clears: %d, %0.1f ms\n", t.invalidateNanos * 1e-6, t.clears, t.clearNanos * 1e-6);
+		}
 	} else {
 		w.W("No JIT (interpreter)\n");
 	}
@@ -146,6 +158,7 @@ static void DrawFrameTimes(UIContext *ctx, const Bounds &bounds) {
 	float *sleepHistory;
 	int valid, pos;
 	float *history = __DisplayGetFrameTimes(&valid, &pos, &sleepHistory);
+	const float *jitHistory = __DisplayGetFrameJitTimes();
 	int scale = 7000;
 	int width = 600;
 
@@ -154,7 +167,10 @@ static void DrawFrameTimes(UIContext *ctx, const Bounds &bounds) {
 	int bottom = bounds.y2();
 	for (int i = 0; i < valid; ++i) {
 		double activeTime = history[i] - sleepHistory[i];
-		ctx->Draw()->vLine(bounds.x + i, bottom, bottom - activeTime * scale, 0xFF3FFF3F);
+		// JIT compile time at the bottom, in orange.
+		double jitTime = std::min((double)jitHistory[i], activeTime);
+		ctx->Draw()->vLine(bounds.x + i, bottom, bottom - jitTime * scale, 0xFF3F9FFF);
+		ctx->Draw()->vLine(bounds.x + i, bottom - jitTime * scale, bottom - activeTime * scale, 0xFF3FFF3F);
 		ctx->Draw()->vLine(bounds.x + i, bottom - activeTime * scale, bottom - history[i] * scale, 0x7F3FFF3F);
 	}
 	ctx->Draw()->vLine(bounds.x + pos, bottom, bottom - 512, 0xFFff3F3f);