From 6860e78bf7d6e0c1642e4b981a07c3265a41bebc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Tue, 10 Nov 2026 19:14:08 +0100 Subject: [PATCH] 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 --- Common/TimeUtil.cpp | 8 +++++++ Common/TimeUtil.h | 2 ++ Core/HW/Display.cpp | 35 +++++++++++++++++++++++++++++++ Core/HW/Display.h | 2 ++ Core/MIPS/IR/IRFrontend.cpp | 5 +++++ Core/MIPS/IR/IRFrontend.h | 9 ++++++++ Core/MIPS/IR/IRJit.cpp | 29 +++++++++++++++++++++++-- Core/MIPS/IR/IRJit.h | 1 + Core/MIPS/JitCommon/JitCommon.cpp | 2 ++ Core/MIPS/JitCommon/JitCommon.h | 20 ++++++++++++++++++ UI/DebugOverlay.cpp | 18 +++++++++++++++- 11 files changed, 128 insertions(+), 3 deletions(-) diff --git a/Common/TimeUtil.cpp b/Common/TimeUtil.cpp index a33938b926..1c4be68bde 100644 --- a/Common/TimeUtil.cpp +++ b/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); } diff --git a/Common/TimeUtil.h b/Common/TimeUtil.h index 8d6fca0b5c..9c90788fc0 100644 --- a/Common/TimeUtil.h +++ b/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_; diff --git a/Core/HW/Display.cpp b/Core/HW/Display.cpp index e09ea44205..39cc4c4e67 100644 --- a/Core/HW/Display.cpp +++ b/Core/HW/Display.cpp @@ -21,6 +21,7 @@ #include #include #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() { diff --git a/Core/HW/Display.h b/Core/HW/Display.h index 75c6278942..c233eedfa9 100644 --- a/Core/HW/Display.h +++ b/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(); diff --git a/Core/MIPS/IR/IRFrontend.cpp b/Core/MIPS/IR/IRFrontend.cpp index c8d2ae5742..e6d2116ed5 100644 --- a/Core/MIPS/IR/IRFrontend.cpp +++ b/Core/MIPS/IR/IRFrontend.cpp @@ -318,6 +318,7 @@ MIPSOpcode IRFrontend::GetOffsetInstruction(int offset) { } void IRFrontend::DoJit(u32 em_address, std::vector &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 &instructions, u32 &m IRWriter simplified; IRWriter *code = &ir; + Instant passStart = Instant::Now(); if (!js.hadBreakpoints) { std::vector passes{ &ApplyMemoryValidation, @@ -392,6 +394,9 @@ void IRFrontend::DoJit(u32 em_address, std::vector &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]; diff --git a/Core/MIPS/IR/IRFrontend.h b/Core/MIPS/IR/IRFrontend.h index f69b127a08..21b7adb001 100644 --- a/Core/MIPS/IR/IRFrontend.h +++ b/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 &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; diff --git a/Core/MIPS/IR/IRJit.cpp b/Core/MIPS/IR/IRJit.cpp index ecc8398401..8eb9b6313d 100644 --- a/Core/MIPS/IR/IRJit.cpp +++ b/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 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 &instructions, u32 &mipsBytes) { _dbg_assert_(compilerEnabled_); + JitCompileTimes × = 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 &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; } diff --git a/Core/MIPS/IR/IRJit.h b/Core/MIPS/IR/IRJit.h index f0990d814f..73be3a0749 100644 --- a/Core/MIPS/IR/IRJit.h +++ b/Core/MIPS/IR/IRJit.h @@ -208,6 +208,7 @@ protected: CODE_FULL, }; CompileResult CompileBlock(u32 em_address, std::vector &instructions, u32 &mipsBytes); + void TimedClearCache(); // Makes the allocated block runnable, and sets its entry. virtual CompileResult CompileTargetBlock(int block_num, const std::vector &instructions) = 0; // For the debugger: the IR the block was compiled from, the size of what it compiled to (for the diff --git a/Core/MIPS/JitCommon/JitCommon.cpp b/Core/MIPS/JitCommon/JitCommon.cpp index 6ddd4ae5cc..7fc9aeb748 100644 --- a/Core/MIPS/JitCommon/JitCommon.cpp +++ b/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.. diff --git a/Core/MIPS/JitCommon/JitCommon.h b/Core/MIPS/JitCommon/JitCommon.h index 6235c4a790..756290e22a 100644 --- a/Core/MIPS/JitCommon/JitCommon.h +++ b/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() {} diff --git a/UI/DebugOverlay.cpp b/UI/DebugOverlay.cpp index d7beceb2fa..495ab33b0d 100644 --- a/UI/DebugOverlay.cpp +++ b/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(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);