From 377fa492b32580595e6342a1ef2047057d50d43c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 09:16:15 +0100 Subject: [PATCH 1/9] Profiler: Record per-thread event timelines, and add timeline and graph windows The frame profiler kept its state in 4 thread slots, and every thread after the fourth shared the last one's nesting depth and stack without locking. Several threads entering and leaving scopes at once corrupted the depth, which then indexed outside the arrays and crashed. Now each thread that enters a scope gets a lane of its own: a ring of begin and end events that only it writes. A thread that exits hands its lane to the next new one; lanes are never freed, so readers can walk them without locks, and a reader checks that an event wasn't overwritten while it copied it. A literal scope name is looked up once per call site. The per-frame totals (time in each category, not counting nested scopes) are worked out from the events at each frame end, so the on-screen overlay keeps working. The ImGui debugger gets a CPU profiler window, with a zoomable timeline of each thread's scopes and frame ends plus a table of per-frame totals, and a Frame profile window with the overlay's graph, per thread. The Vulkan render thread has scopes for rendering, submitting and presenting. Co-Authored-By: Claude Opus 5.5 --- Common/GPU/Vulkan/VulkanRenderManager.cpp | 13 +- Common/Profiler/Profiler.cpp | 515 ++++++++++++++-------- Common/Profiler/Profiler.h | 83 +++- GPU/Common/SplineCommon.cpp | 2 +- UI/CMakeLists.txt | 2 + UI/ImDebugger/ImDebugger.cpp | 16 + UI/ImDebugger/ImDebugger.h | 2 + UI/ImDebugger/ImProfiler.cpp | 417 ++++++++++++++++++ UI/ImDebugger/ImProfiler.h | 8 + UI/UI.vcxproj | 2 + UI/UI.vcxproj.filters | 6 + UWP/UI_UWP/UI_UWP.vcxproj | 2 + UWP/UI_UWP/UI_UWP.vcxproj.filters | 6 + android/jni/Android.mk | 1 + unittest/UnitTest.cpp | 97 ++++ 15 files changed, 959 insertions(+), 213 deletions(-) create mode 100644 UI/ImDebugger/ImProfiler.cpp create mode 100644 UI/ImDebugger/ImProfiler.h diff --git a/Common/GPU/Vulkan/VulkanRenderManager.cpp b/Common/GPU/Vulkan/VulkanRenderManager.cpp index 033db37843..8632a5423d 100644 --- a/Common/GPU/Vulkan/VulkanRenderManager.cpp +++ b/Common/GPU/Vulkan/VulkanRenderManager.cpp @@ -5,6 +5,7 @@ #include #include "Common/Log.h" +#include "Common/Profiler/Profiler.h" #include "Common/StringUtils.h" #include "Common/TimeUtil.h" @@ -1893,6 +1894,7 @@ void VulkanRenderManager::Run(VKRRenderThreadTask &task) { FrameData &frameData = frameData_[task.frame]; if (task.runType == VKRRunType::PRESENT) { + PROFILE_THIS_SCOPE("vk_present"); if (!frameData.skipSwap) { VkResult res = frameData.QueuePresent(vulkan_, frameDataShared_); frameTimeHistory_[frameData.frameId].queuePresent = time_now_d(); @@ -1932,6 +1934,7 @@ void VulkanRenderManager::Run(VKRRenderThreadTask &task) { _dbg_assert_(!frameData.hasPresentCommands); + PROFILE_THIS_SCOPE("vk_render"); if (!frameTimeHistory_[frameData.frameId].firstSubmit) { frameTimeHistory_[frameData.frameId].firstSubmit = time_now_d(); } @@ -1955,10 +1958,14 @@ void VulkanRenderManager::Run(VKRRenderThreadTask &task) { FlushDescriptors(task.frame); frameData.profile.descWriteTime = time_now_d() - descStart; - queueRunner_.PreprocessSteps(task.steps); - //queueRunner_.LogSteps(stepsOnThread, false); - queueRunner_.RunSteps(task.steps, task.frame, frameData, frameDataShared_); + { + PROFILE_THIS_SCOPE("vk_steps"); + queueRunner_.PreprocessSteps(task.steps); + //queueRunner_.LogSteps(stepsOnThread, false); + queueRunner_.RunSteps(task.steps, task.frame, frameData, frameDataShared_); + } + PROFILE_THIS_SCOPE("vk_submit"); switch (task.runType) { case VKRRunType::SUBMIT: // A frame that never drew to the backbuffer never acquired an image, so there's nothing to diff --git a/Common/Profiler/Profiler.cpp b/Common/Profiler/Profiler.cpp index 0b41fa9c3a..8e44d9a7cf 100644 --- a/Common/Profiler/Profiler.cpp +++ b/Common/Profiler/Profiler.cpp @@ -1,263 +1,394 @@ -// Ultra-lightweight category profiler with history. +// Frame profiler: per-thread event rings, with per-frame totals worked out from them. -#include -#include +#include +#include #include +#include #include "ppsspp_config.h" -#include "Common/Render/DrawBuffer.h" - -#include "Common/TimeUtil.h" #include "Common/Profiler/Profiler.h" + +#ifdef USE_PROFILER + #include "Common/Log.h" +#include "Common/StringUtils.h" +#include "Common/Thread/ThreadUtil.h" +#include "Common/TimeUtil.h" -#define MAX_CATEGORIES 64 // Can be any number, represents max profiled names. -#define MAX_DEPTH 16 // Can be any number, represents max nesting depth of profiled names. -#if PPSSPP_PLATFORM(IOS) && defined(__IPHONE_OS_VERSION_MIN_REQUIRED) && __IPHONE_OS_VERSION_MIN_REQUIRED < __IPHONE_9_0 -// iOS did not support C++ thread_local before iOS 9 -#define MAX_THREADS 1 // Can be any number, represents concurrent threads calling the profiler. -#else -#define MAX_THREADS 4 // Can be any number, represents concurrent threads calling the profiler. -#endif -#define HISTORY_SIZE 128 // Must be power of 2 +#define MAX_CATEGORIES 64 // Names past this aren't recorded. +#define MAX_LANES 32 // Threads recording at once. Past this, a thread isn't recorded. +#define MAX_DEPTH 32 // Deeper scopes are recorded at this level. +#define LANE_EVENTS 16384 // Must be a power of 2. 256 KB a thread. +#define HISTORY_SIZE 128 // Must be a power of 2. -#ifndef _DEBUG -// If the compiler can collapse identical strings, we don't even need the strcmp. -#define UNIFIED_CONST_STR -#endif +namespace { -struct Category { - const char *name; +struct Lane { + ProfilerEvent events[LANE_EVENTS]; + // Count of events ever written. Only the owning thread writes it. + std::atomic written{}; + std::atomic inUse{}; + // Guarded by g_lanesMutex. + char name[32]{}; + + // Owning thread only. + int depth = 0; + + // End of frame only (one thread). Replays the events to attribute the time between them to the + // innermost open scope. + uint64_t aggRead = 0; + uint64_t aggLastTicks = 0; + int aggDepth = 0; + uint16_t aggStack[MAX_DEPTH]{}; }; -struct CategoryFrame { - CategoryFrame() { - memset(time_taken, 0, sizeof(time_taken)); - memset(count, 0, sizeof(count)); - } - float time_taken[MAX_CATEGORIES]; - int count[MAX_CATEGORIES]; +struct FrameTotals { + float seconds[MAX_LANES][MAX_CATEGORIES]; + int counts[MAX_LANES][MAX_CATEGORIES]; }; -struct Profiler { - int historyPos; - int depth[MAX_THREADS]; - int parentCategory[MAX_THREADS][MAX_DEPTH]; - double eventStart[MAX_THREADS][MAX_CATEGORIES]; - double curFrameStart; -}; +// Lanes are allocated as threads first record and never freed, so readers can walk them unlocked. +// A thread that exits gives its lane back for the next new thread. +Lane *g_lanes[MAX_LANES]; +std::atomic g_numLanes; +std::mutex g_lanesMutex; -static Profiler profiler; -static Category categories[MAX_CATEGORIES]; -static std::mutex categoriesLock; -static int threadIdAfterLast = 0; -static std::mutex threadsLock; -static CategoryFrame *history; -#if MAX_THREADS > 1 -thread_local int profilerThreadId = -1; -#else -static int profilerThreadId = 0; -#endif +const char *g_categories[MAX_CATEGORIES]; +std::atomic g_numCategories; +std::mutex g_categoriesMutex; -void internal_profiler_init() { - memset(&profiler, 0, sizeof(profiler)); -#if MAX_THREADS == 1 - threadIdAfterLast = 1; -#endif - for (int i = 0; i < MAX_THREADS; i++) { - for (int j = 0; j < MAX_DEPTH; j++) { - profiler.parentCategory[i][j] = -1; +std::atomic g_paused; +bool g_initialized; + +// End of frame only, apart from reads of the finished frames. +FrameTotals *g_history; +uint64_t g_frameEnds[HISTORY_SIZE]; +int g_historyPos; +double g_secondsPerTick; +uint64_t g_startTicks; + +struct LaneOwner { + Lane *lane = nullptr; + bool failed = false; + ~LaneOwner() { + if (lane) { + lane->inUse.store(false, std::memory_order_release); } } - history = new CategoryFrame[HISTORY_SIZE * MAX_THREADS]; -} +}; -static int internal_profiler_find_thread() { - int thread_id = profilerThreadId; - if (thread_id != -1) { - return thread_id; - } +thread_local LaneOwner t_laneOwner; - std::lock_guard guard(threadsLock); - if (threadIdAfterLast < MAX_THREADS) { - thread_id = threadIdAfterLast++; - profilerThreadId = thread_id; - return thread_id; - } - - // Just keep reusing the last one. - return threadIdAfterLast - 1; -} - -int internal_profiler_find_cat(const char *category_name, bool create_missing) { - int i; - for (i = 0; i < MAX_CATEGORIES; i++) { - const char *catname = categories[i].name; - if (!catname) +Lane *ClaimLane() { + std::lock_guard guard(g_lanesMutex); + const int count = g_numLanes.load(std::memory_order_relaxed); + Lane *lane = nullptr; + for (int i = 0; i < count; i++) { + if (!g_lanes[i]->inUse.load(std::memory_order_acquire)) { + lane = g_lanes[i]; break; -#ifdef UNIFIED_CONST_STR - if (catname == category_name) { -#else - if (!strcmp(catname, category_name)) { -#endif + } + } + if (!lane) { + if (count >= MAX_LANES) { + return nullptr; + } + lane = new Lane(); + g_lanes[count] = lane; + g_numLanes.store(count + 1, std::memory_order_release); + } + lane->inUse.store(true, std::memory_order_relaxed); + lane->depth = 0; + const char *name = GetCurrentThreadName(); + truncate_cpy(lane->name, (name && name[0]) ? name : "(unnamed)"); + return lane; +} + +inline Lane *CurrentLane() { + LaneOwner &owner = t_laneOwner; + if (!owner.lane && !owner.failed) { + owner.lane = ClaimLane(); + owner.failed = owner.lane == nullptr; + } + return owner.lane; +} + +inline void Record(Lane *lane, ProfilerEventType type, int category, int level) { + const uint64_t w = lane->written.load(std::memory_order_relaxed); + ProfilerEvent &e = lane->events[w & (LANE_EVENTS - 1)]; + e.ticks = time_now_fast_ticks(); + e.category = (uint16_t)category; + e.type = type; + e.level = (int8_t)std::min(level, MAX_DEPTH - 1); + lane->written.store(w + 1, std::memory_order_release); +} + +// Copies event index i of the lane. False if the writer has overwritten (or may be overwriting) it. +inline bool ReadEvent(const Lane *lane, uint64_t i, ProfilerEvent *out) { + *out = lane->events[i & (LANE_EVENTS - 1)]; + std::atomic_thread_fence(std::memory_order_acquire); + const uint64_t w = lane->written.load(std::memory_order_relaxed); + return i + LANE_EVENTS > w && out->category < MAX_CATEGORIES && out->level >= 0 && out->level < MAX_DEPTH; +} + +inline uint64_t OldestReadable(uint64_t written) { + return written > LANE_EVENTS - 1 ? written - (LANE_EVENTS - 1) : 0; +} + +void Attribute(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t until) { + if (lane->aggDepth > 0 && until > lane->aggLastTicks) { + frame.seconds[laneIndex][lane->aggStack[lane->aggDepth - 1]] += (float)((until - lane->aggLastTicks) * g_secondsPerTick); + } + if (until > lane->aggLastTicks) { + lane->aggLastTicks = until; + } +} + +void AggregateLane(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t frameEnd) { + const uint64_t written = lane->written.load(std::memory_order_acquire); + uint64_t i = lane->aggRead; + if (i < OldestReadable(written)) { + // Lost some, so the open scopes are unknown. The next event's level resyncs them. + i = OldestReadable(written); + lane->aggDepth = 0; + } + for (; i < written; i++) { + ProfilerEvent e; + if (!ReadEvent(lane, i, &e)) { + lane->aggDepth = 0; + continue; + } + if (e.ticks > frameEnd) { + break; + } + if (lane->aggDepth == 0) { + // Nothing open (or resyncing): nothing to attribute up to here. + lane->aggLastTicks = e.ticks; + } + Attribute(lane, laneIndex, frame, e.ticks); + if (e.type == ProfilerEventType::Begin) { + lane->aggStack[e.level] = e.category; + lane->aggDepth = e.level + 1; + } else { + lane->aggDepth = e.level; + frame.counts[laneIndex][e.category]++; + } + } + lane->aggRead = i; + Attribute(lane, laneIndex, frame, frameEnd); +} + +int HistoryIndex(int i, int count) { + // i in [0, count), where count - 1 is the last finished frame. + return (g_historyPos - count + i + HISTORY_SIZE) & (HISTORY_SIZE - 1); +} + +} // namespace + +void internal_profiler_init() { + if (g_initialized) { + return; + } + g_secondsPerTick = fast_ticks_to_nanos() * 1e-9; + g_history = new FrameTotals[HISTORY_SIZE](); + g_startTicks = time_now_fast_ticks(); + g_initialized = true; +} + +int Profiler_GetCategory(const char *name) { + const int count = g_numCategories.load(std::memory_order_acquire); + for (int i = 0; i < count; i++) { + if (g_categories[i] == name) { return i; } } - - if (i < MAX_CATEGORIES && category_name && create_missing) { - std::lock_guard guard(categoriesLock); - int race_check = internal_profiler_find_cat(category_name, false); - if (race_check == -1) - categories[i].name = category_name; - return i; - } - - return -1; -} - -// Suspend, also used to prepare for leaving. -static void internal_profiler_suspend(int thread_id, int category, double now) { - double diff = now - profiler.eventStart[thread_id][category]; - history[MAX_THREADS * profiler.historyPos + thread_id].time_taken[category] += (float)diff; - profiler.eventStart[thread_id][category] = 0.0; -} - -// Resume, also used as part of entering. -static void internal_profiler_resume(int thread_id, int category, double now) { - profiler.eventStart[thread_id][category] = now; -} - -int internal_profiler_enter(const char *category_name, int *out_thread_id) { - int category = internal_profiler_find_cat(category_name, true); - int thread_id = internal_profiler_find_thread(); - if (category == -1 || !history) { - return category; - } - - int &depth = profiler.depth[thread_id]; - if (profiler.eventStart[thread_id][category] == 0.0f) { - double now = time_now_d(); - int parent = profiler.parentCategory[thread_id][depth]; - // Temporarily suspend the parent on entering a child. - if (parent != -1) { - internal_profiler_suspend(thread_id, parent, now); + std::lock_guard guard(g_categoriesMutex); + const int locked = g_numCategories.load(std::memory_order_relaxed); + for (int i = 0; i < locked; i++) { + if (!strcmp(g_categories[i], name)) { + return i; } - internal_profiler_resume(thread_id, category, now); - } else { - DEBUG_LOG(Log::System, "profiler: recursive enter (%i - %s)", category, category_name); } - - depth++; - profiler.parentCategory[thread_id][depth] = category; - - *out_thread_id = thread_id; - return category; + if (locked >= MAX_CATEGORIES) { + return -1; + } + g_categories[locked] = name; + g_numCategories.store(locked + 1, std::memory_order_release); + return locked; } -void internal_profiler_leave(int thread_id, int category) { - if (category == -1 || !history) { +void Profiler_Enter(int category) { + if (category < 0 || !g_initialized) { return; } - - int &depth = profiler.depth[thread_id]; - if (category < 0 || category >= MAX_CATEGORIES) { - ERROR_LOG(Log::System, "Bad category index %d", category); - depth--; + Lane *lane = CurrentLane(); + if (!lane) { return; } + const int level = lane->depth++; + if (!g_paused.load(std::memory_order_relaxed)) { + Record(lane, ProfilerEventType::Begin, category, level); + } +} - double now = time_now_d(); - - depth--; - _assert_msg_(depth >= 0, "Profiler enter/leave mismatch!"); - - int parent = profiler.parentCategory[thread_id][depth]; - // When there's recursion, we don't suspend or resume. - if (parent != category) { - internal_profiler_suspend(thread_id, category, now); - history[MAX_THREADS * profiler.historyPos + thread_id].count[category]++; - - if (parent != -1) { - // Resume tracking the parent. - internal_profiler_resume(thread_id, parent, now); - } +void Profiler_Leave(int category) { + if (category < 0 || !g_initialized) { + return; + } + Lane *lane = CurrentLane(); + // A scope entered before init has nothing to close. + if (!lane || lane->depth == 0) { + return; + } + const int level = --lane->depth; + if (!g_paused.load(std::memory_order_relaxed)) { + Record(lane, ProfilerEventType::End, category, level); } } void internal_profiler_end_frame() { - int thread_id = internal_profiler_find_thread(); - _assert_msg_(profiler.depth[thread_id] == 0, "Can't be inside a profiler scope at end of frame!"); - profiler.curFrameStart = time_now_d(); - profiler.historyPos++; - profiler.historyPos &= (HISTORY_SIZE - 1); - memset(&history[MAX_THREADS * profiler.historyPos], 0, sizeof(CategoryFrame) * MAX_THREADS); + if (!g_initialized || g_paused.load(std::memory_order_relaxed)) { + return; + } + const uint64_t now = time_now_fast_ticks(); + const int pos = g_historyPos; + FrameTotals &frame = g_history[pos]; + memset(&frame, 0, sizeof(frame)); + const int numLanes = g_numLanes.load(std::memory_order_acquire); + for (int i = 0; i < numLanes; i++) { + AggregateLane(g_lanes[i], i, frame, now); + } + g_frameEnds[pos] = now; + g_historyPos = (pos + 1) & (HISTORY_SIZE - 1); } const char *Profiler_GetCategoryName(int i) { - return i >= 0 ? categories[i].name : "N/A"; + return i >= 0 && i < g_numCategories.load(std::memory_order_acquire) ? g_categories[i] : "N/A"; } int Profiler_GetHistoryLength() { - return HISTORY_SIZE; + // Leaves out the slot the next frame end will write. + return HISTORY_SIZE - 1; } int Profiler_GetNumCategories() { - for (int i = 0; i < MAX_CATEGORIES; i++) { - if (!categories[i].name) - return i; - } - return 0; + return g_numCategories.load(std::memory_order_acquire); } int Profiler_GetNumThreads() { - return threadIdAfterLast; + return g_numLanes.load(std::memory_order_acquire); +} + +const char *Profiler_GetThreadName(int thread, char *buf, size_t bufSize) { + std::lock_guard guard(g_lanesMutex); + if (thread < 0 || thread >= g_numLanes.load(std::memory_order_relaxed) || bufSize == 0) { + return ""; + } + truncate_cpy(buf, bufSize, g_lanes[thread]->name); + return buf; } void Profiler_GetSlowestThreads(int *data, int count) { - int numCategories = Profiler_GetNumCategories(); - for (int i = 0; i < HISTORY_SIZE; i++) { - int x = i - count + profiler.historyPos + 1; - while (x < 0) - x += HISTORY_SIZE; - while (x >= HISTORY_SIZE) - x -= HISTORY_SIZE; - + const int numCategories = Profiler_GetNumCategories(); + const int numLanes = Profiler_GetNumThreads(); + for (int i = 0; i < count; i++) { + const FrameTotals &frame = g_history[HistoryIndex(i, count)]; float slowestTime = 0.0f; data[i] = 0; - for (int thread = 0; thread < threadIdAfterLast; ++thread) { + for (int lane = 0; lane < numLanes; ++lane) { float sum = 0.0f; for (int c = 0; c < numCategories; ++c) { - sum += history[MAX_THREADS * x + thread].time_taken[c]; + sum += frame.seconds[lane][c]; } if (sum > slowestTime) { slowestTime = sum; - data[i] = thread; + data[i] = lane; } } } } void Profiler_GetSlowestHistory(int category, int *slowestThreads, float *data, int count) { - for (int i = 0; i < HISTORY_SIZE; i++) { - int x = i - count + profiler.historyPos + 1; - while (x < 0) - x += HISTORY_SIZE; - while (x >= HISTORY_SIZE) - x -= HISTORY_SIZE; - - int thread = slowestThreads[i]; - data[i] = history[MAX_THREADS * x + thread].time_taken[category]; + for (int i = 0; i < count; i++) { + data[i] = category >= 0 && category < MAX_CATEGORIES ? g_history[HistoryIndex(i, count)].seconds[slowestThreads[i]][category] : 0.0f; } } void Profiler_GetHistory(int category, int thread, float *data, int count) { - for (int i = 0; i < HISTORY_SIZE; i++) { - int x = i - count + profiler.historyPos + 1; - while (x < 0) - x += HISTORY_SIZE; - while (x >= HISTORY_SIZE) - x -= HISTORY_SIZE; - data[i] = history[MAX_THREADS * x + thread].time_taken[category]; + const bool valid = category >= 0 && category < MAX_CATEGORIES && thread >= 0 && thread < MAX_LANES; + for (int i = 0; i < count; i++) { + data[i] = valid ? g_history[HistoryIndex(i, count)].seconds[thread][category] : 0.0f; } } + +void Profiler_GetHistoryCounts(int category, int thread, int *data, int count) { + const bool valid = category >= 0 && category < MAX_CATEGORIES && thread >= 0 && thread < MAX_LANES; + for (int i = 0; i < count; i++) { + data[i] = valid ? g_history[HistoryIndex(i, count)].counts[thread][category] : 0; + } +} + +void Profiler_SetPaused(bool paused) { + g_paused.store(paused, std::memory_order_relaxed); +} + +bool Profiler_IsPaused() { + return g_paused.load(std::memory_order_relaxed); +} + +uint64_t Profiler_Now() { + return time_now_fast_ticks(); +} + +uint64_t Profiler_GetStartTicks() { + return g_startTicks; +} + +double Profiler_TicksToSeconds(int64_t ticks) { + return ticks * g_secondsPerTick; +} + +int64_t Profiler_SecondsToTicks(double seconds) { + return g_secondsPerTick > 0.0 ? (int64_t)(seconds / g_secondsPerTick) : 0; +} + +void Profiler_GetEvents(int thread, uint64_t from, uint64_t to, std::vector *events) { + if (thread < 0 || thread >= g_numLanes.load(std::memory_order_acquire)) { + return; + } + const Lane *lane = g_lanes[thread]; + const uint64_t written = lane->written.load(std::memory_order_acquire); + // Ticks only grow along a lane, so binary search for the first event at or after from. + uint64_t lo = OldestReadable(written), hi = written; + while (lo < hi) { + const uint64_t mid = lo + (hi - lo) / 2; + ProfilerEvent e; + if (!ReadEvent(lane, mid, &e) || e.ticks < from) { + lo = mid + 1; + } else { + hi = mid; + } + } + for (uint64_t i = lo; i < written; i++) { + ProfilerEvent e; + if (!ReadEvent(lane, i, &e)) { + continue; + } + if (e.ticks > to) { + break; + } + events->push_back(e); + } +} + +void Profiler_GetFrameEnds(std::vector *ends) { + for (int i = 0; i < HISTORY_SIZE - 1; i++) { + const uint64_t t = g_frameEnds[HistoryIndex(i, HISTORY_SIZE - 1)]; + if (t != 0) { + ends->push_back(t); + } + } +} + +#endif diff --git a/Common/Profiler/Profiler.h b/Common/Profiler/Profiler.h index e5addb1ac4..de40165f3f 100644 --- a/Common/Profiler/Profiler.h +++ b/Common/Profiler/Profiler.h @@ -1,48 +1,97 @@ #pragma once #include +#include // #define USE_PROFILER #ifdef USE_PROFILER -class DrawBuffer; +// Each thread that enters a scope records begin and end events into a ring of its own (a lane), with +// no locking. Per-frame totals are worked out from those events at the end of each frame, and the +// ImGui debugger's timeline draws them directly. void internal_profiler_init(); void internal_profiler_end_frame(); -int internal_profiler_enter(const char *category_name, int *thread_id); // Returns the category number. -void internal_profiler_leave(int thread_id, int category); +// Returns the category number for a name, adding it if new. Names are compared by pointer first, so +// a string literal is cheap to look up. +int Profiler_GetCategory(const char *name); +void Profiler_Enter(int category); +void Profiler_Leave(int category); +class ProfileThis { +public: + explicit ProfileThis(int category) : category_(category) { + Profiler_Enter(category); + } + ~ProfileThis() { + Profiler_Leave(category_); + } +private: + int category_; +}; + +#define PROFILE_INIT() internal_profiler_init(); +// Named by line, so a scope can hold more than one. +#define PROFILE_CONCAT_INNER(a, b) a##b +#define PROFILE_CONCAT(a, b) PROFILE_CONCAT_INNER(a, b) +// cat must be the same string every time this line runs (normally a literal): it's looked up once. +#define PROFILE_THIS_SCOPE(cat) \ + static const int PROFILE_CONCAT(_profile_cat, __LINE__) = Profiler_GetCategory(cat); \ + ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(PROFILE_CONCAT(_profile_cat, __LINE__)); +// For a name that varies between calls. +#define PROFILE_THIS_SCOPE_DYNAMIC(cat) ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_GetCategory(cat)); +#define PROFILE_END_FRAME() internal_profiler_end_frame(); + +// Per-frame totals, in seconds of time spent in each category itself (not in scopes nested in it). +// A frame is the time between two PROFILE_END_FRAME() calls; history index count - 1 is the last one. const char *Profiler_GetCategoryName(int i); int Profiler_GetNumCategories(); int Profiler_GetHistoryLength(); int Profiler_GetNumThreads(); +const char *Profiler_GetThreadName(int thread, char *buf, size_t bufSize); void Profiler_GetSlowestThreads(int *data, int count); void Profiler_GetSlowestHistory(int category, int *slowestThreads, float *data, int count); void Profiler_GetHistory(int category, int thread, float *data, int count); +// How many times each scope of the category was left in the frame. +void Profiler_GetHistoryCounts(int category, int thread, int *data, int count); -class ProfileThis { -public: - ProfileThis(const char *category) { - cat_ = internal_profiler_enter(category, &thread_); - } - ~ProfileThis() { - internal_profiler_leave(thread_, cat_); - } -private: - int cat_; - int thread_; +// While paused, nothing is recorded and the history stands still. +void Profiler_SetPaused(bool paused); +bool Profiler_IsPaused(); + +// For the timeline. +enum class ProfilerEventType : uint8_t { + Begin, + End, }; -#define PROFILE_INIT() internal_profiler_init(); -#define PROFILE_THIS_SCOPE(cat) ProfileThis _profile_scoped(cat); -#define PROFILE_END_FRAME() internal_profiler_end_frame(); +struct ProfilerEvent { + uint64_t ticks; + uint16_t category; + ProfilerEventType type; + // Nesting depth, 0 at the outermost scope. Begin and End of one scope have the same level. + int8_t level; + uint32_t padding; +}; + +uint64_t Profiler_Now(); +// When internal_profiler_init() ran. +uint64_t Profiler_GetStartTicks(); +double Profiler_TicksToSeconds(int64_t ticks); +int64_t Profiler_SecondsToTicks(double seconds); +// Appends the thread's events with ticks in [from, to], oldest first. Events that have left the ring +// are gone, so the first ones may be Ends whose Begin isn't there. +void Profiler_GetEvents(int thread, uint64_t from, uint64_t to, std::vector *events); +// When each of the history's frames ended, oldest first. +void Profiler_GetFrameEnds(std::vector *ends); #else #define PROFILE_INIT() #define PROFILE_THIS_SCOPE(cat) +#define PROFILE_THIS_SCOPE_DYNAMIC(cat) #define PROFILE_END_FRAME() #endif diff --git a/GPU/Common/SplineCommon.cpp b/GPU/Common/SplineCommon.cpp index 54ca27c4a2..30dcb463d1 100644 --- a/GPU/Common/SplineCommon.cpp +++ b/GPU/Common/SplineCommon.cpp @@ -1371,7 +1371,7 @@ template void DrawEngineCommon::SubmitCurve(const void *control_p template void DrawEngineCommon::SubmitCurve(const void *control_points, const void *indices, Surface &surface, u32 vertType, int *bytesRead, const char *scope) { - PROFILE_THIS_SCOPE(scope); + PROFILE_THIS_SCOPE_DYNAMIC(scope); // Real hardware seems to draw nothing when given < 4 either U or V. // This would result in num_patches_u / num_patches_v being 0. diff --git a/UI/CMakeLists.txt b/UI/CMakeLists.txt index cf244a6751..171dcefd8b 100644 --- a/UI/CMakeLists.txt +++ b/UI/CMakeLists.txt @@ -22,6 +22,8 @@ list(APPEND UISource ImDebugger/ImStructViewer.h ImDebugger/ImJitViewer.cpp ImDebugger/ImJitViewer.h + ImDebugger/ImProfiler.cpp + ImDebugger/ImProfiler.h DiscordIntegration.cpp DiscordIntegration.h NativeApp.cpp diff --git a/UI/ImDebugger/ImDebugger.cpp b/UI/ImDebugger/ImDebugger.cpp index 24b83a0db1..e37e2e9472 100644 --- a/UI/ImDebugger/ImDebugger.cpp +++ b/UI/ImDebugger/ImDebugger.cpp @@ -26,6 +26,7 @@ #include "Core/Debugger/DebugInterface.h" #include "Core/Debugger/DisassemblyManager.h" #include "Core/Debugger/Breakpoints.h" +#include "Common/Profiler/Profiler.h" #include "Core/MIPS/MIPSDebugInterface.h" #include "Core/MIPS/MIPSTables.h" #include "Core/MIPS/MIPSVFPUUtils.h" @@ -73,6 +74,7 @@ #include "UI/ImDebugger/ImDebugger.h" #include "UI/ImDebugger/ImGe.h" +#include "UI/ImDebugger/ImProfiler.h" #include "UI/AudioCommon.h" #include "UI/GameInfoCache.h" #include "UI/PauseScreen.h" @@ -3031,6 +3033,10 @@ void ImDebugger::Frame(MIPSDebugInterface *mipsDebug, GPUCommon *gpuDebug, Draw: auto menuMisc = [&]() { if (beginMenu("Misc")) { ImGui::MenuItem("PPSSPP Internals", nullptr, &cfg_.internalsOpen); +#ifdef USE_PROFILER + ImGui::MenuItem("CPU profiler", nullptr, &cfg_.cpuProfilerOpen); + ImGui::MenuItem("Frame profile", nullptr, &cfg_.frameProfileOpen); +#endif ImGui::MenuItem("Dear ImGui Demo", nullptr, &cfg_.demoOpen); ImGui::MenuItem("Dear ImGui Style editor", nullptr, &cfg_.styleEditorOpen); ImGui::Separator(); @@ -3301,6 +3307,14 @@ void ImDebugger::Frame(MIPSDebugInterface *mipsDebug, GPUCommon *gpuDebug, Draw: DrawInternals(cfg_); } + if (cfg_.cpuProfilerOpen) { + DrawCpuProfiler(cfg_); + } + + if (cfg_.frameProfileOpen) { + DrawFrameProfile(cfg_); + } + if (externalCommand_.cmd != ImCmd::NONE) { control.command = externalCommand_; externalCommand_.cmd = ImCmd::NONE; @@ -3631,6 +3645,8 @@ void ImConfig::SyncConfig(IniFile *ini, bool save) { sync.Sync("paramSFOOpen", ¶mSFOOpen, false); sync.Sync("atracToolOpen", &atracToolOpen, false); sync.Sync("jitViewerOpen", &jitViewerOpen, false); + sync.Sync("cpuProfilerOpen", &cpuProfilerOpen, false); + sync.Sync("frameProfileOpen", &frameProfileOpen, false); for (int i = 0; i < 4; i++) { char name[64]; snprintf(name, sizeof(name), "memory%dOpen", i + 1); diff --git a/UI/ImDebugger/ImDebugger.h b/UI/ImDebugger/ImDebugger.h index 9c32c1a831..9657dfc457 100644 --- a/UI/ImDebugger/ImDebugger.h +++ b/UI/ImDebugger/ImDebugger.h @@ -93,6 +93,8 @@ struct ImConfig { bool audioOutOpen; bool paramSFOOpen; bool jitViewerOpen; + bool cpuProfilerOpen; + bool frameProfileOpen; // HLE explorer settings // bool filterByUsed = true; diff --git a/UI/ImDebugger/ImProfiler.cpp b/UI/ImDebugger/ImProfiler.cpp new file mode 100644 index 0000000000..e621ec51a1 --- /dev/null +++ b/UI/ImDebugger/ImProfiler.cpp @@ -0,0 +1,417 @@ +// Copyright (c) 2012- PPSSPP Project. + +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, version 2.0 or later versions. + +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License 2.0 for more details. + +// A copy of the GPL 2.0 should have been included with the program. +// If not, see http://www.gnu.org/licenses/ + +// Official git repository and contact information can be found at +// https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. + +#include +#include +#include +#include + +#include "ext/imgui/imgui.h" + +#include "Common/Common.h" +#include "Common/Profiler/Profiler.h" +#include "UI/ImDebugger/ImDebugger.h" +#include "UI/ImDebugger/ImProfiler.h" + +#ifdef USE_PROFILER + +namespace { + +const ImU32 categoryColors[] = { + IM_COL32(0x40, 0x80, 0xFF, 255), + IM_COL32(0x40, 0xC0, 0x60, 255), + IM_COL32(0xD0, 0x60, 0x40, 255), + IM_COL32(0xB0, 0x50, 0xC0, 255), + IM_COL32(0x30, 0xA0, 0xA0, 255), + IM_COL32(0xC0, 0xA0, 0x30, 255), + IM_COL32(0x80, 0x60, 0x40, 255), + IM_COL32(0x60, 0x70, 0xA0, 255), + IM_COL32(0xE0, 0x40, 0x80, 255), + IM_COL32(0x90, 0xD0, 0x40, 255), + IM_COL32(0x40, 0xD0, 0xE0, 255), + IM_COL32(0xE0, 0x90, 0x20, 255), + IM_COL32(0x80, 0x40, 0xE0, 255), + IM_COL32(0x20, 0x80, 0x50, 255), + IM_COL32(0xA0, 0x30, 0x30, 255), + IM_COL32(0xD0, 0xD0, 0x90, 255), +}; + +// Names containing these are waits, drawn grey. +bool IsWaitCategory(const char *name) { + return strstr(name, "sleep") || strstr(name, "wait") || strstr(name, "idle"); +} + +ImU32 CategoryColor(int category) { + if (IsWaitCategory(Profiler_GetCategoryName(category))) { + return IM_COL32(0x70, 0x70, 0x70, 255); + } + return categoryColors[category % ARRAY_SIZE(categoryColors)]; +} + +struct TimelineView { + double spanSeconds = 0.05; + // Right edge of the view, used when not following. + uint64_t end = 0; + bool follow = true; + // Deepest level seen per thread, so lanes don't jump in height. + std::vector laneDepth; +}; + +TimelineView g_view; +std::vector g_events; + +void DrawTimeline() { + TimelineView &view = g_view; + const uint64_t now = Profiler_Now(); + if (view.follow && !Profiler_IsPaused()) { + view.end = now; + } + const int64_t span = std::max(Profiler_SecondsToTicks(view.spanSeconds), 1); + const uint64_t viewEnd = view.end; + const uint64_t viewStart = viewEnd > (uint64_t)span ? viewEnd - span : 0; + + const ImVec2 origin = ImGui::GetCursorScreenPos(); + const ImVec2 avail = ImGui::GetContentRegionAvail(); + const float nameWidth = 150.0f; + const float rowH = ImGui::GetTextLineHeight() + 4.0f; + const float x0 = origin.x + nameWidth; + const float width = std::max(avail.x - nameWidth, 50.0f); + auto toX = [&](uint64_t ticks) { + return x0 + (float)((double)((int64_t)ticks - (int64_t)viewStart) / (double)span) * width; + }; + + const int numThreads = Profiler_GetNumThreads(); + if ((int)view.laneDepth.size() < numThreads) { + view.laneDepth.resize(numThreads, 1); + } + float totalH = rowH; // ruler + for (int t = 0; t < numThreads; t++) { + totalH += rowH * view.laneDepth[t] + 4.0f; + } + + ImGui::InvisibleButton("timeline", ImVec2(avail.x, std::max(totalH, 50.0f))); + const bool hovered = ImGui::IsItemHovered(); + ImGuiIO &io = ImGui::GetIO(); + if (ImGui::IsItemActive() && ImGui::IsMouseDragging(ImGuiMouseButton_Left, 0.0f) && io.MouseDelta.x != 0.0f) { + view.follow = false; + const int64_t delta = (int64_t)(-io.MouseDelta.x / width * span); + view.end = (uint64_t)std::max((int64_t)view.end + delta, span); + } + if (hovered && io.MouseWheel != 0.0f) { + // Zoom around the mouse. + const double frac = std::clamp((io.MousePos.x - x0) / width, 0.0f, 1.0f); + const uint64_t anchor = viewStart + (uint64_t)(frac * span); + const double newSpan = std::clamp(view.spanSeconds * pow(0.85, io.MouseWheel), 0.0001, 2.0); + const int64_t newSpanTicks = Profiler_SecondsToTicks(newSpan); + view.spanSeconds = newSpan; + if (!view.follow || Profiler_IsPaused()) { + view.end = anchor + (uint64_t)((1.0 - frac) * newSpanTicks); + } + } + + ImDrawList *dl = ImGui::GetWindowDrawList(); + dl->PushClipRect(origin, ImVec2(origin.x + avail.x, origin.y + std::max(totalH, 50.0f)), true); + + // Ruler, in seconds since the profiler started, with a mark per power of ten of milliseconds that + // gives at most about 10 marks. + const double spanMs = Profiler_TicksToSeconds(span) * 1000.0; + const double stepMs = pow(10.0, floor(log10(std::max(spanMs, 0.001) / 2.0))); + const int decimals = std::max(0, 3 - (int)floor(log10(stepMs))); + char buf[64]; + const double startMs = Profiler_TicksToSeconds((int64_t)(viewStart - Profiler_GetStartTicks())) * 1000.0; + for (double ms = ceil(startMs / stepMs) * stepMs; ms < startMs + spanMs; ms += stepMs) { + const float x = x0 + (float)((ms - startMs) / spanMs) * width; + dl->AddLine(ImVec2(x, origin.y + rowH - 4.0f), ImVec2(x, origin.y + rowH), IM_COL32(180, 180, 180, 255)); + snprintf(buf, sizeof(buf), "%.*f s", decimals, ms / 1000.0); + dl->AddText(ImVec2(x + 2.0f, origin.y), IM_COL32(180, 180, 180, 255), buf); + } + + struct Open { + uint64_t start; + bool valid; + }; + const char *hoveredName = nullptr; + double hoveredMs = 0.0; + float y = origin.y + rowH; + for (int t = 0; t < numThreads; t++) { + const float laneH = rowH * view.laneDepth[t]; + dl->AddRectFilled(ImVec2(origin.x, y), ImVec2(origin.x + avail.x, y + laneH), (t & 1) ? IM_COL32(40, 40, 40, 255) : IM_COL32(32, 32, 32, 255)); + dl->AddText(ImVec2(origin.x + 4.0f, y + 2.0f), IM_COL32(220, 220, 220, 255), Profiler_GetThreadName(t, buf, sizeof(buf))); + + g_events.clear(); + Profiler_GetEvents(t, viewStart, viewEnd, &g_events); + + Open open[32]{}; + int maxLevel = 0; + auto drawBar = [&](int level, int category, uint64_t from, uint64_t to) { + maxLevel = std::max(maxLevel, level); + if (level >= view.laneDepth[t]) { + return; + } + const float xa = std::max(toX(from), x0); + const float xb = std::max(toX(to), xa + 1.0f); + const float ya = y + rowH * level; + const ImVec2 a(xa, ya + 1.0f), b(xb, ya + rowH - 1.0f); + const char *name = Profiler_GetCategoryName(category); + dl->AddRectFilled(a, b, CategoryColor(category)); + if (xb - xa > 30.0f) { + dl->PushClipRect(a, b, true); + dl->AddText(ImVec2(xa + 2.0f, ya + 2.0f), IM_COL32(255, 255, 255, 255), name); + dl->PopClipRect(); + } + if (hovered && io.MousePos.x >= a.x && io.MousePos.x < b.x && io.MousePos.y >= a.y && io.MousePos.y < b.y) { + hoveredName = name; + hoveredMs = Profiler_TicksToSeconds((int64_t)(to - from)) * 1000.0; + } + }; + for (const ProfilerEvent &e : g_events) { + if (e.type == ProfilerEventType::Begin) { + open[e.level] = Open{ e.ticks, true }; + } else { + // Without its Begin, the scope started before the view. + drawBar(e.level, e.category, open[e.level].valid ? open[e.level].start : viewStart, e.ticks); + open[e.level].valid = false; + } + } + // Still open at the right edge. + for (int level = 0; level < (int)ARRAY_SIZE(open); level++) { + if (open[level].valid) { + int category = 0; + for (auto it = g_events.rbegin(); it != g_events.rend(); ++it) { + if (it->type == ProfilerEventType::Begin && it->level == level) { + category = it->category; + break; + } + } + drawBar(level, category, open[level].start, std::min(viewEnd, now)); + } + } + if (maxLevel + 1 > view.laneDepth[t]) { + view.laneDepth[t] = maxLevel + 1; + } + y += laneH + 4.0f; + } + + // Frame ends, over the lanes. + std::vector frameEnds; + Profiler_GetFrameEnds(&frameEnds); + for (uint64_t t : frameEnds) { + if (t >= viewStart && t <= viewEnd) { + const float x = toX(t); + dl->AddLine(ImVec2(x, origin.y), ImVec2(x, origin.y + totalH), IM_COL32(255, 255, 0, 160)); + } + } + dl->PopClipRect(); + + if (hoveredName) { + ImGui::SetTooltip("%s\n%0.3f ms", hoveredName, hoveredMs); + } +} + +void DrawFrameTotals() { + const int numThreads = Profiler_GetNumThreads(); + const int numCategories = Profiler_GetNumCategories(); + const int historyLength = Profiler_GetHistoryLength(); + std::vector history(historyLength); + std::vector counts(historyLength); + char buf[64]; + + ImGui::TextUnformatted("Time spent in each category itself, in the last frame and on average over the history."); + for (int t = 0; t < numThreads; t++) { + if (!ImGui::CollapsingHeader(Profiler_GetThreadName(t, buf, sizeof(buf)), ImGuiTreeNodeFlags_DefaultOpen)) { + continue; + } + ImGui::PushID(t); + if (ImGui::BeginTable("totals", 5, ImGuiTableFlags_RowBg | ImGuiTableFlags_BordersInnerV | ImGuiTableFlags_SizingFixedFit)) { + ImGui::TableSetupColumn("Category", ImGuiTableColumnFlags_WidthStretch); + ImGui::TableSetupColumn("Last ms"); + ImGui::TableSetupColumn("Last count"); + ImGui::TableSetupColumn("Avg ms"); + ImGui::TableSetupColumn("Max ms"); + ImGui::TableHeadersRow(); + for (int c = 0; c < numCategories; c++) { + Profiler_GetHistory(c, t, history.data(), historyLength); + Profiler_GetHistoryCounts(c, t, counts.data(), historyLength); + float sum = 0.0f, maxVal = 0.0f; + for (float v : history) { + sum += v; + maxVal = std::max(maxVal, v); + } + if (maxVal <= 0.0f) { + continue; + } + ImGui::TableNextRow(); + ImGui::TableNextColumn(); + ImGui::TextUnformatted(Profiler_GetCategoryName(c)); + ImGui::TableNextColumn(); + ImGui::Text("%0.2f", history[historyLength - 1] * 1000.0f); + ImGui::TableNextColumn(); + ImGui::Text("%d", counts[historyLength - 1]); + ImGui::TableNextColumn(); + ImGui::Text("%0.2f", sum / historyLength * 1000.0f); + ImGui::TableNextColumn(); + ImGui::Text("%0.2f", maxVal * 1000.0f); + } + ImGui::EndTable(); + } + ImGui::PopID(); + } +} + +} // namespace + +#endif + +void DrawFrameProfile(ImConfig &cfg) { + ImGui::SetNextWindowSize(ImVec2(800, 300), ImGuiCond_FirstUseEver); + if (!ImGui::Begin("Frame profile", &cfg.frameProfileOpen)) { + ImGui::End(); + return; + } +#ifdef USE_PROFILER + const int numCategories = Profiler_GetNumCategories(); + const int numThreads = Profiler_GetNumThreads(); + const int historyLength = Profiler_GetHistoryLength(); + + // history[thread][category][frame]. Threads and categories with no time in the history are left out. + std::vector>> history(numThreads); + std::vector> totals(numThreads); + std::vector shownThreads; + std::vector categoryShown(numCategories); + float maxTotal = 1.0f / 60.0f; + for (int t = 0; t < numThreads; t++) { + history[t].resize(numCategories); + totals[t].resize(historyLength); + for (int c = 0; c < numCategories; c++) { + history[t][c].resize(historyLength); + Profiler_GetHistory(c, t, history[t][c].data(), historyLength); + for (int i = 0; i < historyLength; i++) { + totals[t][i] += history[t][c][i]; + if (history[t][c][i] > 0.0f) { + categoryShown[c] = true; + } + } + } + const float threadMax = *std::max_element(totals[t].begin(), totals[t].end()); + if (threadMax > 0.0f) { + shownThreads.push_back(t); + maxTotal = std::max(maxTotal, threadMax); + } + } + + ImGui::Text("Time per frame in each category, per thread. Scale: %0.1f ms.", maxTotal * 1000.0f); + const float legendW = 140.0f; + const ImVec2 avail = ImGui::GetContentRegionAvail(); + const float graphW = std::max(avail.x - legendW, 100.0f); + const float lineH = ImGui::GetTextLineHeightWithSpacing(); + const float graphH = std::max((avail.y - lineH * shownThreads.size()) / std::max((int)shownThreads.size(), 1) - 4.0f, 40.0f); + const float dx = graphW / historyLength; + const float scale = graphH / maxTotal; + char buf[64]; + + ImGui::BeginGroup(); + for (int t : shownThreads) { + ImGui::TextUnformatted(Profiler_GetThreadName(t, buf, sizeof(buf))); + const ImVec2 origin = ImGui::GetCursorScreenPos(); + ImGui::PushID(t); + ImGui::InvisibleButton("graph", ImVec2(graphW, graphH)); + ImGui::PopID(); + const bool hovered = ImGui::IsItemHovered(); + ImDrawList *dl = ImGui::GetWindowDrawList(); + dl->AddRectFilled(origin, ImVec2(origin.x + graphW, origin.y + graphH), IM_COL32(25, 25, 25, 255)); + + const float bottom = origin.y + graphH; + for (int i = 0; i < historyLength; i++) { + float stacked = 0.0f; + const float x = origin.x + i * dx; + for (int c = 0; c < numCategories; c++) { + const float v = history[t][c][i]; + if (v <= 0.0f) { + continue; + } + dl->AddRectFilled(ImVec2(x, bottom - (stacked + v) * scale), ImVec2(x + std::max(dx - 1.0f, 1.0f), bottom - stacked * scale), CategoryColor(c)); + stacked += v; + } + } + // 60 fps line. + const float y60 = bottom - (1.0f / 60.0f) * scale; + dl->AddLine(ImVec2(origin.x, y60), ImVec2(origin.x + graphW, y60), IM_COL32(255, 255, 0, 160)); + dl->AddText(ImVec2(origin.x + 4.0f, y60 - ImGui::GetTextLineHeight()), IM_COL32(255, 255, 0, 200), "1/60 s"); + + if (hovered) { + const int i = std::clamp((int)((ImGui::GetIO().MousePos.x - origin.x) / dx), 0, historyLength - 1); + ImGui::BeginTooltip(); + ImGui::Text("%s, %d frames ago: %0.2f ms", buf, historyLength - 1 - i, totals[t][i] * 1000.0f); + for (int c = numCategories - 1; c >= 0; c--) { + if (history[t][c][i] > 0.0f) { + ImGui::TextColored(ImGui::ColorConvertU32ToFloat4(CategoryColor(c)), "%s: %0.2f ms", Profiler_GetCategoryName(c), history[t][c][i] * 1000.0f); + } + } + ImGui::EndTooltip(); + } + } + ImGui::EndGroup(); + + // Legend, in stacking order from the top. + ImGui::SameLine(); + ImGui::BeginGroup(); + for (int c = numCategories - 1; c >= 0; c--) { + if (!categoryShown[c]) { + continue; + } + ImGui::ColorButton(Profiler_GetCategoryName(c), ImGui::ColorConvertU32ToFloat4(CategoryColor(c)), ImGuiColorEditFlags_NoTooltip, ImVec2(12, 12)); + ImGui::SameLine(); + ImGui::TextUnformatted(Profiler_GetCategoryName(c)); + } + ImGui::EndGroup(); +#else + ImGui::TextUnformatted("Build with USE_PROFILER (Common/Profiler/Profiler.h) to use this."); +#endif + ImGui::End(); +} + +void DrawCpuProfiler(ImConfig &cfg) { + ImGui::SetNextWindowSize(ImVec2(800, 300), ImGuiCond_FirstUseEver); + if (!ImGui::Begin("CPU profiler", &cfg.cpuProfilerOpen)) { + ImGui::End(); + return; + } +#ifdef USE_PROFILER + bool paused = Profiler_IsPaused(); + if (ImGui::Checkbox("Pause", &paused)) { + Profiler_SetPaused(paused); + } + ImGui::SameLine(); + ImGui::Checkbox("Follow", &g_view.follow); + ImGui::SameLine(); + ImGui::Text("%0.1f ms shown. Wheel zooms, dragging pans.", g_view.spanSeconds * 1000.0); + if (ImGui::BeginTabBar("profiler")) { + if (ImGui::BeginTabItem("Timeline")) { + DrawTimeline(); + ImGui::EndTabItem(); + } + if (ImGui::BeginTabItem("Frame totals")) { + DrawFrameTotals(); + ImGui::EndTabItem(); + } + ImGui::EndTabBar(); + } +#else + ImGui::TextUnformatted("Build with USE_PROFILER (Common/Profiler/Profiler.h) to use this."); +#endif + ImGui::End(); +} diff --git a/UI/ImDebugger/ImProfiler.h b/UI/ImDebugger/ImProfiler.h new file mode 100644 index 0000000000..0998ff9ae0 --- /dev/null +++ b/UI/ImDebugger/ImProfiler.h @@ -0,0 +1,8 @@ +#pragma once + +struct ImConfig; + +// The frame profiler's timeline and per-frame totals. Only does anything when built with USE_PROFILER. +void DrawCpuProfiler(ImConfig &cfg); +// The on-screen frame profile overlay's graph, in a window. +void DrawFrameProfile(ImConfig &cfg); diff --git a/UI/UI.vcxproj b/UI/UI.vcxproj index b31d954f1c..f2327988b2 100644 --- a/UI/UI.vcxproj +++ b/UI/UI.vcxproj @@ -57,6 +57,7 @@ + @@ -135,6 +136,7 @@ + diff --git a/UI/UI.vcxproj.filters b/UI/UI.vcxproj.filters index f133da1084..be7b7d0d6d 100644 --- a/UI/UI.vcxproj.filters +++ b/UI/UI.vcxproj.filters @@ -181,6 +181,9 @@ ImDebugger + + ImDebugger + Screens @@ -360,6 +363,9 @@ ImDebugger + + ImDebugger + Screens diff --git a/UWP/UI_UWP/UI_UWP.vcxproj b/UWP/UI_UWP/UI_UWP.vcxproj index 0c3918ae12..d72278d36d 100644 --- a/UWP/UI_UWP/UI_UWP.vcxproj +++ b/UWP/UI_UWP/UI_UWP.vcxproj @@ -115,6 +115,7 @@ + @@ -184,6 +185,7 @@ + diff --git a/UWP/UI_UWP/UI_UWP.vcxproj.filters b/UWP/UI_UWP/UI_UWP.vcxproj.filters index 54c3ddafec..ece9273295 100644 --- a/UWP/UI_UWP/UI_UWP.vcxproj.filters +++ b/UWP/UI_UWP/UI_UWP.vcxproj.filters @@ -35,6 +35,9 @@ ImDebugger + + ImDebugger + Screens @@ -228,6 +231,9 @@ ImDebugger + + ImDebugger + Screens diff --git a/android/jni/Android.mk b/android/jni/Android.mk index b0901e8450..74bcd15685 100644 --- a/android/jni/Android.mk +++ b/android/jni/Android.mk @@ -1071,6 +1071,7 @@ LOCAL_SRC_FILES := \ $(SRC)/UI/ImDebugger/ImDisasmView.cpp \ $(SRC)/UI/ImDebugger/ImMemView.cpp \ $(SRC)/UI/ImDebugger/ImJitViewer.cpp \ + $(SRC)/UI/ImDebugger/ImProfiler.cpp \ $(SRC)/UI/ImDebugger/ImStructViewer.cpp \ $(SRC)/UI/AudioCommon.cpp \ $(SRC)/UI/BackgroundAudio.cpp \ diff --git a/unittest/UnitTest.cpp b/unittest/UnitTest.cpp index fc73d518df..5398fae595 100644 --- a/unittest/UnitTest.cpp +++ b/unittest/UnitTest.cpp @@ -47,6 +47,7 @@ #include #include #include +#include #include #include @@ -85,6 +86,7 @@ #include "Common/System/System.h" #include "Common/Thread/ThreadUtil.h" #include "Common/Data/Format/IniFile.h" +#include "Common/Profiler/Profiler.h" #include "Common/TimeUtil.h" #include "Common/ArmEmitter.h" @@ -1911,6 +1913,100 @@ bool TestSymbolMap() { // Saving a symbol map and loading it back, as the debugger does while a game is running: its modules // are loaded then, possibly at other addresses than when the map was saved. +// The frame profiler: per-frame totals from nested scopes, and threads coming and going (more of them +// than there are lanes) while frames are being totalled. Only does anything with USE_PROFILER. +bool TestProfiler() { +#ifdef USE_PROFILER + PROFILE_INIT(); + PROFILE_END_FRAME(); + + { + PROFILE_THIS_SCOPE("test_outer"); + sleep_ms(20, "test"); + { + PROFILE_THIS_SCOPE("test_inner"); + sleep_ms(30, "test"); + } + } + PROFILE_END_FRAME(); + + int outerCat = -1, innerCat = -1; + for (int i = 0; i < Profiler_GetNumCategories(); i++) { + if (!strcmp(Profiler_GetCategoryName(i), "test_outer")) + outerCat = i; + if (!strcmp(Profiler_GetCategoryName(i), "test_inner")) + innerCat = i; + } + EXPECT_TRUE(outerCat >= 0 && innerCat >= 0); + const int len = Profiler_GetHistoryLength(); + std::vector outer(len), inner(len); + std::vector counts(len); + // This thread's lane is the one with test_inner time in it. + int lane = -1; + for (int t = 0; t < Profiler_GetNumThreads(); t++) { + Profiler_GetHistory(innerCat, t, inner.data(), len); + if (inner[len - 1] > 0.0f) + lane = t; + } + EXPECT_TRUE(lane >= 0); + Profiler_GetHistory(outerCat, lane, outer.data(), len); + Profiler_GetHistory(innerCat, lane, inner.data(), len); + Profiler_GetHistoryCounts(innerCat, lane, counts.data(), len); + // Outer gets only its own time, not the inner scope's. Sleeps run long, never short. + EXPECT_TRUE(outer[len - 1] >= 0.019f && outer[len - 1] < 0.035f); + EXPECT_TRUE(inner[len - 1] >= 0.029f && inner[len - 1] < 0.045f); + EXPECT_EQ_INT(counts[len - 1], 1); + + // A scope open across a frame end is split between the frames. + { + PROFILE_THIS_SCOPE("test_outer"); + sleep_ms(10, "test"); + PROFILE_END_FRAME(); + sleep_ms(10, "test"); + } + PROFILE_END_FRAME(); + Profiler_GetHistory(outerCat, lane, outer.data(), len); + EXPECT_TRUE(outer[len - 2] >= 0.009f && outer[len - 2] < 0.025f); + EXPECT_TRUE(outer[len - 1] >= 0.009f && outer[len - 1] < 0.025f); + + // Short-lived threads, more at once than there are lanes, while another thread ends frames and + // reads the events. + std::atomic stop{}; + std::thread reader([&] { + std::vector events; + while (!stop) { + PROFILE_END_FRAME(); + for (int t = 0; t < Profiler_GetNumThreads(); t++) { + events.clear(); + Profiler_GetEvents(t, 0, Profiler_Now(), &events); + } + std::this_thread::yield(); + } + }); + for (int round = 0; round < 4; round++) { + std::vector threads; + for (int i = 0; i < 40; i++) { + threads.emplace_back([] { + for (int j = 0; j < 2000; j++) { + PROFILE_THIS_SCOPE("test_a"); + PROFILE_THIS_SCOPE("test_b"); + for (int k = 0; k < 40; k++) { + PROFILE_THIS_SCOPE_DYNAMIC((k & 1) ? "test_c" : "test_d"); + } + } + }); + } + for (auto &t : threads) { + t.join(); + } + } + stop = true; + reader.join(); + EXPECT_TRUE(Profiler_GetNumThreads() <= 32); +#endif + return true; +} + bool TestSymbolMapFiles() { const u32 kModStart = 0x08804000; const u32 kModSize = 0x00010000; @@ -4789,6 +4885,7 @@ TestItem availableTests[] = { TEST_ITEM(BlockAllocator), TEST_ITEM(SymbolMap), TEST_ITEM(SymbolMapFiles), + TEST_ITEM(Profiler), TEST_ITEM(Hashmaps), TEST_ITEM(Breakpoints), TEST_ITEM(TempBreakpoints), From 1db3a7ecce58c7c2c67c75488063e07dad4301ad Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 09:55:12 +0100 Subject: [PATCH 2/9] Profiler: Log stalls without the UI, and compile it in with a runtime switch --profile-log=FILE writes each frame's per-thread totals as JSON lines, and for each slow frame every scope of at least --profile-span-ms that ended in it, with its own time. A frame is slow if it takes at least --profile-hitch-ms and 1.5 times the median of the frames before it (a 30 fps game takes 33 ms every frame). Slow frames also get a line in the log naming their longest scopes. Tools/profile_report.py tells stalls (frames that fell behind the emulated time they covered, counted with a new vblank scope) from frames where the game just didn't flip, and sums up what the stalls' time went to. PROFILE_LABEL names a scope: syscalls get the function's name, CoreTiming events (now a scope) the event's, module loads the file and pipeline creation the pipeline's tag. New scopes cover sleeps (labelled with their reason, and the frame-idle wait now goes through sleep_us), Vulkan's waits for the GPU, the render thread, pipelines and shaders, and GPU memory copies, uploads and framebuffer readbacks. The profiler is now compiled in everywhere except iOS, UWP, libretro and Android release builds, and off until --profile-log, the frame profile overlay or an ImGui profiler window turns it on. Off, a scope costs a load and a branch. While on, syscalls compiled by the JIT go through CallSyscall, which has the scope (decided in GetQuickSyscallFunc, instead of at build time in each backend). The frame profile overlay's slot is no longer build-dependent. Co-Authored-By: Claude Opus 5.5 --- Common/GPU/Vulkan/VulkanQueueRunner.cpp | 2 + Common/GPU/Vulkan/VulkanRenderManager.cpp | 20 +- Common/Profiler/Profiler.cpp | 293 ++++++++++++++++-- Common/Profiler/Profiler.h | 52 +++- Common/TimeUtil.cpp | 9 + Core/CmdLine.cpp | 11 + Core/CmdLine.h | 4 + Core/ConfigValues.h | 4 +- Core/CoreTiming.cpp | 2 + Core/HLE/HLE.cpp | 6 + Core/HLE/sceDisplay.cpp | 6 +- Core/HLE/sceKernelModule.cpp | 3 + Core/MIPS/ARM/ArmIRCompSystem.cpp | 9 +- Core/MIPS/ARM64/Arm64IRCompSystem.cpp | 9 +- .../LoongArch64/LoongArch64CompSystem.cpp | 9 +- Core/MIPS/RiscV/RiscVCompSystem.cpp | 9 +- Core/MIPS/x86/X64IRCompSystem.cpp | 7 +- GPU/Common/FramebufferManagerCommon.cpp | 3 + GPU/GPUCommon.cpp | 3 + Tools/profile_report.py | 205 ++++++++++++ UI/DevScreens.cpp | 2 - UI/EmuScreen.cpp | 2 - UI/ImDebugger/ImProfiler.cpp | 34 +- UI/ProfilerDraw.cpp | 1 + android/build.gradle.kts | 7 + unittest/UnitTest.cpp | 18 +- 26 files changed, 632 insertions(+), 98 deletions(-) create mode 100644 Tools/profile_report.py diff --git a/Common/GPU/Vulkan/VulkanQueueRunner.cpp b/Common/GPU/Vulkan/VulkanQueueRunner.cpp index 0b4ca51983..ef48084812 100644 --- a/Common/GPU/Vulkan/VulkanQueueRunner.cpp +++ b/Common/GPU/Vulkan/VulkanQueueRunner.cpp @@ -5,6 +5,7 @@ #include "Common/GPU/Vulkan/VulkanQueueRunner.h" #include "Common/GPU/Vulkan/VulkanRenderManager.h" #include "Common/Log.h" +#include "Common/Profiler/Profiler.h" #include "Common/TimeUtil.h" #include "Common/VR/PPSSPPVR.h" @@ -1303,6 +1304,7 @@ void VulkanQueueRunner::PerformRenderPass(const VKRStep &step, VkCommandBuffer c if (compileHere) { graphicsPipeline->Create(vulkan_, renderPass->Get(vulkan_, rpType, fbSampleCount), rpType, fbSampleCount, time_now_d(), -1); } + PROFILE_THIS_SCOPE("wait_pipeline"); VkPipeline pipeline = promise->BlockUntilReady(); if (pipeline != VK_NULL_HANDLE) { diff --git a/Common/GPU/Vulkan/VulkanRenderManager.cpp b/Common/GPU/Vulkan/VulkanRenderManager.cpp index 8632a5423d..b73fa8a6d5 100644 --- a/Common/GPU/Vulkan/VulkanRenderManager.cpp +++ b/Common/GPU/Vulkan/VulkanRenderManager.cpp @@ -30,6 +30,8 @@ using namespace PPSSPP_VK; // renderPass is an example of the "compatibility class" or RenderPassType type. bool VKRGraphicsPipeline::Create(VulkanContext *vulkan, VkRenderPass compatibleRenderPass, RenderPassType rpType, VkSampleCountFlagBits sampleCount, double scheduleTime, int countToCompile) { + PROFILE_THIS_SCOPE("pipeline_create"); + PROFILE_LABEL_COPY(tag_.c_str()); // Good torture test to test the shutdown-while-precompiling-shaders issue on PC where it's normally // hard to catch because shaders compile so fast. // sleep_ms(200); @@ -52,8 +54,12 @@ bool VKRGraphicsPipeline::Create(VulkanContext *vulkan, VkRenderPass compatibleR } // Fill in the last part of the desc since now it's time to block. - VkShaderModule vs = desc->vertexShader->BlockUntilReady(); - VkShaderModule fs = desc->fragmentShader->BlockUntilReady(); + VkShaderModule vs, fs; + { + PROFILE_THIS_SCOPE("wait_shaders"); + vs = desc->vertexShader->BlockUntilReady(); + fs = desc->fragmentShader->BlockUntilReady(); + } if (!vs || !fs) { ERROR_LOG(Log::G3D, "Failed creating graphics pipeline - missing shader modules"); @@ -968,6 +974,7 @@ void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfile // Makes sure the submission from the previous time around has happened. Otherwise // we are not allowed to wait from another thread here.. if (useRenderThread_) { + PROFILE_THIS_SCOPE("wait_submit"); std::unique_lock lock(frameData.fenceMutex); while (!frameData.readyForFence) { frameData.fenceCondVar.wait(lock); @@ -984,8 +991,11 @@ void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfile // This must be the very first Vulkan call we do in a new frame. // Makes sure the very last command buffer from the frame before the previous has been fully executed. - if (vkWaitForFences(device, 1, &frameData.fence, true, UINT64_MAX) == VK_ERROR_DEVICE_LOST) { - _assert_msg_(false, "Device lost in vkWaitForFences"); + { + PROFILE_THIS_SCOPE("wait_gpu"); + if (vkWaitForFences(device, 1, &frameData.fence, true, UINT64_MAX) == VK_ERROR_DEVICE_LOST) { + _assert_msg_(false, "Device lost in vkWaitForFences"); + } } if (!RecreatePresentationIfNeeded()) { @@ -2028,6 +2038,8 @@ void VulkanRenderManager::FlushSync() { } { + // Waits for the render thread to run everything queued so far, and the GPU to finish it. + PROFILE_THIS_SCOPE("wait_sync"); std::unique_lock lock(syncMutex_); // Wait for the flush to be hit, since we're syncing. while (!frameData.syncDone) { diff --git a/Common/Profiler/Profiler.cpp b/Common/Profiler/Profiler.cpp index 8e44d9a7cf..60f4899e90 100644 --- a/Common/Profiler/Profiler.cpp +++ b/Common/Profiler/Profiler.cpp @@ -11,6 +11,11 @@ #ifdef USE_PROFILER +#include +#include + +#include "Common/File/FileUtil.h" +#include "Common/File/Path.h" #include "Common/Log.h" #include "Common/StringUtils.h" #include "Common/Thread/ThreadUtil.h" @@ -21,6 +26,10 @@ #define MAX_DEPTH 32 // Deeper scopes are recorded at this level. #define LANE_EVENTS 16384 // Must be a power of 2. 256 KB a thread. #define HISTORY_SIZE 128 // Must be a power of 2. +#define LABEL_COPIES 64 +#define RECENT_FRAMES 61 +#define MAX_FRAME_SPANS 4096 +#define NO_EVENT UINT64_MAX namespace { @@ -34,13 +43,31 @@ struct Lane { // Owning thread only. int depth = 0; + // Event index of each open scope's Begin, for labelling it. NO_EVENT if it wasn't recorded. + uint64_t openBegin[MAX_DEPTH]{}; + char labelCopies[LABEL_COPIES][48]{}; + int labelCopyPos = 0; // End of frame only (one thread). Replays the events to attribute the time between them to the - // innermost open scope. + // innermost open scope, and to find the long scopes. uint64_t aggRead = 0; uint64_t aggLastTicks = 0; int aggDepth = 0; uint16_t aggStack[MAX_DEPTH]{}; + uint64_t aggBeginTicks[MAX_DEPTH]{}; + const char *aggBeginLabel[MAX_DEPTH]{}; + bool aggBeginValid[MAX_DEPTH]{}; +}; + +// A scope that ended in the current frame, long enough to log. +struct Span { + int lane; + int category; + int level; + uint64_t begin; + uint64_t end; + const char *label; + uint64_t self; // Minus the logged spans nested in it. }; struct FrameTotals { @@ -58,7 +85,6 @@ const char *g_categories[MAX_CATEGORIES]; std::atomic g_numCategories; std::mutex g_categoriesMutex; -std::atomic g_paused; bool g_initialized; // End of frame only, apart from reads of the finished frames. @@ -68,6 +94,14 @@ int g_historyPos; double g_secondsPerTick; uint64_t g_startTicks; +// Logging. Set before init or from the end-of-frame thread. +double g_hitchMs; +double g_spanMs; +FILE *g_logFile; +uint64_t g_lastFrameEnd; +uint64_t g_frameNumber; +std::vector g_frameSpans; + struct LaneOwner { Lane *lane = nullptr; bool failed = false; @@ -114,14 +148,17 @@ inline Lane *CurrentLane() { return owner.lane; } -inline void Record(Lane *lane, ProfilerEventType type, int category, int level) { +// Returns the event's index. +inline uint64_t Record(Lane *lane, ProfilerEventType type, int category, int level) { const uint64_t w = lane->written.load(std::memory_order_relaxed); ProfilerEvent &e = lane->events[w & (LANE_EVENTS - 1)]; e.ticks = time_now_fast_ticks(); + e.label = nullptr; e.category = (uint16_t)category; e.type = type; - e.level = (int8_t)std::min(level, MAX_DEPTH - 1); + e.level = (int8_t)level; lane->written.store(w + 1, std::memory_order_release); + return w; } // Copies event index i of the lane. False if the writer has overwritten (or may be overwriting) it. @@ -145,18 +182,23 @@ void Attribute(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t until) { } } -void AggregateLane(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t frameEnd) { +void LoseTrack(Lane *lane) { + lane->aggDepth = 0; + memset(lane->aggBeginValid, 0, sizeof(lane->aggBeginValid)); +} + +void AggregateLane(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t frameEnd, uint64_t spanTicks) { const uint64_t written = lane->written.load(std::memory_order_acquire); uint64_t i = lane->aggRead; if (i < OldestReadable(written)) { // Lost some, so the open scopes are unknown. The next event's level resyncs them. i = OldestReadable(written); - lane->aggDepth = 0; + LoseTrack(lane); } for (; i < written; i++) { ProfilerEvent e; if (!ReadEvent(lane, i, &e)) { - lane->aggDepth = 0; + LoseTrack(lane); continue; } if (e.ticks > frameEnd) { @@ -167,12 +209,24 @@ void AggregateLane(Lane *lane, int laneIndex, FrameTotals &frame, uint64_t frame lane->aggLastTicks = e.ticks; } Attribute(lane, laneIndex, frame, e.ticks); + const int level = e.level; if (e.type == ProfilerEventType::Begin) { - lane->aggStack[e.level] = e.category; - lane->aggDepth = e.level + 1; + lane->aggStack[level] = e.category; + lane->aggDepth = level + 1; + lane->aggBeginTicks[level] = e.ticks; + // The label may come after this read, if a frame ended in between. Rare enough. + lane->aggBeginLabel[level] = e.label; + lane->aggBeginValid[level] = true; } else { - lane->aggDepth = e.level; + lane->aggDepth = level; frame.counts[laneIndex][e.category]++; + if (lane->aggBeginValid[level] && lane->aggStack[level] == e.category) { + const uint64_t length = e.ticks - lane->aggBeginTicks[level]; + if (spanTicks && length >= spanTicks && g_frameSpans.size() < MAX_FRAME_SPANS) { + g_frameSpans.push_back(Span{ laneIndex, e.category, level, lane->aggBeginTicks[level], e.ticks, lane->aggBeginLabel[level], length }); + } + } + lane->aggBeginValid[level] = false; } } lane->aggRead = i; @@ -184,8 +238,143 @@ int HistoryIndex(int i, int count) { return (g_historyPos - count + i + HISTORY_SIZE) & (HISTORY_SIZE - 1); } +// Writes s as a JSON string. +void WriteJsonString(FILE *f, const char *s) { + fputc('"', f); + for (; *s; s++) { + const unsigned char c = (unsigned char)*s; + if (c == '"' || c == '\\') { + fputc('\\', f); + fputc(c, f); + } else if (c < 0x20) { + fprintf(f, "\\u%04x", c); + } else { + fputc(c, f); + } + } + fputc('"', f); +} + +double TicksToMs(uint64_t ticks) { + return ticks * g_secondsPerTick * 1000.0; +} + +// Recent frame lengths, for what's normal for the game right now. +double g_recentFrameMs[RECENT_FRAMES]; +int g_recentFramePos; + +void LogFrame(const FrameTotals &frame, int numLanes, uint64_t frameStart, uint64_t frameEnd) { + const double frameMs = TicksToMs(frameEnd - frameStart); + // Slow both in absolute terms and for the game: one that runs at 30 fps takes 33 ms every frame. + double sorted[RECENT_FRAMES]; + memcpy(sorted, g_recentFrameMs, sizeof(sorted)); + std::nth_element(sorted, sorted + RECENT_FRAMES / 2, sorted + RECENT_FRAMES); + const double typicalMs = sorted[RECENT_FRAMES / 2]; + g_recentFrameMs[g_recentFramePos] = frameMs; + g_recentFramePos = (g_recentFramePos + 1) % RECENT_FRAMES; + const bool hitch = frameMs >= g_hitchMs && frameMs >= typicalMs * 1.5; + const int numCategories = g_numCategories.load(std::memory_order_acquire); + + char names[MAX_LANES][32]; + { + std::lock_guard guard(g_lanesMutex); + for (int i = 0; i < numLanes; i++) { + truncate_cpy(names[i], g_lanes[i]->name); + } + } + + // Self time of each span: what's left after the logged spans directly inside it. + std::sort(g_frameSpans.begin(), g_frameSpans.end(), [](const Span &a, const Span &b) { + return a.lane != b.lane ? a.lane < b.lane : (a.begin != b.begin ? a.begin < b.begin : a.level < b.level); + }); + for (size_t i = 0; i < g_frameSpans.size(); i++) { + Span &parent = g_frameSpans[i]; + for (size_t j = i + 1; j < g_frameSpans.size(); j++) { + const Span &child = g_frameSpans[j]; + if (child.lane != parent.lane || child.begin >= parent.end) { + break; + } + if (child.level == parent.level + 1 && child.end <= parent.end) { + parent.self -= std::min(parent.self, child.end - child.begin); + } + } + } + + if (FILE *f = g_logFile) { + fprintf(f, "{\"f\":%llu,\"t\":%0.4f,\"ms\":%0.2f,\"typ\":%0.1f,%s\"th\":{", (unsigned long long)g_frameNumber, TicksToMs(frameEnd - g_startTicks) * 0.001, frameMs, typicalMs, hitch ? "\"slow\":1," : ""); + bool firstLane = true; + for (int l = 0; l < numLanes; l++) { + bool firstCat = true; + for (int c = 0; c < numCategories; c++) { + if (frame.seconds[l][c] <= 0.0f && frame.counts[l][c] == 0) { + continue; + } + if (firstCat) { + fputs(firstLane ? "" : ",", f); + WriteJsonString(f, names[l]); + fputs(":{", f); + firstLane = false; + } + fputs(firstCat ? "" : ",", f); + WriteJsonString(f, g_categories[c]); + fprintf(f, ":[%0.3f,%d]", frame.seconds[l][c] * 1000.0f, frame.counts[l][c]); + firstCat = false; + } + if (!firstCat) { + fputc('}', f); + } + } + fputs("}}\n", f); + if (hitch) { + for (const Span &s : g_frameSpans) { + fprintf(f, "{\"span\":%llu,\"th\":", (unsigned long long)g_frameNumber); + WriteJsonString(f, names[s.lane]); + fputs(",\"c\":", f); + WriteJsonString(f, g_categories[s.category]); + if (s.label) { + fputs(",\"n\":", f); + WriteJsonString(f, s.label); + } + fprintf(f, ",\"l\":%d,\"t\":%0.4f,\"ms\":%0.3f,\"self\":%0.3f}\n", s.level, TicksToMs(s.begin - g_startTicks) * 0.001, TicksToMs(s.end - s.begin), TicksToMs(s.self)); + } + fflush(f); + } else if ((g_frameNumber & 63) == 0) { + fflush(f); + } + } + + if (!hitch) { + return; + } + // The log line: the spans that took the most time themselves, leaving out plain sleeps. + std::vector worst; + for (const Span &s : g_frameSpans) { + if (strcmp(g_categories[s.category], "sleep") != 0) { + worst.push_back(&s); + } + } + std::sort(worst.begin(), worst.end(), [](const Span *a, const Span *b) { return a->self > b->self; }); + int vblanks = 0; + for (int c = 0; c < numCategories; c++) { + if (!strcmp(g_categories[c], "vblank")) { + for (int l = 0; l < numLanes; l++) { + vblanks += frame.counts[l][c]; + } + } + } + char buf[512]; + size_t len = snprintf(buf, sizeof(buf), "Profiler: Frame %llu took %0.1f ms (typically %0.1f), %d vblanks.", (unsigned long long)g_frameNumber, frameMs, typicalMs, vblanks); + for (size_t i = 0; i < worst.size() && i < 6 && len < sizeof(buf); i++) { + const Span &s = *worst[i]; + len += snprintf(buf + len, sizeof(buf) - len, " %s %s%s%s %0.1f/%0.1f ms.", names[s.lane], g_categories[s.category], s.label ? ":" : "", s.label ? s.label : "", TicksToMs(s.self), TicksToMs(s.end - s.begin)); + } + INFO_LOG(Log::System, "%s", buf); +} + } // namespace +std::atomic g_profilerEnabled; + void internal_profiler_init() { if (g_initialized) { return; @@ -226,10 +415,37 @@ void Profiler_Enter(int category) { if (!lane) { return; } - const int level = lane->depth++; - if (!g_paused.load(std::memory_order_relaxed)) { - Record(lane, ProfilerEventType::Begin, category, level); + const int level = std::min(lane->depth++, MAX_DEPTH - 1); + lane->openBegin[level] = Record(lane, ProfilerEventType::Begin, category, level); +} + +void Profiler_Label(const char *text) { + if (!g_initialized || !text) { + return; } + Lane *lane = CurrentLane(); + if (!lane || lane->depth == 0) { + return; + } + const uint64_t index = lane->openBegin[std::min(lane->depth - 1, MAX_DEPTH - 1)]; + // Unless the ring has moved past it. + if (index != NO_EVENT && index + LANE_EVENTS > lane->written.load(std::memory_order_relaxed)) { + lane->events[index & (LANE_EVENTS - 1)].label = text; + } +} + +void Profiler_LabelCopy(const char *text) { + if (!g_initialized || !text) { + return; + } + Lane *lane = CurrentLane(); + if (!lane || lane->depth == 0) { + return; + } + char *copy = lane->labelCopies[lane->labelCopyPos]; + lane->labelCopyPos = (lane->labelCopyPos + 1) % LABEL_COPIES; + truncate_cpy(copy, sizeof(lane->labelCopies[0]), text); + Profiler_Label(copy); } void Profiler_Leave(int category) { @@ -241,14 +457,17 @@ void Profiler_Leave(int category) { if (!lane || lane->depth == 0) { return; } - const int level = --lane->depth; - if (!g_paused.load(std::memory_order_relaxed)) { - Record(lane, ProfilerEventType::End, category, level); - } + const int level = std::min(--lane->depth, MAX_DEPTH - 1); + Record(lane, ProfilerEventType::End, category, level); } void internal_profiler_end_frame() { - if (!g_initialized || g_paused.load(std::memory_order_relaxed)) { + if (!g_initialized) { + return; + } + if (!Profiler_IsEnabled()) { + // So the first frame after turning it back on isn't taken for a long one. + g_lastFrameEnd = 0; return; } const uint64_t now = time_now_fast_ticks(); @@ -256,11 +475,39 @@ void internal_profiler_end_frame() { FrameTotals &frame = g_history[pos]; memset(&frame, 0, sizeof(frame)); const int numLanes = g_numLanes.load(std::memory_order_acquire); + const bool logging = g_hitchMs > 0.0; + const uint64_t spanTicks = logging ? std::max(1, (uint64_t)(g_spanMs * 0.001 / g_secondsPerTick)) : 0; + g_frameSpans.clear(); for (int i = 0; i < numLanes; i++) { - AggregateLane(g_lanes[i], i, frame, now); + AggregateLane(g_lanes[i], i, frame, now, spanTicks); } g_frameEnds[pos] = now; g_historyPos = (pos + 1) & (HISTORY_SIZE - 1); + + if (logging && g_lastFrameEnd != 0) { + LogFrame(frame, numLanes, g_lastFrameEnd, now); + } + g_lastFrameEnd = now; + g_frameNumber++; +} + +void Profiler_SetLogging(const char *path, double hitchMs, double spanMs) { + if (g_logFile) { + fclose(g_logFile); + g_logFile = nullptr; + } + g_hitchMs = hitchMs; + g_spanMs = spanMs; + if (hitchMs > 0.0) { + Profiler_SetEnabled(true); + } + if (hitchMs > 0.0 && path && path[0]) { + g_logFile = File::OpenCFile(Path(path), "wb"); + if (!g_logFile) { + ERROR_LOG(Log::System, "Profiler: Couldn't open %s for the log", path); + } + } + INFO_LOG(Log::System, "Profiler: Logging frames of %0.1f ms or more%s%s", hitchMs, g_logFile ? " to " : "", g_logFile ? path : ""); } const char *Profiler_GetCategoryName(int i) { @@ -329,12 +576,8 @@ void Profiler_GetHistoryCounts(int category, int thread, int *data, int count) { } } -void Profiler_SetPaused(bool paused) { - g_paused.store(paused, std::memory_order_relaxed); -} - -bool Profiler_IsPaused() { - return g_paused.load(std::memory_order_relaxed); +void Profiler_SetEnabled(bool enabled) { + g_profilerEnabled.store(enabled, std::memory_order_relaxed); } uint64_t Profiler_Now() { diff --git a/Common/Profiler/Profiler.h b/Common/Profiler/Profiler.h index de40165f3f..4fe35f51ed 100644 --- a/Common/Profiler/Profiler.h +++ b/Common/Profiler/Profiler.h @@ -1,9 +1,17 @@ #pragma once +#include #include #include -// #define USE_PROFILER +#include "ppsspp_config.h" + +// Compiled in everywhere but iOS, UWP, libretro and builds that define NO_PROFILER (Android release +// builds), and off until something turns it on (Profiler_SetEnabled), which costs a scope one load and +// a branch. Check USE_PROFILER only after including this file. +#if !defined(USE_PROFILER) && !defined(NO_PROFILER) && !PPSSPP_PLATFORM(IOS) && !PPSSPP_PLATFORM(UWP) && !defined(__LIBRETRO__) +#define USE_PROFILER +#endif #ifdef USE_PROFILER @@ -14,6 +22,13 @@ void internal_profiler_init(); void internal_profiler_end_frame(); +extern std::atomic g_profilerEnabled; +// While off, nothing is recorded and the history stands still. +void Profiler_SetEnabled(bool enabled); +inline bool Profiler_IsEnabled() { + return g_profilerEnabled.load(std::memory_order_relaxed); +} + // Returns the category number for a name, adding it if new. Names are compared by pointer first, so // a string literal is cheap to look up. int Profiler_GetCategory(const char *name); @@ -22,11 +37,16 @@ void Profiler_Leave(int category); class ProfileThis { public: - explicit ProfileThis(int category) : category_(category) { - Profiler_Enter(category); + explicit ProfileThis(int category) : category_(Profiler_IsEnabled() ? category : -1) { + if (category_ >= 0) { + Profiler_Enter(category_); + } } ~ProfileThis() { - Profiler_Leave(category_); + // Left even if the profiler was turned off meanwhile, so Begins and Ends pair up. + if (category_ >= 0) { + Profiler_Leave(category_); + } } private: int category_; @@ -44,6 +64,22 @@ private: #define PROFILE_THIS_SCOPE_DYNAMIC(cat) ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_GetCategory(cat)); #define PROFILE_END_FRAME() internal_profiler_end_frame(); +// Names this thread's innermost open scope (which syscall, which file) in the log and the timeline. +// The text must outlive the profiler, like a literal or a name in a static table. +void Profiler_Label(const char *text); +// The same for text that won't live that long: copies the first 47 characters into the thread's lane, +// which keeps the last 64 copies. +void Profiler_LabelCopy(const char *text); +#define PROFILE_LABEL(text) do { if (Profiler_IsEnabled()) { Profiler_Label(text); } } while (false) +#define PROFILE_LABEL_COPY(text) do { if (Profiler_IsEnabled()) { Profiler_LabelCopy(text); } } while (false) + +// Logs stalls without the UI. Any frame (between two PROFILE_END_FRAME calls) of at least hitchMs gets +// a line in the log naming its longest scopes. With a path, every frame's per-thread totals go to that +// file as JSON lines, and for each frame of at least hitchMs, every scope of at least spanMs that ended +// in it. Tools/profile_report.py summarizes the file. Turns the profiler on, unless hitchMs <= 0, which +// turns the logging off. +void Profiler_SetLogging(const char *path, double hitchMs, double spanMs); + // Per-frame totals, in seconds of time spent in each category itself (not in scopes nested in it). // A frame is the time between two PROFILE_END_FRAME() calls; history index count - 1 is the last one. const char *Profiler_GetCategoryName(int i); @@ -57,10 +93,6 @@ void Profiler_GetHistory(int category, int thread, float *data, int count); // How many times each scope of the category was left in the frame. void Profiler_GetHistoryCounts(int category, int thread, int *data, int count); -// While paused, nothing is recorded and the history stands still. -void Profiler_SetPaused(bool paused); -bool Profiler_IsPaused(); - // For the timeline. enum class ProfilerEventType : uint8_t { Begin, @@ -69,6 +101,8 @@ enum class ProfilerEventType : uint8_t { struct ProfilerEvent { uint64_t ticks; + // From PROFILE_LABEL, on a Begin. Null if none. + const char *label; uint16_t category; ProfilerEventType type; // Nesting depth, 0 at the outermost scope. Begin and End of one scope have the same level. @@ -93,5 +127,7 @@ void Profiler_GetFrameEnds(std::vector *ends); #define PROFILE_THIS_SCOPE(cat) #define PROFILE_THIS_SCOPE_DYNAMIC(cat) #define PROFILE_END_FRAME() +#define PROFILE_LABEL(text) +#define PROFILE_LABEL_COPY(text) #endif diff --git a/Common/TimeUtil.cpp b/Common/TimeUtil.cpp index f0d1d4c70f..9599351d38 100644 --- a/Common/TimeUtil.cpp +++ b/Common/TimeUtil.cpp @@ -5,6 +5,7 @@ #include #include "Common/TimeUtil.h" +#include "Common/Profiler/Profiler.h" #include "Common/Data/Random/Rng.h" #include "Common/Log.h" @@ -290,6 +291,8 @@ void sleep_ms(int ms, const char *reason) { if (ms <= 0) { return; } + PROFILE_THIS_SCOPE("sleep"); + PROFILE_LABEL(reason); #if SLEEP_LOG_ENABLED INFO_LOG(Log::System, "Sleep %d ms: %s", ms, reason); #endif @@ -308,6 +311,8 @@ void sleep_us(int us, const char *reason) { if (us <= 0) { return; } + PROFILE_THIS_SCOPE("sleep"); + PROFILE_LABEL(reason); #if SLEEP_LOG_ENABLED INFO_LOG(Log::System, "Sleep %d us: %s", us, reason); #endif @@ -327,6 +332,8 @@ void sleep_precise(double seconds, const char *reason) { if (seconds <= 0.0) { return; } + PROFILE_THIS_SCOPE("sleep"); + PROFILE_LABEL(reason); #if SLEEP_LOG_ENABLED INFO_LOG(Log::System, "Sleep precise %f s: %s", seconds, reason); #endif @@ -384,6 +391,8 @@ void sleep_approx(double seconds, const char *reason) { if (seconds <= 0.0) { return; } + PROFILE_THIS_SCOPE("sleep"); + PROFILE_LABEL(reason); #if SLEEP_LOG_ENABLED INFO_LOG(Log::System, "Sleep approx %f s: %s", seconds, reason); #endif diff --git a/Core/CmdLine.cpp b/Core/CmdLine.cpp index 1ab2a44079..41c2951d41 100644 --- a/Core/CmdLine.cpp +++ b/Core/CmdLine.cpp @@ -10,6 +10,7 @@ #include "Core/WebServer.h" #include "Core/Util/PathUtil.h" #include "Common/File/FileUtil.h" +#include "Common/Profiler/Profiler.h" #include "Common/StringUtils.h" #include "Common/Log/LogManager.h" @@ -267,6 +268,9 @@ static const CommandLineParam g_autoParams[] = { {POFF(adhocDelayMs), CmdParamType::Int, "adhoc-delay", '\0', "Delay ad hoc datagrams received by MS milliseconds of emulated time, to simulate a distant player"}, {POFF(adhocJitterMs), CmdParamType::Int, "adhoc-jitter", '\0', "With --adhoc-delay, up to MS more at random"}, {POFF(adhocLossPercent), CmdParamType::Int, "adhoc-loss", '\0', "Drop this percentage of the ad hoc datagrams received"}, + {POFF(profileLog), CmdParamType::String, "profile-log", '\0', "Profiler builds: write each frame's profile, and the long scopes of slow frames, to FILE as JSON lines (see Tools/profile_report.py)"}, + {POFF(profileHitchMs), CmdParamType::Double, "profile-hitch-ms", '\0', "Profiler builds: log frames taking at least MS milliseconds (default 25)"}, + {POFF(profileSpanMs), CmdParamType::Double, "profile-span-ms", '\0', "Profiler builds: in slow frames, log the scopes of at least MS milliseconds (default 1)"}, {POFF(lagSync), CmdParamType::Bool, "lag-sync", '\0', "Keep emulated time in step with the wall clock every millisecond, not every frame (the Force real clock sync setting)"}, {POFF(frameStats), CmdParamType::Bool, "frame-stats", '\0', "Print flips per emulated second at the end of the run, counted from --state's load", CmdLineMode::Headless}, {POFF(audioSinkPeriod), CmdParamType::Int, "audio-sink", '\0', "Pull audio like an output device, FRAMES at 48 kHz at a time, and print the buffer's stats at the end (with --realtime)", CmdLineMode::Headless}, @@ -593,6 +597,13 @@ CommandLineParseResult CommandLineOptions::Parse(int argc, const char *argv[], C } void CommandLineOptions::ApplyToConfig() const { + if (profileLog.has_value() || profileHitchMs.has_value()) { +#ifdef USE_PROFILER + Profiler_SetLogging(profileLog.value_or("").c_str(), profileHitchMs.value_or(25.0), profileSpanMs.value_or(1.0)); +#else + WARN_LOG(Log::System, "--profile-log and --profile-hitch-ms need a build with USE_PROFILER"); +#endif + } if (adhocServer.has_value()) { g_Config.bEnableAdhocServer = adhocServer.value(); g_Config.DoNotSaveSetting(&g_Config.bEnableAdhocServer); diff --git a/Core/CmdLine.h b/Core/CmdLine.h index 5e6c88cf0f..9c8c680adf 100644 --- a/Core/CmdLine.h +++ b/Core/CmdLine.h @@ -219,6 +219,10 @@ struct CommandLineOptions { std::optional adhocDelayMs; std::optional adhocJitterMs; std::optional adhocLossPercent; + // Frame profiler logging (builds with USE_PROFILER). See Profiler_SetLogging. + std::optional profileLog; + std::optional profileHitchMs; + std::optional profileSpanMs; std::optional screenshotFilename; std::optional screenshotFilenameSave; diff --git a/Core/ConfigValues.h b/Core/ConfigValues.h index 64d2baae98..0e87547407 100644 --- a/Core/ConfigValues.h +++ b/Core/ConfigValues.h @@ -290,9 +290,7 @@ enum class DebugOverlay : int { DEBUG_STATS, FRAME_GRAPH, FRAME_TIMING, -#ifdef USE_PROFILER - FRAME_PROFILE, -#endif + FRAME_PROFILE, // Draws nothing in builds without USE_PROFILER. CONTROL, Audio, GPU_PROFILE, diff --git a/Core/CoreTiming.cpp b/Core/CoreTiming.cpp index 04aef5f5bd..7083385e9e 100644 --- a/Core/CoreTiming.cpp +++ b/Core/CoreTiming.cpp @@ -409,6 +409,8 @@ void ProcessEvents() { Event *evt = first; first = first->next; if (evt->type >= 0 && evt->type < (int)event_types.size()) { + PROFILE_THIS_SCOPE("event"); + PROFILE_LABEL(event_types[evt->type].name); event_types[evt->type].callback(evt->userdata, (int)(GetTicks(currentMIPS) - evt->time)); } else { _dbg_assert_msg_(false, "Bad event type %d", evt->type); diff --git a/Core/HLE/HLE.cpp b/Core/HLE/HLE.cpp index f6076c9a4d..2e62931bb1 100644 --- a/Core/HLE/HLE.cpp +++ b/Core/HLE/HLE.cpp @@ -1197,6 +1197,11 @@ const HLEFunction *GetSyscallFunctionData(MIPSOpcode op, u32 pcForDiagnostics) { void *GetQuickSyscallFunc(const HLEFunction *info, MIPSOpcode op) { if (g_coreCollectDebugStats) return nullptr; +#ifdef USE_PROFILER + // CallSyscall has the profiler scope. Blocks compiled before the profiler was turned on skip it. + if (Profiler_IsEnabled()) + return nullptr; +#endif if (!info || !info->func) return nullptr; @@ -1230,6 +1235,7 @@ void CallSyscallWithPC(MIPSState *mips, MIPSOpcode op, u32 pc) { RETURN(SCE_KERNEL_ERROR_LIBRARY_NOT_YET_LINKED); return; } + PROFILE_LABEL(info->name); if (info->func) { if (op == g_idleOp) diff --git a/Core/HLE/sceDisplay.cpp b/Core/HLE/sceDisplay.cpp index 3890eefb59..eb3cd5aab0 100644 --- a/Core/HLE/sceDisplay.cpp +++ b/Core/HLE/sceDisplay.cpp @@ -660,7 +660,7 @@ static void DoFrameIdleTiming() { #else const double left = goal - cur_time; if (left > 0.0f && left < 1.0f) { // Sanity check - usleep((long)(left * 1000000)); + sleep_us((int)(left * 1000000), "frame-idle"); } #endif } @@ -723,6 +723,8 @@ LagSyncMode __DisplayGetLagSyncMode() { } void hleEnterVblank(u64 userdata, int cyclesLate) { + // Counted per frame: Tools/profile_report.py compares a frame's length with the vblanks in it. + PROFILE_THIS_SCOPE("vblank"); int vbCount = userdata; UpdateLagSyncMode(); @@ -808,6 +810,8 @@ void __DisplaySetDisplayLayoutConfig(const DisplayLayoutConfig &config) { } void __DisplayFlip(int cyclesLate) { + // Runs on each vblank that hasn't flipped yet, and holds the frame-idle sleep. + PROFILE_THIS_SCOPE("flip"); if (!gpu) { _dbg_assert_(gpu); // Something has gone wrong. diff --git a/Core/HLE/sceKernelModule.cpp b/Core/HLE/sceKernelModule.cpp index b1602aed2c..fb559d1208 100644 --- a/Core/HLE/sceKernelModule.cpp +++ b/Core/HLE/sceKernelModule.cpp @@ -22,6 +22,7 @@ #include "zlib.h" #include "Common/Data/Convert/SmallDataConvert.h" +#include "Common/Profiler/Profiler.h" #include "Common/Serialize/Serializer.h" #include "Common/Serialize/SerializeFuncs.h" #include "Common/Serialize/SerializeMap.h" @@ -2392,6 +2393,8 @@ SceUID KernelLoadModule(const std::string &filename, std::string *error_string, // filename is only used for dumping etc. static PSPModule *__KernelLoadModule(u8 *fileptr, size_t fileSize, SceKernelLMOption *options, std::string_view filename, std::string *error_string) { + PROFILE_THIS_SCOPE("module_load"); + PROFILE_LABEL_COPY(std::string(filename).c_str()); PSPModule *module = nullptr; // Check for PBP if (fileSize >= sizeof(PSP_Header) && memcmp(fileptr, "\0PBP", 4) == 0) { diff --git a/Core/MIPS/ARM/ArmIRCompSystem.cpp b/Core/MIPS/ARM/ArmIRCompSystem.cpp index 0ccd4ab8f1..517c578c55 100644 --- a/Core/MIPS/ARM/ArmIRCompSystem.cpp +++ b/Core/MIPS/ARM/ArmIRCompSystem.cpp @@ -188,13 +188,7 @@ void ArmJitBackend::CompIR_System(IRInst inst) { SaveStaticRegisters(); WriteDebugProfilerStatus(IRProfilerStatus::SYSCALL); -#ifdef USE_PROFILER - // When profiling, we can't skip CallSyscall, since it times syscalls. - MOVP2R(R0, mips_); - MOVI2R(R1, inst.constant); - QuickCallFunction(R12, &CallSyscall); -#else - // Skip the CallSyscall where possible. + // Skip the CallSyscall where possible (GetQuickSyscallFunc says when not). { MIPSOpcode op(inst.constant); const HLEFunction *func = GetSyscallFunctionData(op, 0); @@ -216,7 +210,6 @@ void ArmJitBackend::CompIR_System(IRInst inst) { QuickCallFunction(R12, &CallSyscallUnresolvedAtPC); } } -#endif WriteDebugProfilerStatus(IRProfilerStatus::IN_JIT); LoadStaticRegisters(); diff --git a/Core/MIPS/ARM64/Arm64IRCompSystem.cpp b/Core/MIPS/ARM64/Arm64IRCompSystem.cpp index 2e3386a50b..cad25bdf8a 100644 --- a/Core/MIPS/ARM64/Arm64IRCompSystem.cpp +++ b/Core/MIPS/ARM64/Arm64IRCompSystem.cpp @@ -213,13 +213,7 @@ void Arm64JitBackend::CompIR_System(IRInst inst) { SaveStaticRegisters(); WriteDebugProfilerStatus(IRProfilerStatus::SYSCALL); -#ifdef USE_PROFILER - // When profiling, we can't skip CallSyscall, since it times syscalls. - MOVP2R(X0, mips_); - MOVI2R(W1, inst.constant); - QuickCallFunction(SCRATCH2_64, &CallSyscall); -#else - // Skip the CallSyscall where possible. + // Skip the CallSyscall where possible (GetQuickSyscallFunc says when not). { MIPSOpcode op(inst.constant); const HLEFunction *func = GetSyscallFunctionData(op, 0); @@ -241,7 +235,6 @@ void Arm64JitBackend::CompIR_System(IRInst inst) { QuickCallFunction(SCRATCH2_64, &CallSyscallUnresolvedAtPC); } } -#endif WriteDebugProfilerStatus(IRProfilerStatus::IN_JIT); LoadStaticRegisters(); diff --git a/Core/MIPS/LoongArch64/LoongArch64CompSystem.cpp b/Core/MIPS/LoongArch64/LoongArch64CompSystem.cpp index 9f9a60051f..a0e1a49fda 100644 --- a/Core/MIPS/LoongArch64/LoongArch64CompSystem.cpp +++ b/Core/MIPS/LoongArch64/LoongArch64CompSystem.cpp @@ -177,13 +177,7 @@ void LoongArch64JitBackend::CompIR_System(IRInst inst) { SaveStaticRegisters(); WriteDebugProfilerStatus(IRProfilerStatus::SYSCALL); -#ifdef USE_PROFILER - // When profiling, we can't skip CallSyscall, since it times syscalls. - LI(R4, (uintptr_t)mips_); - LI(R5, (int32_t)inst.constant); - QuickCallFunction(&CallSyscall, SCRATCH2); -#else - // Skip the CallSyscall where possible. + // Skip the CallSyscall where possible (GetQuickSyscallFunc says when not). { MIPSOpcode op(inst.constant); const HLEFunction *func = GetSyscallFunctionData(op, 0); @@ -205,7 +199,6 @@ void LoongArch64JitBackend::CompIR_System(IRInst inst) { QuickCallFunction(&CallSyscallUnresolvedAtPC, SCRATCH2); } } -#endif WriteDebugProfilerStatus(IRProfilerStatus::IN_JIT); LoadStaticRegisters(); // This is always followed by an ExitToPC, where we check coreState. diff --git a/Core/MIPS/RiscV/RiscVCompSystem.cpp b/Core/MIPS/RiscV/RiscVCompSystem.cpp index fdfe23a31d..c6be8738b1 100644 --- a/Core/MIPS/RiscV/RiscVCompSystem.cpp +++ b/Core/MIPS/RiscV/RiscVCompSystem.cpp @@ -185,13 +185,7 @@ void RiscVJitBackend::CompIR_System(IRInst inst) { SaveStaticRegisters(); WriteDebugProfilerStatus(IRProfilerStatus::SYSCALL); -#ifdef USE_PROFILER - // When profiling, we can't skip CallSyscall, since it times syscalls. - LI(X10, (uintptr_t)mips_); - LI(X11, (int32_t)inst.constant); - QuickCallFunction(&CallSyscall); -#else - // Skip the CallSyscall where possible. + // Skip the CallSyscall where possible (GetQuickSyscallFunc says when not). { MIPSOpcode op(inst.constant); const HLEFunction *func = GetSyscallFunctionData(op, 0); @@ -213,7 +207,6 @@ void RiscVJitBackend::CompIR_System(IRInst inst) { QuickCallFunction(&CallSyscallUnresolvedAtPC); } } -#endif WriteDebugProfilerStatus(IRProfilerStatus::IN_JIT); LoadStaticRegisters(); diff --git a/Core/MIPS/x86/X64IRCompSystem.cpp b/Core/MIPS/x86/X64IRCompSystem.cpp index 5db8e72338..69d1ebb3e2 100644 --- a/Core/MIPS/x86/X64IRCompSystem.cpp +++ b/Core/MIPS/x86/X64IRCompSystem.cpp @@ -204,11 +204,7 @@ void X64JitBackend::CompIR_System(IRInst inst) { SaveStaticRegisters(); WriteDebugProfilerStatus(IRProfilerStatus::SYSCALL); -#ifdef USE_PROFILER - // When profiling, we can't skip CallSyscall, since it times syscalls. - ABI_CallFunctionPA((const u8 *)&CallSyscall, mips_, Imm32(inst.constant)); -#else - // Skip the CallSyscall where possible. + // Skip the CallSyscall where possible (GetQuickSyscallFunc says when not). { MIPSOpcode op(inst.constant); const HLEFunction *func = GetSyscallFunctionData(op, 0); @@ -225,7 +221,6 @@ void X64JitBackend::CompIR_System(IRInst inst) { ABI_CallFunctionPA((const u8 *)&CallSyscallUnresolvedAtPC, mips_, Imm32(0)); } } -#endif WriteDebugProfilerStatus(IRProfilerStatus::IN_JIT); LoadStaticRegisters(); diff --git a/GPU/Common/FramebufferManagerCommon.cpp b/GPU/Common/FramebufferManagerCommon.cpp index 8c2f380281..fd1d513927 100644 --- a/GPU/Common/FramebufferManagerCommon.cpp +++ b/GPU/Common/FramebufferManagerCommon.cpp @@ -20,6 +20,7 @@ #include #include "Common/GPU/thin3d.h" +#include "Common/Profiler/Profiler.h" #include "Common/Data/Collections/TinySet.h" #include "Common/Data/Convert/ColorConv.h" #include "Common/LogReporting.h" @@ -3508,6 +3509,7 @@ bool FramebufferManagerCommon::GetOutputFramebuffer(GPUDebugBuffer &buffer) { // dithering behavior and games that expect exact colors like Danganronpa, so we // can't entirely be rid of the CPU path.) -- unknown void FramebufferManagerCommon::ReadbackFramebuffer(VirtualFramebuffer *vfb, int x, int y, int w, int h, RasterChannel channel, Draw::ReadbackMode mode, u8 *shadow) { + PROFILE_THIS_SCOPE("fb_readback"); if (w <= 0 || h <= 0) { ERROR_LOG(Log::FrameBuf, "Bad inputs to ReadbackFramebufferSync: %d %d %d %d", x, y, w, h); return; @@ -3738,6 +3740,7 @@ void FramebufferManagerCommon::FlushBeforeCopy() { // TODO: Replace with with depal, reading the palette from the texture on the GPU directly. void FramebufferManagerCommon::DownloadFramebufferForClut(u32 fb_address, u32 loadBytes) { + PROFILE_THIS_SCOPE("fb_clut_download"); VirtualFramebuffer *vfb = GetVFBAt(fb_address); // Without an fbo there's nothing to read back (ReadbackFramebuffer would read the backbuffer instead). if (vfb && vfb->fb_stride != 0 && vfb->fbo) { diff --git a/GPU/GPUCommon.cpp b/GPU/GPUCommon.cpp index 93aa816aec..b336cb9ed4 100644 --- a/GPU/GPUCommon.cpp +++ b/GPU/GPUCommon.cpp @@ -2611,6 +2611,7 @@ void GPUCommon::NotifyVideoCopy(u32 dest, u32 src, int size) { } bool GPUCommon::PerformMemoryCopy(u32 dest, u32 src, int size, GPUCopyFlag flags) { + PROFILE_THIS_SCOPE("gpu_memcpy"); if (size == 0) { _dbg_assert_msg_(false, "Zero-sized PerformMemoryCopy: %08x -> %08x, size %d (flag: %d)", src, dest, size, (int)flags); return false; @@ -2657,6 +2658,7 @@ bool GPUCommon::PerformMemoryCopy(u32 dest, u32 src, int size, GPUCopyFlag flags } bool GPUCommon::PerformMemorySet(u32 dest, u8 v, int size) { + PROFILE_THIS_SCOPE("gpu_memset"); if (size == 0) { _dbg_assert_msg_(false, "Zero-sized PerformMemorySet: %08x, value %02x, size %d", dest, v, size); return false; @@ -2698,6 +2700,7 @@ bool GPUCommon::PerformReadbackToMemory(u32 dest, int size) { } bool GPUCommon::PerformWriteColorFromMemory(u32 dest, int size) { + PROFILE_THIS_SCOPE("gpu_upload"); if (Memory::IsVRAMAddress(dest)) { recorder_.NotifyUpload(dest, size); return PerformMemoryCopy(dest, dest, size, GPUCopyFlag::FORCE_SRC_MATCH_MEM | GPUCopyFlag::DEBUG_NOTIFIED); diff --git a/Tools/profile_report.py b/Tools/profile_report.py new file mode 100644 index 0000000000..bf4ce4971e --- /dev/null +++ b/Tools/profile_report.py @@ -0,0 +1,205 @@ +#!/usr/bin/env python3 +"""Summarizes a frame profiler log, as written with --profile-log=FILE. + +The log has a JSON line per frame, with each thread's time and count per category, and for each slow +frame (--profile-hitch-ms) a line per scope of at least --profile-span-ms that ended in it, with the +scope's own time (minus the logged scopes inside it) and its label (which syscall, event, module...). + + python Tools/profile_report.py profile.jsonl # summary, causes and the worst frames + python Tools/profile_report.py profile.jsonl --frame 1234 # one frame's scopes +""" + +import argparse +import json +import sys +from collections import defaultdict + +# Waiting, not working. Left out when naming what made a frame slow, but shown in the details. +WAIT_CATEGORIES = ("sleep",) + + +def load(path): + frames = {} + spans = defaultdict(list) + with open(path, encoding="utf-8", errors="replace") as f: + for line in f: + line = line.strip() + if not line: + continue + try: + rec = json.loads(line) + except json.JSONDecodeError: + continue # A line cut short at the end of a run. + if "span" in rec: + spans[rec["span"]].append(rec) + elif "f" in rec: + frames[rec["f"]] = rec + return frames, spans + + +def percentile(values, p): + if not values: + return 0.0 + values = sorted(values) + return values[min(len(values) - 1, int(len(values) * p / 100))] + + +def span_name(s): + return s["c"] + (":" + s["n"] if s.get("n") else "") + + +def is_wait(s): + return s["c"] in WAIT_CATEGORIES + + +def emu_thread(frame): + """The thread running the game: the one with JIT (or interpreter) time.""" + for thread, cats in frame.get("th", {}).items(): + if "jit" in cats or "advance" in cats: + return thread + return None + + +VBLANK_MS = 1000.0 / 59.94 +# A frame this far behind the emulated time it covered is a stall: half a vblank. +STALL_MS = 8.0 +# Frame details show the scopes with this much work of their own. +DETAIL_MS = 1.0 +# The threads that a frame waits for, other than the emulator thread. Vulkan's is "VulkanRenderMan". +RENDER_THREAD_PREFIX = "VulkanRender" + + +def behind_ms(frame): + """How much longer the frame took than the emulated time it covered: the PSP takes a vblank + (16.7 ms) per vblank, so a game that doesn't flip for ten of them (loading, say) shows a 167 ms + frame on the PSP too. A frame without vblanks covered no emulated time (a menu, say).""" + thread = emu_thread(frame) + vblanks = frame["th"][thread].get("vblank", [0.0, 0])[1] if thread else 0 + return frame["ms"] - vblanks * VBLANK_MS + + +def culprits(frame_spans): + """The frame's working scopes, by their own time, longest first.""" + return sorted((s for s in frame_spans if not is_wait(s)), key=lambda s: -s["self"]) + + +def print_frame(frame, frame_spans, out): + out.write("Frame %d at %.2f s: %.1f ms (typically %.1f), %.1f ms behind emulated time\n" % (frame["f"], frame["t"], frame["ms"], frame.get("typ", 0.0), behind_ms(frame))) + for thread, cats in frame.get("th", {}).items(): + busy = sorted(cats.items(), key=lambda kv: -kv[1][0]) + parts = ["%s %.1f%s" % (c, v[0], " x%d" % v[1] if v[1] > 1 else "") for c, v in busy if v[0] >= 0.1] + if parts: + out.write(" %-16s %s\n" % (thread, ", ".join(parts))) + by_thread = defaultdict(list) + for s in frame_spans: + by_thread[s["th"]].append(s) + # Times from the frame's start. A scope that began in an earlier frame starts below zero. + start = frame["t"] - frame["ms"] / 1000.0 + for thread, ss in by_thread.items(): + ss = sorted(ss, key=lambda s: (s["t"], s["l"])) + # The scopes that did work themselves, and the ones around them. + keep = set(i for i, s in enumerate(ss) if s["self"] >= DETAIL_MS and not is_wait(s)) + for i in list(keep): + inner = ss[i] + for j, outer in enumerate(ss): + if outer["l"] < inner["l"] and outer["t"] <= inner["t"] and outer["t"] + outer["ms"] / 1000.0 >= inner["t"] + inner["ms"] / 1000.0 - 1e-6: + keep.add(j) + if not keep: + continue + out.write(" %s scopes with %.0f ms or more of their own work (start, then length and own time):\n" % (thread, DETAIL_MS)) + for i, s in enumerate(ss): + if i in keep: + out.write(" %+8.1f ms %s%s %.1f ms (own %.1f)\n" % ((s["t"] - start) * 1000.0, " " * s["l"], span_name(s), s["ms"], s["self"])) + + +def main(): + ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + ap.add_argument("log") + ap.add_argument("--hitch-ms", type=float, default=None, help="Count frames of at least this long as slow (default: the logged threshold)") + ap.add_argument("--since", type=float, default=0.0, help="Leave out frames before this many seconds") + ap.add_argument("--worst", type=int, default=5, help="Show the scopes of this many of the slowest frames") + ap.add_argument("--causes", type=int, default=25, help="Show this many causes") + ap.add_argument("--frame", type=int, action="append", help="Show this frame's scopes (repeatable)") + args = ap.parse_args() + + frames, spans = load(args.log) + out = sys.stdout + if args.frame: + for n in args.frame: + if n in frames: + print_frame(frames[n], spans.get(n, []), out) + else: + out.write("No frame %d\n" % n) + return + + chosen = [f for f in frames.values() if f["t"] >= args.since] + if not chosen: + out.write("No frames.\n") + return + ms = [f["ms"] for f in chosen] + if args.hitch_ms is not None: + slow = [f for f in chosen if f["ms"] >= args.hitch_ms] + rule = "of %.1f ms or more" % args.hitch_ms + else: + # As logged: slow in absolute terms, and at least 1.5x the frames around it ("typ"). + slow = [f for f in chosen if f.get("slow")] + rule = "logged as slow" + # A slow frame that covered as much emulated time is the game not flipping, as slow on a PSP + # (a loading screen, say). The rest are stalls: emulation fell behind real time. + paced = [f for f in slow if behind_ms(f) < STALL_MS] + slow = [f for f in slow if behind_ms(f) >= STALL_MS] + slow.sort(key=lambda f: -f["ms"]) + duration = chosen[-1]["t"] - chosen[0]["t"] + out.write("%d frames over %.1f s. Frame time median %.1f ms, 95%% %.1f, 99%% %.1f, max %.1f.\n" % ( + len(chosen), duration, percentile(ms, 50), percentile(ms, 95), percentile(ms, 99), max(ms))) + stalled = sum(behind_ms(f) for f in slow) + out.write("%d stalls (frames %s that fell %.0f ms or more behind emulated time), %.2f s behind in all.\n" % (len(slow), rule, STALL_MS, stalled / 1000.0)) + out.write("%d more slow frames took as long as the vblanks they covered (the game not flipping, as on a PSP).\n" % len(paced)) + + # What the stalls' time went to on the threads a frame waits for: each category's own time, from + # the exact per-frame totals. Worker threads run alongside, and show up here as wait_* when waited + # for. A stall's "cause" is its biggest category. + cat_ms = defaultdict(float) + cat_frames = defaultdict(int) + first_cause = defaultdict(int) + for f in slow: + here = defaultdict(float) + for thread, cats in f.get("th", {}).items(): + if thread != emu_thread(f) and not thread.startswith(RENDER_THREAD_PREFIX): + continue + for c, v in cats.items(): + if c not in WAIT_CATEGORIES: + here["%s %s" % (thread, c)] += v[0] + for k, v in here.items(): + cat_ms[k] += v + cat_frames[k] += 1 + if here: + first_cause[max(here.items(), key=lambda kv: kv[1])[0]] += 1 + if cat_ms: + out.write("\nTime in stalls by thread and category (own time):\n") + out.write(" %9s %6s %6s %s\n" % ("ms", "frames", "worst", "category")) + for name, total in sorted(cat_ms.items(), key=lambda kv: -kv[1])[:args.causes]: + out.write(" %9.1f %6d %6d %s\n" % (total, cat_frames[name], first_cause.get(name, 0), name)) + out.write(" (worst: how many stalls it was the biggest category of)\n") + + # Which syscall, event, module or pipeline: the labelled scopes, on any thread. + own = defaultdict(float) + count = defaultdict(int) + for f in slow: + for s in spans.get(f["f"], []): + if s.get("n") and not is_wait(s): + own[span_name(s)] += s["self"] + count[span_name(s)] += 1 + if own: + out.write("\nLabelled scopes in stalls (own time, scopes of at least the logged length, any thread):\n") + out.write(" %9s %6s %s\n" % ("ms", "times", "scope")) + for name, total in sorted(own.items(), key=lambda kv: -kv[1])[:args.causes]: + out.write(" %9.1f %6d %s\n" % (total, count[name], name)) + + for f in slow[:args.worst]: + out.write("\n") + print_frame(f, spans.get(f["f"], []), out) + + +if __name__ == "__main__": + main() diff --git a/UI/DevScreens.cpp b/UI/DevScreens.cpp index 90a0377514..c13f17400f 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -99,9 +99,7 @@ static const char *g_debugOverlayList[] = { "Debug stats", "Draw Frametimes Graph", "Frame timing", -#ifdef USE_PROFILER "Frame profile", -#endif "Control Debug", "Audio Debug", "GPU Profile", diff --git a/UI/EmuScreen.cpp b/UI/EmuScreen.cpp index 075d1bdfd1..dc3314a935 100644 --- a/UI/EmuScreen.cpp +++ b/UI/EmuScreen.cpp @@ -2049,11 +2049,9 @@ void EmuScreen::renderUI() { } } -#ifdef USE_PROFILER if ((DebugOverlay)g_Config.iDebugOverlay == DebugOverlay::FRAME_PROFILE && PSP_IsInited()) { DrawProfile(*ctx); } -#endif if (g_Config.bShowGPOLEDs) { // Draw a vertical strip of LEDs at the right side of the screen. diff --git a/UI/ImDebugger/ImProfiler.cpp b/UI/ImDebugger/ImProfiler.cpp index e621ec51a1..77b3f2486c 100644 --- a/UI/ImDebugger/ImProfiler.cpp +++ b/UI/ImDebugger/ImProfiler.cpp @@ -72,12 +72,21 @@ struct TimelineView { }; TimelineView g_view; + +// The first time a profiler window shows. After that, its Record checkbox decides. +void TurnOnOnce() { + static bool done = false; + if (!done) { + Profiler_SetEnabled(true); + done = true; + } +} std::vector g_events; void DrawTimeline() { TimelineView &view = g_view; const uint64_t now = Profiler_Now(); - if (view.follow && !Profiler_IsPaused()) { + if (view.follow && Profiler_IsEnabled()) { view.end = now; } const int64_t span = std::max(Profiler_SecondsToTicks(view.spanSeconds), 1); @@ -118,7 +127,7 @@ void DrawTimeline() { const double newSpan = std::clamp(view.spanSeconds * pow(0.85, io.MouseWheel), 0.0001, 2.0); const int64_t newSpanTicks = Profiler_SecondsToTicks(newSpan); view.spanSeconds = newSpan; - if (!view.follow || Profiler_IsPaused()) { + if (!view.follow || !Profiler_IsEnabled()) { view.end = anchor + (uint64_t)((1.0 - frac) * newSpanTicks); } } @@ -142,9 +151,11 @@ void DrawTimeline() { struct Open { uint64_t start; + const char *label; bool valid; }; const char *hoveredName = nullptr; + const char *hoveredLabel = nullptr; double hoveredMs = 0.0; float y = origin.y + rowH; for (int t = 0; t < numThreads; t++) { @@ -157,7 +168,7 @@ void DrawTimeline() { Open open[32]{}; int maxLevel = 0; - auto drawBar = [&](int level, int category, uint64_t from, uint64_t to) { + auto drawBar = [&](int level, int category, uint64_t from, uint64_t to, const char *label) { maxLevel = std::max(maxLevel, level); if (level >= view.laneDepth[t]) { return; @@ -175,15 +186,16 @@ void DrawTimeline() { } if (hovered && io.MousePos.x >= a.x && io.MousePos.x < b.x && io.MousePos.y >= a.y && io.MousePos.y < b.y) { hoveredName = name; + hoveredLabel = label; hoveredMs = Profiler_TicksToSeconds((int64_t)(to - from)) * 1000.0; } }; for (const ProfilerEvent &e : g_events) { if (e.type == ProfilerEventType::Begin) { - open[e.level] = Open{ e.ticks, true }; + open[e.level] = Open{ e.ticks, e.label, true }; } else { // Without its Begin, the scope started before the view. - drawBar(e.level, e.category, open[e.level].valid ? open[e.level].start : viewStart, e.ticks); + drawBar(e.level, e.category, open[e.level].valid ? open[e.level].start : viewStart, e.ticks, open[e.level].valid ? open[e.level].label : nullptr); open[e.level].valid = false; } } @@ -197,7 +209,7 @@ void DrawTimeline() { break; } } - drawBar(level, category, open[level].start, std::min(viewEnd, now)); + drawBar(level, category, open[level].start, std::min(viewEnd, now), open[level].label); } } if (maxLevel + 1 > view.laneDepth[t]) { @@ -218,7 +230,7 @@ void DrawTimeline() { dl->PopClipRect(); if (hoveredName) { - ImGui::SetTooltip("%s\n%0.3f ms", hoveredName, hoveredMs); + ImGui::SetTooltip("%s%s%s\n%0.3f ms", hoveredName, hoveredLabel ? ": " : "", hoveredLabel ? hoveredLabel : "", hoveredMs); } } @@ -283,6 +295,7 @@ void DrawFrameProfile(ImConfig &cfg) { return; } #ifdef USE_PROFILER + TurnOnOnce(); const int numCategories = Profiler_GetNumCategories(); const int numThreads = Profiler_GetNumThreads(); const int historyLength = Profiler_GetHistoryLength(); @@ -391,9 +404,10 @@ void DrawCpuProfiler(ImConfig &cfg) { return; } #ifdef USE_PROFILER - bool paused = Profiler_IsPaused(); - if (ImGui::Checkbox("Pause", &paused)) { - Profiler_SetPaused(paused); + TurnOnOnce(); + bool record = Profiler_IsEnabled(); + if (ImGui::Checkbox("Record", &record)) { + Profiler_SetEnabled(record); } ImGui::SameLine(); ImGui::Checkbox("Follow", &g_view.follow); diff --git a/UI/ProfilerDraw.cpp b/UI/ProfilerDraw.cpp index 52efda7379..85b9006e17 100644 --- a/UI/ProfilerDraw.cpp +++ b/UI/ProfilerDraw.cpp @@ -55,6 +55,7 @@ enum ProfileCatStatus { void DrawProfile(UIContext &ui) { #ifdef USE_PROFILER + Profiler_SetEnabled(true); PROFILE_THIS_SCOPE("timing"); int numCategories = Profiler_GetNumCategories(); int numThreads = Profiler_GetNumThreads(); diff --git a/android/build.gradle.kts b/android/build.gradle.kts index 2f2bce04d0..2d05543d8e 100644 --- a/android/build.gradle.kts +++ b/android/build.gradle.kts @@ -157,6 +157,13 @@ android { } else { println("WARNING: RELEASE_STORE_FILE is missing. Release builds will be unusable.") } + // Debug and optimized builds have the frame profiler compiled in (off until turned on). + externalNativeBuild { + cmake { + cFlags.add("-DNO_PROFILER") + cppFlags.add("-DNO_PROFILER") + } + } } } externalNativeBuild { diff --git a/unittest/UnitTest.cpp b/unittest/UnitTest.cpp index 5398fae595..b7005db92a 100644 --- a/unittest/UnitTest.cpp +++ b/unittest/UnitTest.cpp @@ -1917,15 +1917,22 @@ bool TestSymbolMap() { // than there are lanes) while frames are being totalled. Only does anything with USE_PROFILER. bool TestProfiler() { #ifdef USE_PROFILER + // Busy, not sleeping: sleeps have a scope of their own. + auto spin = [](int ms) { + const double end = time_now_d() + ms * 0.001; + while (time_now_d() < end) { + } + }; PROFILE_INIT(); + Profiler_SetEnabled(true); PROFILE_END_FRAME(); { PROFILE_THIS_SCOPE("test_outer"); - sleep_ms(20, "test"); + spin(20); { PROFILE_THIS_SCOPE("test_inner"); - sleep_ms(30, "test"); + spin(30); } } PROFILE_END_FRAME(); @@ -1952,7 +1959,7 @@ bool TestProfiler() { Profiler_GetHistory(outerCat, lane, outer.data(), len); Profiler_GetHistory(innerCat, lane, inner.data(), len); Profiler_GetHistoryCounts(innerCat, lane, counts.data(), len); - // Outer gets only its own time, not the inner scope's. Sleeps run long, never short. + // Outer gets only its own time, not the inner scope's. EXPECT_TRUE(outer[len - 1] >= 0.019f && outer[len - 1] < 0.035f); EXPECT_TRUE(inner[len - 1] >= 0.029f && inner[len - 1] < 0.045f); EXPECT_EQ_INT(counts[len - 1], 1); @@ -1960,9 +1967,9 @@ bool TestProfiler() { // A scope open across a frame end is split between the frames. { PROFILE_THIS_SCOPE("test_outer"); - sleep_ms(10, "test"); + spin(10); PROFILE_END_FRAME(); - sleep_ms(10, "test"); + spin(10); } PROFILE_END_FRAME(); Profiler_GetHistory(outerCat, lane, outer.data(), len); @@ -2003,6 +2010,7 @@ bool TestProfiler() { stop = true; reader.join(); EXPECT_TRUE(Profiler_GetNumThreads() <= 32); + Profiler_SetEnabled(false); #endif return true; } From a935279cc402a3bcabc91663b06e7bf565605397 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 10:34:29 +0100 Subject: [PATCH 3/9] adhoc_session.py: Attach to a running PPSSPP, also on Android, and branch in scripts attach drives one PPSSPP that's already running with --debugger, like the app. With --adb it's the app on an Android device: the port is forwarded and screenshots are taken with screencap, cut to the game's image (--rect) and scaled to 480x272, so references and positions mean the same as headless. screencap also doesn't pause emulation, unlike the debugger's screenshot, so it can watch a run that's being profiled. until takes --or REF@X,Y for screens that differ between runs (a menu that only shows with a save), and a script line "if REF --box X,Y : COMMAND ; COMMAND" runs the commands only when the screen shows the reference. Co-Authored-By: Claude Opus 5.5 --- Tools/adhoc_session.py | 94 +++++++++++++++++++++++++++++++++++++++--- 1 file changed, 89 insertions(+), 5 deletions(-) diff --git a/Tools/adhoc_session.py b/Tools/adhoc_session.py index c07101a3b7..443e0ea209 100644 --- a/Tools/adhoc_session.py +++ b/Tools/adhoc_session.py @@ -321,11 +321,34 @@ def cmd_stop(args): except FileNotFoundError: return for inst in session["instances"]: + if inst.get("pid") is None: + continue # Attached: not ours to stop. try: os.kill(inst["pid"], 15) except ProcessLookupError: pass os.remove(session_file(args)) + + +def cmd_attach(args): + # A session of one already running PPSSPP (the app, say) with the debugger on --port. With --adb, the + # app on an Android device, its debugger port forwarded to this machine, and screenshots taken with + # screencap from --rect, the game's image on the device's screen. + if os.path.exists(session_file(args)): + cmd_stop(args) + os.makedirs(args.dir, exist_ok=True) + inst = {"n": 1, "pid": None, "log": None, "port": args.port} + if args.adb is not None: + if not args.rect: + sys.exit("--adb needs --rect X,Y,W,H: where the game's image is on the device's screen") + inst["adb"] = args.adb + inst["rect"] = parse_ints(args.rect, 4) + subprocess.run(["adb"] + (["-s", args.adb] if args.adb else []) + ["forward", "tcp:%d" % args.port, "tcp:%d" % args.port], check=True, capture_output=True) + connect(inst).request("cpu.status") + session = {"game": None, "instances": [inst], "speed": 100, "attached": True} + with open(session_file(args), "w") as f: + json.dump(session, f, indent=1) + print("Attached to port %d%s, session in %s" % (args.port, " over adb" if args.adb is not None else "", args.dir)) print("Stopped") @@ -404,7 +427,23 @@ def cmd_wait(args): emulated_sleep(load_session(args), args.seconds) +def grab_adb_png(inst): + # The device's screen, cut down to the game's image and scaled to the PSP's 480x272, so references + # and pixel positions mean the same as with headless. Doesn't pause emulation, unlike the debugger's + # screenshot, so it can watch a run that's being profiled. + import io + from PIL import Image + cmd = ["adb"] + (["-s", inst["adb"]] if inst["adb"] else []) + ["exec-out", "screencap", "-p"] + screen = Image.open(io.BytesIO(subprocess.run(cmd, capture_output=True, check=True).stdout)) + x, y, w, h = inst["rect"] + out = io.BytesIO() + screen.convert("RGB").crop((x, y, x + w, y + h)).resize((480, 272), Image.BILINEAR).save(out, "PNG") + return out.getvalue() + + def grab_png(inst, attempts=3): + if inst.get("adb") is not None: + return grab_adb_png(inst) # An instance busy loading can be slow to answer; try again rather than end a long script. for attempt in range(attempts): try: @@ -515,11 +554,43 @@ def cmd_until(args): dbg.send("input.buttons.press", button=args.press, duration=6) dbg.close() last_press = now - waiting = [inst for inst in waiting if not screen_matches(args, Image.open(io.BytesIO(grab_png(inst))))] + waiting = [inst for inst in waiting if not matches_any(args, Image.open(io.BytesIO(grab_png(inst))))] if waiting: time.sleep(wall_seconds(session, args.poll)) +def matches_any(args, image): + # The reference, or any of the --or ones (REF@X,Y), for screens that differ between runs: a menu + # that only shows when there's a save, say. Follow with "if" to tell which it was. + if screen_matches(args, image): + return True + for alt in getattr(args, "alt", None) or []: + ref, _, box = alt.partition("@") + if screen_matches(argparse.Namespace(ref=ref, box=box or None, pixel=None, tolerance=args.tolerance, + slack=args.slack, base=getattr(args, "base", ".")), image): + return True + return False + + +def run_if(args, line): + # "if REF --box X,Y : COMMAND ; COMMAND ..." runs the commands when each selected instance shows the + # reference now (one screenshot each, no waiting). The condition takes until's matching options. + import io + from PIL import Image + cond, _, then = line[3:].partition(":") + if not then.strip(): + sys.exit("if needs ': COMMAND' after the condition: %r" % line) + sub = build_parser().parse_args(["--dir", args.dir, "until"] + cond.split()) + sub.base = os.path.dirname(os.path.abspath(args.script)) + session = load_session(sub) + if all(matches_any(sub, Image.open(io.BytesIO(grab_png(inst)))) for inst in selected(session, sub.i)): + for command in then.split(";"): + command = command.strip() + if command: + print("> " + command) + run_line(args, command) + + def cmd_crop(args): from PIL import Image x, y, w, h = parse_ints(args.box, 4) @@ -566,6 +637,15 @@ def cmd_watch(args): COMMANDS = {} +def run_line(args, line): + if line.startswith("if "): + run_if(args, line) + return + sub = build_parser().parse_args(["--dir", args.dir] + line.split()) + sub.base = os.path.dirname(os.path.abspath(args.script)) + COMMANDS[sub.command](sub) + + def cmd_run(args): with open(args.script) as f: for line in f: @@ -573,9 +653,7 @@ def cmd_run(args): if not line: continue print("> " + line) - sub = build_parser().parse_args(["--dir", args.dir] + line.split()) - sub.base = os.path.dirname(os.path.abspath(args.script)) - COMMANDS[sub.command](sub) + run_line(args, line) def build_parser(): @@ -633,6 +711,7 @@ def build_parser(): p = sub.add_parser("until", help="Wait until the screen shows something: a region like a reference image, or a pixel's color") p.add_argument("ref", nargs="?", help="Reference image (a crop of a screenshot, see crop); relative to the script in a script") p.add_argument("--box", help="X,Y where the reference image goes on the screen (default 0,0)") + p.add_argument("--or", dest="alt", action="append", help="REF@X,Y: or this reference there (repeatable); a script follows with 'if REF --box X,Y : COMMANDS' to tell which") p.add_argument("--pixel", help="X,Y of a pixel to check instead") p.add_argument("--color", help="With --pixel: RRGGBB") p.add_argument("--tolerance", type=float, default=12, help="Mean difference per channel allowed (0-255; default 12)") @@ -662,10 +741,15 @@ def build_parser(): p.add_argument("script") sub.add_parser("stop", help="Stop the instances") + + p = sub.add_parser("attach", help="Drive one PPSSPP that's already running with --debugger=PORT, like the app on a phone") + p.add_argument("--port", type=int, default=45678) + p.add_argument("--adb", nargs="?", const="", help="It runs on an Android device (this serial, or the only one): forward the port and screenshot with screencap") + p.add_argument("--rect", help="With --adb: X,Y,W,H of the game's image on the device's screen, in its pixels") return parser -COMMANDS.update(start=cmd_start, stop=cmd_stop, press=cmd_press, stick=cmd_stick, type=cmd_type, wait=cmd_wait, shot=cmd_shot, stats=cmd_stats, until=cmd_until, crop=cmd_crop, log=cmd_log, +COMMANDS.update(start=cmd_start, stop=cmd_stop, attach=cmd_attach, press=cmd_press, stick=cmd_stick, type=cmd_type, wait=cmd_wait, shot=cmd_shot, stats=cmd_stats, until=cmd_until, crop=cmd_crop, log=cmd_log, watch=cmd_watch, run=cmd_run) From 1b92700e5426bca8e867bda6658cd42705ab957d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 10:35:24 +0100 Subject: [PATCH 4/9] Docs: Finding stalls with the frame profiler, and driving the app or a phone Co-Authored-By: Claude Opus 5.5 --- AGENTS.md | 2 +- docs/adhoc-multiplayer-testing.md | 26 ++++++++++++++++++++++++++ docs/debugging.md | 26 ++++++++++++++++++++++++++ 3 files changed, 53 insertions(+), 1 deletion(-) diff --git a/AGENTS.md b/AGENTS.md index bf5fbe3b6a..3c14834a9f 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -14,7 +14,7 @@ for it: | [docs/building.md](docs/building.md) | Build commands for every target (VS/MSBuild, CMake, UWP, legacy Android NDK, libretro), unit tests, pspautotests | | [docs/android-device-testing.md](docs/android-device-testing.md) | Running a build on a real Android device or a Quest over adb: installing the build you think you are, forcing activity recreates, measuring retained activities, VR, running the C++ unit tests on a device (`Tools/android_unittest.py`), starting the app with options (`Tools/android_run.py`), and the storage tests that exercise content URIs in the app (`Tools/android_storage_test.py`) | | [docs/android-todo.md](docs/android-todo.md) | Known Android Java issues found in reviews and not fixed yet - check before reviewing or changing that code | -| [docs/debugging.md](docs/debugging.md) | Driving the WebSocket debugger and PPSSPPHeadless from a script, measuring a commercial game with headless, comparing binaries' speed (`Tools/headless_bench.py`), finding a game's hot JIT blocks (`--jit-profile`), breakpoint reliability per CPU backend, debugging a game that works on hardware, finding and hashing a game function (like its own `memcpy`) for `ReplaceTables` when hardware backends miss CPU writes to VRAM | +| [docs/debugging.md](docs/debugging.md) | Driving the WebSocket debugger and PPSSPPHeadless from a script, measuring a commercial game with headless, comparing binaries' speed (`Tools/headless_bench.py`), finding a game's hot JIT blocks (`--jit-profile`), finding what makes frames stall (`--profile-log`, `Tools/profile_report.py`), breakpoint reliability per CPU backend, debugging a game that works on hardware, finding and hashing a game function (like its own `memcpy`) for `ReplaceTables` when hardware backends miss CPU writes to VRAM | | [docs/DebuggerThreading.md](docs/DebuggerThreading.md) | `Core_RunOnCPUThread` / `g_frameMutex` / shutdown-lock rules - required reading before touching debugger code | | [docs/HLEModules.md](docs/HLEModules.md) | Adding an HLE module or function, and the seven build files a new source file goes in | | [docs/translations.md](docs/translations.md) | Translating UI strings with Tools/langtool | diff --git a/docs/adhoc-multiplayer-testing.md b/docs/adhoc-multiplayer-testing.md index 0117a5c084..c2662276c2 100644 --- a/docs/adhoc-multiplayer-testing.md +++ b/docs/adhoc-multiplayer-testing.md @@ -73,6 +73,32 @@ with `crop SHOT.png X,Y,W,H OUT.png` from a screenshot of the screen you want, a script: paths in a script are relative to it. A title screen left alone too long may start an attract demo, so don't wait for one without pressing. +A screen that only shows on some runs (a profile menu that needs a save, say) takes a branch: `until` +also stops on any `--or REF@X,Y`, and a line `if REF --box X,Y : COMMAND ; COMMAND` runs the commands +only when the screen shows the reference right then: + +``` +until select_profile.png --box 100,14 --or create_profile.png@100,14 --press start --every 4 +if select_profile.png --box 100,14 : press cross +if create_profile.png --box 100,14 : press cross ; wait 2 ; press cross +``` + +### Driving the app, or a phone + +`attach` makes a session of one PPSSPP that's already running with `--debugger=PORT` (default 45678), +and the other commands then drive it. With `--adb`, that's the app on an Android device: the port is +forwarded, and screenshots come from `screencap`, cut to the game's image (`--rect X,Y,W,H` in the +device's pixels; `0,249,1080,612` on a Galaxy S8 in portrait) and scaled to 480x272, so a script and its +references work the same on a phone as headless. `screencap` doesn't pause emulation, unlike the +debugger's screenshot, which matters when the run is being profiled +([debugging.md](debugging.md#finding-stalls-with-the-frame-profiler)). + +```bash +python Tools/android_run.py -- --debugger=45678 /sdcard/PSP/GAME.iso +python3 Tools/adhoc_session.py attach --adb --rect 0,249,1080,612 +python3 Tools/adhoc_session.py run game_ingame.txt +``` + To see what a game does, `log sceNet debug` turns a log channel up, and `watch SECONDS NAME` collects each instance's log messages meanwhile into `NAME_N.log` (the debugger only sends log messages to clients that are connected). That works without `--log`, which slows the instances down enough to diff --git a/docs/debugging.md b/docs/debugging.md index 359a3c8a1c..590cf93903 100644 --- a/docs/debugging.md +++ b/docs/debugging.md @@ -295,6 +295,32 @@ shows as emitter and IR pass functions; profile 20 emulated seconds or more to s To compare two builds by where the time goes, profile one game at a time: several at once wait on each other's GPU work, which moves the shares. +### Finding stalls with the frame profiler + +The frame profiler (`Common/Profiler/Profiler.h`) is compiled into everything but Android release +builds, iOS, UWP and libretro, and off until something turns it on. `--profile-log=FILE` (app and +headless) does, and writes a JSON line per frame with each thread's time per scope category, plus, for +each slow frame, every scope of at least `--profile-span-ms` (default 1) that ended in it, with its +label: which syscall, CoreTiming event, module file or pipeline. A frame is slow when it takes at least +`--profile-hitch-ms` (default 25) and 1.5 times the median of the frames before it; each one also gets a +`Profiler: Frame` line in the log naming its longest scopes. + +```bash +python Tools/profile_report.py profile.jsonl # summary, causes, the worst frames' scopes +python Tools/profile_report.py profile.jsonl --frame 1234 # one frame +``` + +The report only counts a slow frame as a stall if it fell behind the emulated time it covered (each +vblank in it is 16.7 ms on a PSP): a game that doesn't flip for ten vblanks while loading shows a 167 ms +frame on hardware too. It sums the stalls' time by thread and category from the exact per-frame totals, +for the emulator thread and the render thread (a worker's time matters where something waits for it, +which shows as `wait_*`), and lists the labelled scopes. + +To find the stalls a player sees, measure a cold first run: `--shader-cache=false`, and 1x rendering +resolution so the GPU matters less. Getting into the game from boot takes a script (see "Driving the +app, or a phone" in [adhoc-multiplayer-testing.md](adhoc-multiplayer-testing.md)): pressing buttons at +random gets stuck in profile and save menus. + ## Debugging and breakpoint considerations It might be worth trying the interpreter - all types of breakpoints are the most reliable with this CPU backend. From c4f3d7db37186d911b41e2c56e6a4f44c54e5a81 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 11:04:06 +0100 Subject: [PATCH 5/9] Profiler: Check that it's on before the scope's category The category's static has a thread-safe init guard, which every scope checked before the profiler's on switch. Now the lookup is in a lambda that only runs while the profiler is on, so a scope costs a load and a branch while it's off. A non-literal name no longer compiles there (the lambda can't capture it); that takes PROFILE_THIS_SCOPE_DYNAMIC. Measured on a Galaxy S8 with ppsspp_headless, 20 emulated seconds of GTA: LCS driving from a savestate, 12 runs each: compiled in and off, it runs 0.39% more instructions than a build with NO_PROFILER (the runs spread 0.35-0.47%), and no measurable CPU time difference. Co-Authored-By: Claude Opus 5.5 --- Common/Profiler/Profiler.h | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/Common/Profiler/Profiler.h b/Common/Profiler/Profiler.h index 4fe35f51ed..9742a60da1 100644 --- a/Common/Profiler/Profiler.h +++ b/Common/Profiler/Profiler.h @@ -35,9 +35,11 @@ int Profiler_GetCategory(const char *name); void Profiler_Enter(int category); void Profiler_Leave(int category); +// The macros below check that the profiler is on before anything else, so that's all a scope costs +// while it's off. category is -1 then. class ProfileThis { public: - explicit ProfileThis(int category) : category_(Profiler_IsEnabled() ? category : -1) { + explicit ProfileThis(int category) : category_(category) { if (category_ >= 0) { Profiler_Enter(category_); } @@ -56,12 +58,15 @@ private: // Named by line, so a scope can hold more than one. #define PROFILE_CONCAT_INNER(a, b) a##b #define PROFILE_CONCAT(a, b) PROFILE_CONCAT_INNER(a, b) -// cat must be the same string every time this line runs (normally a literal): it's looked up once. +// cat must be a literal (or another constant): it's looked up once, the first time the line runs with the +// profiler on. Checking that first skips the static's thread-safe init guard while off. #define PROFILE_THIS_SCOPE(cat) \ - static const int PROFILE_CONCAT(_profile_cat, __LINE__) = Profiler_GetCategory(cat); \ - ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(PROFILE_CONCAT(_profile_cat, __LINE__)); + ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_IsEnabled() ? [] { \ + static const int category = Profiler_GetCategory(cat); \ + return category; \ + }() : -1); // For a name that varies between calls. -#define PROFILE_THIS_SCOPE_DYNAMIC(cat) ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_GetCategory(cat)); +#define PROFILE_THIS_SCOPE_DYNAMIC(cat) ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_IsEnabled() ? Profiler_GetCategory(cat) : -1); #define PROFILE_END_FRAME() internal_profiler_end_frame(); // Names this thread's innermost open scope (which syscall, which file) in the log and the timeline. From dacea56aaa9cbf3c2513b8b2af3997c5ad3edb62 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Tue, 10 Nov 2026 22:19:47 +0100 Subject: [PATCH 6/9] SoftGPU: Remove the frame profiler scopes A sampling profiler shows its costs better. Some were per pixel, and two in one scope kept USE_PROFILER builds from compiling. Co-Authored-By: Claude Opus 5.5 --- GPU/Software/BinManager.cpp | 6 ------ GPU/Software/Clipper.cpp | 1 - GPU/Software/Rasterizer.cpp | 10 ---------- GPU/Software/RasterizerRectangle.cpp | 1 - GPU/Software/SoftGpu.cpp | 4 ---- GPU/Software/TransformUnit.cpp | 4 ---- 6 files changed, 26 deletions(-) diff --git a/GPU/Software/BinManager.cpp b/GPU/Software/BinManager.cpp index 5fe2b88991..803c348814 100644 --- a/GPU/Software/BinManager.cpp +++ b/GPU/Software/BinManager.cpp @@ -21,7 +21,6 @@ #include #include "Common/BitSet.h" -#include "Common/Profiler/Profiler.h" #include "Common/Thread/ParallelLoop.h" #include "Common/Thread/ThreadManager.h" #include "Common/Data/Text/StringWriter.h" @@ -244,7 +243,6 @@ void BinManager::DeswizzleMirrorTextures(RasterizerState &state) { } void BinManager::UpdateState() { - PROFILE_THIS_SCOPE("bin_state"); if (HasDirty(SoftDirty::PIXEL_ALL | SoftDirty::SAMPLER_ALL | SoftDirty::RAST_ALL)) { PushState(); ClearDirty(SoftDirty::PIXEL_ALL | SoftDirty::SAMPLER_ALL | SoftDirty::RAST_ALL); @@ -487,7 +485,6 @@ inline void BinDirtyRange::Expand(uint32_t newBase, uint32_t bpp, uint32_t strid } void BinManager::UpdateClut(const void *src) { - PROFILE_THIS_SCOPE("bin_clut"); if (cluts_.Full()) Flush("cluts"); BinClut &clut = cluts_.PeekPush(); @@ -617,8 +614,6 @@ void BinManager::AddPoint(const VertexData &v0) { } void BinManager::Drain() { - PROFILE_THIS_SCOPE("bin_drain"); - // Also when switching to one thread: what's left goes to the tiles, which hold the earlier items. if (maxTasks_ > 1 || activeCount_ != 0) { DistributeItems(); @@ -634,7 +629,6 @@ void BinManager::Drain() { OptimizePendingStates(pendingStateIndex_, stateIndex_); pendingStateIndex_ = stateIndex_; - PROFILE_THIS_SCOPE("bin_drain_single"); // Anything (transfers, the CPU) may have written memory since the last drain. selfTexValid_ = false; while (!queue_.Empty()) { diff --git a/GPU/Software/Clipper.cpp b/GPU/Software/Clipper.cpp index 360b44fce8..cb6077e9ba 100644 --- a/GPU/Software/Clipper.cpp +++ b/GPU/Software/Clipper.cpp @@ -23,7 +23,6 @@ #include "GPU/Software/RasterizerRectangle.h" #include "GPU/Software/TransformUnit.h" -#include "Common/Profiler/Profiler.h" namespace Clipper { diff --git a/GPU/Software/Rasterizer.cpp b/GPU/Software/Rasterizer.cpp index de1b7269fe..45650bc58d 100644 --- a/GPU/Software/Rasterizer.cpp +++ b/GPU/Software/Rasterizer.cpp @@ -23,7 +23,6 @@ #include "Common/Common.h" #include "Common/CPUDetect.h" #include "Common/Data/Convert/ColorConv.h" -#include "Common/Profiler/Profiler.h" #include "Common/StringUtils.h" #include "Core/Config.h" #include "Core/Debugger/MemBlockInfo.h" @@ -726,7 +725,6 @@ static inline void ApplyTexturing(const RasterizerState &state, int *colors, int perPixel = false; } - PROFILE_THIS_SCOPE("sampler"); if (state.linearQuad) { // All four at once, when they're all bilinear. int levels[4], fracs[4], active = 0; @@ -1928,7 +1926,6 @@ void DrawTriangleSlice( fog[i] = std::clamp((int)fogWalk.At(i), 0, 255); } - PROFILE_THIS_SCOPE("draw_tri_px"); #if !defined(SOFTGPU_MEMORY_TAGGING_DETAILED) if (state.drawSpan) { alignas(16) int lanes[16]; @@ -1976,8 +1973,6 @@ void DrawTriangleSlice( // Draws triangle, vertices specified in counter-clockwise direction void DrawTriangle(const VertexData &v0, const VertexData &v1, const VertexData &v2, const BinCoords &range, const RasterizerState &state) { - PROFILE_THIS_SCOPE("draw_tri"); - auto drawSlice = cpu_info.bSSE4_1 ? (state.pixelID.clearMode ? &DrawTriangleSlice : &DrawTriangleSlice) : (state.pixelID.clearMode ? &DrawTriangleSlice : &DrawTriangleSlice); @@ -2187,7 +2182,6 @@ void DrawRectangle(const VertexData &v0, const VertexData &v1, const BinCoords & (Vec4S32::Load(prim_color + c * 4) + Vec4S32::Splat(sec_color[c])).Store(prim_color + c * 4); } - PROFILE_THIS_SCOPE("draw_rect_px"); #if !defined(SOFTGPU_MEMORY_TAGGING_DETAILED) if (state.drawSpan) { Vec4 fogs = fog, zs = z; @@ -2277,7 +2271,6 @@ void DrawPoint(const VertexData &v0, const BinCoords &range, const RasterizerSta int texLevelFrac; bool bilinear; CalculateSamplingParams(0.0f, 0.0f, 1.0f / v0.clipw, state, texLevel, texLevelFrac, bilinear); - PROFILE_THIS_SCOPE("sampler"); prim_color = ApplyTexturingSingle(s, t, ToVec4IntArg(prim_color), texLevel, texLevelFrac, bilinear, state); } @@ -2291,7 +2284,6 @@ void DrawPoint(const VertexData &v0, const BinCoords &range, const RasterizerSta fog = ClampFogDepth(v0.fogdepth); } - PROFILE_THIS_SCOPE("draw_px"); state.drawPixel(p.x, p.y, z, fog, ToVec4IntArg(prim_color), pixelID); #if defined(SOFTGPU_MEMORY_TAGGING_DETAILED) || defined(SOFTGPU_MEMORY_TAGGING_BASIC) @@ -2823,14 +2815,12 @@ void DrawLine(const VertexData &v0, const VertexData &v1, const BinCoords &range texBilinear = true; } - PROFILE_THIS_SCOPE("sampler"); prim_color = ApplyTexturingSingle(s, t, ToVec4IntArg(prim_color), texLevel, texLevelFrac, texBilinear, state); } if (!pixelID.clearMode) prim_color += Vec4(sec_color, 0); - PROFILE_THIS_SCOPE("draw_px"); state.drawPixel(p.x, p.y, z, fog, ToVec4IntArg(prim_color), pixelID); #if defined(SOFTGPU_MEMORY_TAGGING_DETAILED) || defined(SOFTGPU_MEMORY_TAGGING_BASIC) diff --git a/GPU/Software/RasterizerRectangle.cpp b/GPU/Software/RasterizerRectangle.cpp index 15ea18dcf3..8ad3d11696 100644 --- a/GPU/Software/RasterizerRectangle.cpp +++ b/GPU/Software/RasterizerRectangle.cpp @@ -5,7 +5,6 @@ #include "Common/Common.h" #include "Common/Data/Convert/ColorConv.h" -#include "Common/Profiler/Profiler.h" #include "Core/Debugger/MemBlockInfo.h" #include "Core/System.h" diff --git a/GPU/Software/SoftGpu.cpp b/GPU/Software/SoftGpu.cpp index f7c35b86a1..2f3fa1d239 100644 --- a/GPU/Software/SoftGpu.cpp +++ b/GPU/Software/SoftGpu.cpp @@ -35,7 +35,6 @@ #include "Core/MemMap.h" #include "Core/MIPS/MIPS.h" #include "Core/Util/PPGeDraw.h" -#include "Common/Profiler/Profiler.h" #include "Common/GPU/thin3d.h" #include "GPU/GPUCommon.h" @@ -823,7 +822,6 @@ void SoftGPU::CheckConfigChanged(const DisplayLayoutConfig &config) { } void SoftGPU::FastRunLoop(DisplayList &list) { - PROFILE_THIS_SCOPE("soft_runloop"); const auto *cmdInfo = softgpuCmdInfo; int dc = downcount; SoftDirty dirty = dirtyFlags_; @@ -1428,8 +1426,6 @@ void SoftGPU::Execute_ImmVertexAlphaPrim(u32 op, u32 diff) { } void SoftGPU::Execute_Call(u32 op, u32 diff) { - PROFILE_THIS_SCOPE("gpu_call"); - const u32 target = gstate_c.getRelativeAddress(op & 0x00FFFFFC); if (!Memory::IsValidAddress(target)) { ERROR_LOG(Log::G3D, "CALL to illegal address %08x - ignoring! data=%06x", target, op & 0x00FFFFFF); diff --git a/GPU/Software/TransformUnit.cpp b/GPU/Software/TransformUnit.cpp index 3dde1aee1e..f4cb5c4d32 100644 --- a/GPU/Software/TransformUnit.cpp +++ b/GPU/Software/TransformUnit.cpp @@ -29,7 +29,6 @@ #include "Common/Data/Convert/ColorConv.h" #include "Common/Math/math_util.h" #include "Common/MemoryUtil.h" -#include "Common/Profiler/Profiler.h" #include "Common/Thread/ThreadManager.h" #include "Common/TimeUtil.h" #include "GPU/GPUState.h" @@ -681,8 +680,6 @@ static bool PreparePositions4(const Vec4F32 pos[4], const TransformState &state, // Writes straight into the destination: building the vertex in a temporary and copying it reloads its // fields with wider loads than they were stored with, which stalls. void TransformUnit::ReadVertex(const VertexReader &vreader, const TransformState &state, VertexCarry &carry, ClipVertexData &vertex, const PreparedPosition *prepared) { - PROFILE_THIS_SCOPE("read_vert"); - // (x, y, z, 1), the left operands of the transform's rows. Vec4F32 pos = vreader.ReadPosOne(); @@ -821,7 +818,6 @@ void TransformUnit::ReadVertex(const VertexReader &vreader, const TransformState Lighting::GenerateLightST(vertex.v, pos, worldnormal, normalRsqrt, state.lightingState.viewDir); } - PROFILE_THIS_SCOPE("light"); if (state.enableLighting) Lighting::Process(vertex.v, pos, worldnormal, normalRsqrt, state.lightingState); } else { From af59826fe00c56643d99254fb97f27b03b75f44c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 11:33:51 +0100 Subject: [PATCH 7/9] Profiler: Compile it into every build, with coarser scopes in rendering It's now in release builds too, Android's included, and on iOS, UWP and libretro, so no build runs a rarely tested configuration. NO_PROFILER still leaves it out. The scopes per GE CALL (gpu_call), per primitive (execprim) and per draw inside a flush (renderman_q, applydrawstate, soft) are gone: their time shows in gpuloop and flush (now named the same on every backend, D3D11 included). A software-transformed flush is labelled "soft" instead. PROFILE_THIS_SCOPE_DYNAMIC is gone too; its one user, the curve code, labels a "curve" scope with the kind. The profiler windows and Tools/profile_report.py show how many scopes run per frame, and headless ends a profiler frame per emulated one, so --profile-log works there as it says. What a scope costs while off, timed in the unit test on a Galaxy S8 (20 million of them against the same loop without): nothing measurable. It's two instructions there (a load of the switch and a branch), up to four elsewhere. GTA: Liberty City Stories runs about 1,640 scopes a frame, so a few thousand instructions in about 31 million. (The 0.39% more instructions measured over whole runs is about 64 per scope, so most of it was something else, likely threads that spin while waiting.) Co-Authored-By: Claude Opus 5.5 --- Common/Profiler/Profiler.h | 16 ++++++---------- GPU/Common/SplineCommon.cpp | 3 ++- GPU/D3D11/DrawEngineD3D11.cpp | 3 ++- GPU/GLES/DrawEngineGLES.cpp | 2 +- GPU/GLES/StateMappingGLES.cpp | 3 --- GPU/GPUCommon.cpp | 2 -- GPU/GPUCommonHW.cpp | 2 -- GPU/Metal/DrawEngineMetal.mm | 4 ++-- GPU/Vulkan/DrawEngineVulkan.cpp | 6 ++---- Tools/profile_report.py | 2 ++ UI/ImDebugger/ImProfiler.cpp | 24 ++++++++++++++++++++++++ android/build.gradle.kts | 7 ------- docs/debugging.md | 5 ++--- headless/Headless.cpp | 2 ++ unittest/UnitTest.cpp | 23 ++++++++++++++++++++++- 15 files changed, 67 insertions(+), 37 deletions(-) diff --git a/Common/Profiler/Profiler.h b/Common/Profiler/Profiler.h index 9742a60da1..a874eab86c 100644 --- a/Common/Profiler/Profiler.h +++ b/Common/Profiler/Profiler.h @@ -4,12 +4,10 @@ #include #include -#include "ppsspp_config.h" - -// Compiled in everywhere but iOS, UWP, libretro and builds that define NO_PROFILER (Android release -// builds), and off until something turns it on (Profiler_SetEnabled), which costs a scope one load and -// a branch. Check USE_PROFILER only after including this file. -#if !defined(USE_PROFILER) && !defined(NO_PROFILER) && !PPSSPP_PLATFORM(IOS) && !PPSSPP_PLATFORM(UWP) && !defined(__LIBRETRO__) +// Compiled into every build (unless it defines NO_PROFILER), and off until something turns it on +// (Profiler_SetEnabled), which costs a scope one load and a branch. Check USE_PROFILER only after +// including this file. +#if !defined(USE_PROFILER) && !defined(NO_PROFILER) #define USE_PROFILER #endif @@ -59,14 +57,13 @@ private: #define PROFILE_CONCAT_INNER(a, b) a##b #define PROFILE_CONCAT(a, b) PROFILE_CONCAT_INNER(a, b) // cat must be a literal (or another constant): it's looked up once, the first time the line runs with the -// profiler on. Checking that first skips the static's thread-safe init guard while off. +// profiler on. Checking that first skips the static's thread-safe init guard while off. For what varies +// between calls (which file, which syscall), add a PROFILE_LABEL. #define PROFILE_THIS_SCOPE(cat) \ ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_IsEnabled() ? [] { \ static const int category = Profiler_GetCategory(cat); \ return category; \ }() : -1); -// For a name that varies between calls. -#define PROFILE_THIS_SCOPE_DYNAMIC(cat) ProfileThis PROFILE_CONCAT(_profile_scoped, __LINE__)(Profiler_IsEnabled() ? Profiler_GetCategory(cat) : -1); #define PROFILE_END_FRAME() internal_profiler_end_frame(); // Names this thread's innermost open scope (which syscall, which file) in the log and the timeline. @@ -130,7 +127,6 @@ void Profiler_GetFrameEnds(std::vector *ends); #define PROFILE_INIT() #define PROFILE_THIS_SCOPE(cat) -#define PROFILE_THIS_SCOPE_DYNAMIC(cat) #define PROFILE_END_FRAME() #define PROFILE_LABEL(text) #define PROFILE_LABEL_COPY(text) diff --git a/GPU/Common/SplineCommon.cpp b/GPU/Common/SplineCommon.cpp index 30dcb463d1..20500b65ac 100644 --- a/GPU/Common/SplineCommon.cpp +++ b/GPU/Common/SplineCommon.cpp @@ -1371,7 +1371,8 @@ template void DrawEngineCommon::SubmitCurve(const void *control_p template void DrawEngineCommon::SubmitCurve(const void *control_points, const void *indices, Surface &surface, u32 vertType, int *bytesRead, const char *scope) { - PROFILE_THIS_SCOPE_DYNAMIC(scope); + PROFILE_THIS_SCOPE("curve"); + PROFILE_LABEL(scope); // Real hardware seems to draw nothing when given < 4 either U or V. // This would result in num_patches_u / num_patches_v being 0. diff --git a/GPU/D3D11/DrawEngineD3D11.cpp b/GPU/D3D11/DrawEngineD3D11.cpp index 436bb8a51a..2ab4dfae3b 100644 --- a/GPU/D3D11/DrawEngineD3D11.cpp +++ b/GPU/D3D11/DrawEngineD3D11.cpp @@ -298,6 +298,7 @@ void DrawEngineD3D11::Flush() { if (!numDrawVerts_) { return; } + PROFILE_THIS_SCOPE("flush"); // This is not done on every drawcall, we collect vertex data // until critical state changes. That's when we draw (flush). @@ -443,7 +444,7 @@ void DrawEngineD3D11::Flush() { DepthRasterSubmitHW(prim, vertexCount, cpuClip); } } else { - PROFILE_THIS_SCOPE("soft"); + PROFILE_LABEL("soft"); DecodeVerts(dec_, decoded_); int vertexCount = DecodeInds(); diff --git a/GPU/GLES/DrawEngineGLES.cpp b/GPU/GLES/DrawEngineGLES.cpp index 9bb9a5135e..8d80d520dd 100644 --- a/GPU/GLES/DrawEngineGLES.cpp +++ b/GPU/GLES/DrawEngineGLES.cpp @@ -385,7 +385,7 @@ void DrawEngineGLES::Flush() { DepthRasterSubmitHW(prim, vertexCount, cpuClip); } } else { - PROFILE_THIS_SCOPE("soft"); + PROFILE_LABEL("soft"); DecodeVerts(dec_, decoded_); int vertexCount = DecodeInds(); diff --git a/GPU/GLES/StateMappingGLES.cpp b/GPU/GLES/StateMappingGLES.cpp index 9dd4e9f238..db4d16905a 100644 --- a/GPU/GLES/StateMappingGLES.cpp +++ b/GPU/GLES/StateMappingGLES.cpp @@ -123,9 +123,6 @@ void DrawEngineGLES::ApplyDrawState(int prim) { return; } - // Start profiling here to skip SetTexture which is already accounted for - PROFILE_THIS_SCOPE("applydrawstate"); - uint64_t dirtyRequiresRecheck_ = 0; bool useBufferedRendering = framebufferManager_->UseBufferedRendering(); diff --git a/GPU/GPUCommon.cpp b/GPU/GPUCommon.cpp index b336cb9ed4..f2efc6d8c2 100644 --- a/GPU/GPUCommon.cpp +++ b/GPU/GPUCommon.cpp @@ -1186,8 +1186,6 @@ void GPUCommon::Execute_BJump(u32 op, u32 diff) { } void GPUCommon::Execute_Call(u32 op, u32 diff) { - PROFILE_THIS_SCOPE("gpu_call"); - const u32 target = gstate_c.getRelativeAddress(op & 0x00FFFFFC); if (!Memory::IsValidAddress(target)) { ERROR_LOG(Log::G3D, "CALL to illegal address %08x - ignoring! data=%06x", target, op & 0x00FFFFFF); diff --git a/GPU/GPUCommonHW.cpp b/GPU/GPUCommonHW.cpp index 8eb786503a..cfec528f8a 100644 --- a/GPU/GPUCommonHW.cpp +++ b/GPU/GPUCommonHW.cpp @@ -877,8 +877,6 @@ void GPUCommonHW::Execute_Prim(u32 op, u32 diff) { // This drives all drawing. All other state we just buffer up, then we apply it only // when it's time to draw. As most PSP games set state redundantly ALL THE TIME, this is a huge optimization. - PROFILE_THIS_SCOPE("execprim"); - FlushImm(); UpdateMatrixProducts(); diff --git a/GPU/Metal/DrawEngineMetal.mm b/GPU/Metal/DrawEngineMetal.mm index 53b35cde54..f5c0bb20b4 100644 --- a/GPU/Metal/DrawEngineMetal.mm +++ b/GPU/Metal/DrawEngineMetal.mm @@ -659,7 +659,7 @@ void DrawEngineMetal::Flush() { if (!numDrawVerts_) { return; } - PROFILE_THIS_SCOPE("Flush"); + PROFILE_THIS_SCOPE("flush"); GEPrimitiveType prim = prevPrim_; @@ -776,7 +776,7 @@ void DrawEngineMetal::Flush() { } } else { gpuStats.perFrame.numSoftTransformedDraws++; - PROFILE_THIS_SCOPE("soft"); + PROFILE_LABEL("soft"); DecodeVerts(dec_, decoded_); int vertexCount = DecodeInds(); diff --git a/GPU/Vulkan/DrawEngineVulkan.cpp b/GPU/Vulkan/DrawEngineVulkan.cpp index 3cdc37b190..dad9bb3053 100644 --- a/GPU/Vulkan/DrawEngineVulkan.cpp +++ b/GPU/Vulkan/DrawEngineVulkan.cpp @@ -234,7 +234,7 @@ void DrawEngineVulkan::Flush() { renderManager->AssertInRenderPass(); - PROFILE_THIS_SCOPE("Flush"); + PROFILE_THIS_SCOPE("flush"); GEPrimitiveType prim = prevPrim_; // Always use software for flat shading to fix the provoking index @@ -421,7 +421,7 @@ void DrawEngineVulkan::Flush() { } else { gpuStats.perFrame.numSoftTransformedDraws++; - PROFILE_THIS_SCOPE("soft"); + PROFILE_LABEL("soft"); int prevDecodedVerts = numDecodedVerts_; DecodeVerts(dec_, decoded_); @@ -562,8 +562,6 @@ void DrawEngineVulkan::Flush() { baseUBOOffset, lightUBOOffset, }; - PROFILE_THIS_SCOPE("renderman_q"); - VkBuffer vbuf, ibuf; u32 vbOffset = (uint32_t)pushVertex_->Push(result.drawBuffer, result.drawVertexCount * sizeof(TransformedVertex), 4, &vbuf); u32 ibOffset = (uint32_t)pushIndex_->Push(inds, sizeof(short) * result.drawIndexCount, 4, &ibuf); diff --git a/Tools/profile_report.py b/Tools/profile_report.py index bf4ce4971e..11cd887263 100644 --- a/Tools/profile_report.py +++ b/Tools/profile_report.py @@ -152,6 +152,8 @@ def main(): duration = chosen[-1]["t"] - chosen[0]["t"] out.write("%d frames over %.1f s. Frame time median %.1f ms, 95%% %.1f, 99%% %.1f, max %.1f.\n" % ( len(chosen), duration, percentile(ms, 50), percentile(ms, 95), percentile(ms, 99), max(ms))) + scopes = [sum(v[1] for cats in f.get("th", {}).values() for v in cats.values()) for f in chosen] + out.write("Scopes per frame (all threads): median %d, max %d.\n" % (percentile(scopes, 50), max(scopes))) stalled = sum(behind_ms(f) for f in slow) out.write("%d stalls (frames %s that fell %.0f ms or more behind emulated time), %.2f s behind in all.\n" % (len(slow), rule, STALL_MS, stalled / 1000.0)) out.write("%d more slow frames took as long as the vblanks they covered (the game not flipping, as on a PSP).\n" % len(paced)) diff --git a/UI/ImDebugger/ImProfiler.cpp b/UI/ImDebugger/ImProfiler.cpp index 77b3f2486c..d9c1a1db56 100644 --- a/UI/ImDebugger/ImProfiler.cpp +++ b/UI/ImDebugger/ImProfiler.cpp @@ -81,6 +81,28 @@ void TurnOnOnce() { done = true; } } + +// How many scopes all threads left in the last frame, and on average over the history: what the profiler +// costs to run, and while off, about how many loads and branches it adds. +void DrawScopeCount() { + const int historyLength = Profiler_GetHistoryLength(); + std::vector counts(historyLength); + std::vector total(historyLength); + for (int t = 0; t < Profiler_GetNumThreads(); t++) { + for (int c = 0; c < Profiler_GetNumCategories(); c++) { + Profiler_GetHistoryCounts(c, t, counts.data(), historyLength); + for (int i = 0; i < historyLength; i++) { + total[i] += counts[i]; + } + } + } + long long sum = 0; + for (int n : total) { + sum += n; + } + ImGui::Text("Scopes per frame: %d in the last one, %0.0f on average.", total[historyLength - 1], (double)sum / historyLength); +} + std::vector g_events; void DrawTimeline() { @@ -327,6 +349,7 @@ void DrawFrameProfile(ImConfig &cfg) { } ImGui::Text("Time per frame in each category, per thread. Scale: %0.1f ms.", maxTotal * 1000.0f); + DrawScopeCount(); const float legendW = 140.0f; const ImVec2 avail = ImGui::GetContentRegionAvail(); const float graphW = std::max(avail.x - legendW, 100.0f); @@ -413,6 +436,7 @@ void DrawCpuProfiler(ImConfig &cfg) { ImGui::Checkbox("Follow", &g_view.follow); ImGui::SameLine(); ImGui::Text("%0.1f ms shown. Wheel zooms, dragging pans.", g_view.spanSeconds * 1000.0); + DrawScopeCount(); if (ImGui::BeginTabBar("profiler")) { if (ImGui::BeginTabItem("Timeline")) { DrawTimeline(); diff --git a/android/build.gradle.kts b/android/build.gradle.kts index 2d05543d8e..2f2bce04d0 100644 --- a/android/build.gradle.kts +++ b/android/build.gradle.kts @@ -157,13 +157,6 @@ android { } else { println("WARNING: RELEASE_STORE_FILE is missing. Release builds will be unusable.") } - // Debug and optimized builds have the frame profiler compiled in (off until turned on). - externalNativeBuild { - cmake { - cFlags.add("-DNO_PROFILER") - cppFlags.add("-DNO_PROFILER") - } - } } } externalNativeBuild { diff --git a/docs/debugging.md b/docs/debugging.md index 590cf93903..4ac6a267a1 100644 --- a/docs/debugging.md +++ b/docs/debugging.md @@ -297,9 +297,8 @@ other's GPU work, which moves the shares. ### Finding stalls with the frame profiler -The frame profiler (`Common/Profiler/Profiler.h`) is compiled into everything but Android release -builds, iOS, UWP and libretro, and off until something turns it on. `--profile-log=FILE` (app and -headless) does, and writes a JSON line per frame with each thread's time per scope category, plus, for +The frame profiler (`Common/Profiler/Profiler.h`) is compiled into every build, and off until +something turns it on. `--profile-log=FILE` (app and headless) does, and writes a JSON line per frame with each thread's time per scope category, plus, for each slow frame, every scope of at least `--profile-span-ms` (default 1) that ended in it, with its label: which syscall, CoreTiming event, module file or pipeline. A frame is slow when it takes at least `--profile-hitch-ms` (default 25) and 1.5 times the median of the frames before it; each one also gets a diff --git a/headless/Headless.cpp b/headless/Headless.cpp index ce95253eb0..b83b01c9e2 100644 --- a/headless/Headless.cpp +++ b/headless/Headless.cpp @@ -879,6 +879,8 @@ static bool RunAutoTest(GraphicsContext *graphicsContext, CoreParameter &corePar if (gpu) { gpu->BeginHostFrame(g_Config.GetDisplayLayoutConfig(DeviceOrientation::Landscape)); } + // As the app does in NativeFrame: the profiler's frames are host frames (--profile-log). + PROFILE_END_FRAME(); } // Without a debugger nothing can resume a stop, so it ends the run. if (coreState == CORE_STEPPING_CPU && !opt.debugger) { diff --git a/unittest/UnitTest.cpp b/unittest/UnitTest.cpp index b7005db92a..516fb102ad 100644 --- a/unittest/UnitTest.cpp +++ b/unittest/UnitTest.cpp @@ -1924,6 +1924,26 @@ bool TestProfiler() { } }; PROFILE_INIT(); + + // What a scope costs while the profiler is off, against the same loop without one. For information: + // it's compiled into every build. + { + Profiler_SetEnabled(false); + volatile int sink = 0; + const int n = 20000000; + const double t0 = time_now_d(); + for (int i = 0; i < n; i++) { + sink = sink + 1; + } + const double t1 = time_now_d(); + for (int i = 0; i < n; i++) { + PROFILE_THIS_SCOPE("test_off"); + sink = sink + 1; + } + const double t2 = time_now_d(); + printf("Profiler off: %0.2f ns per scope (the loop alone takes %0.2f ns)\n", ((t2 - t1) - (t1 - t0)) / n * 1e9, (t1 - t0) / n * 1e9); + } + Profiler_SetEnabled(true); PROFILE_END_FRAME(); @@ -1998,7 +2018,8 @@ bool TestProfiler() { PROFILE_THIS_SCOPE("test_a"); PROFILE_THIS_SCOPE("test_b"); for (int k = 0; k < 40; k++) { - PROFILE_THIS_SCOPE_DYNAMIC((k & 1) ? "test_c" : "test_d"); + PROFILE_THIS_SCOPE("test_c"); + PROFILE_LABEL((k & 1) ? "odd" : "even"); } } }); From 6f5eab87d9fe7acc22095af0a98f158d4dc882e3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 12:59:36 +0100 Subject: [PATCH 8/9] Profiler: Write the log without fputs, which libretro's stdio doesn't have Co-Authored-By: Claude Opus 5.5 --- Common/Profiler/Profiler.cpp | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/Common/Profiler/Profiler.cpp b/Common/Profiler/Profiler.cpp index 60f4899e90..90afcc7159 100644 --- a/Common/Profiler/Profiler.cpp +++ b/Common/Profiler/Profiler.cpp @@ -238,6 +238,11 @@ int HistoryIndex(int i, int count) { return (g_historyPos - count + i + HISTORY_SIZE) & (HISTORY_SIZE - 1); } +// libretro's stdio replacements have no fputs. +void WriteString(const char *s, FILE *f) { + fwrite(s, 1, strlen(s), f); +} + // Writes s as a JSON string. void WriteJsonString(FILE *f, const char *s) { fputc('"', f); @@ -310,12 +315,12 @@ void LogFrame(const FrameTotals &frame, int numLanes, uint64_t frameStart, uint6 continue; } if (firstCat) { - fputs(firstLane ? "" : ",", f); + WriteString(firstLane ? "" : ",", f); WriteJsonString(f, names[l]); - fputs(":{", f); + WriteString(":{", f); firstLane = false; } - fputs(firstCat ? "" : ",", f); + WriteString(firstCat ? "" : ",", f); WriteJsonString(f, g_categories[c]); fprintf(f, ":[%0.3f,%d]", frame.seconds[l][c] * 1000.0f, frame.counts[l][c]); firstCat = false; @@ -324,15 +329,15 @@ void LogFrame(const FrameTotals &frame, int numLanes, uint64_t frameStart, uint6 fputc('}', f); } } - fputs("}}\n", f); + WriteString("}}\n", f); if (hitch) { for (const Span &s : g_frameSpans) { fprintf(f, "{\"span\":%llu,\"th\":", (unsigned long long)g_frameNumber); WriteJsonString(f, names[s.lane]); - fputs(",\"c\":", f); + WriteString(",\"c\":", f); WriteJsonString(f, g_categories[s.category]); if (s.label) { - fputs(",\"n\":", f); + WriteString(",\"n\":", f); WriteJsonString(f, s.label); } fprintf(f, ",\"l\":%d,\"t\":%0.4f,\"ms\":%0.3f,\"self\":%0.3f}\n", s.level, TicksToMs(s.begin - g_startTicks) * 0.001, TicksToMs(s.end - s.begin), TicksToMs(s.self)); From 56e3017966b23e5d52288207bba7f0ed0bdcbaac Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Wed, 11 Nov 2026 13:07:27 +0100 Subject: [PATCH 9/9] libretro: Build the profiler, which every build has now Co-Authored-By: Claude Opus 5.5 --- libretro/Makefile.common | 1 + 1 file changed, 1 insertion(+) diff --git a/libretro/Makefile.common b/libretro/Makefile.common index cf87163f28..80a3c41f95 100644 --- a/libretro/Makefile.common +++ b/libretro/Makefile.common @@ -537,6 +537,7 @@ SOURCES_CXX += \ $(COMMONDIR)/Log/LogManager.cpp \ $(COMMONDIR)/OSVersion.cpp \ $(COMMONDIR)/MemoryUtil.cpp \ + $(COMMONDIR)/Profiler/Profiler.cpp \ $(COMMONDIR)/RiscVCPUDetect.cpp \ $(COMMONDIR)/LogReporting.cpp \ $(COMMONDIR)/SysError.cpp \