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/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 033db37843..b73fa8a6d5 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" @@ -29,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); @@ -51,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"); @@ -967,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); @@ -983,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()) { @@ -1893,6 +1904,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 +1944,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 +1968,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 @@ -2021,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 0b41fa9c3a..90afcc7159 100644 --- a/Common/Profiler/Profiler.cpp +++ b/Common/Profiler/Profiler.cpp @@ -1,263 +1,642 @@ -// 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 +#include + +#include "Common/File/FileUtil.h" +#include "Common/File/Path.h" #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. +#define LABEL_COPIES 64 +#define RECENT_FRAMES 61 +#define MAX_FRAME_SPANS 4096 +#define NO_EVENT UINT64_MAX -#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; + // 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, 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]{}; }; -struct CategoryFrame { - CategoryFrame() { - memset(time_taken, 0, sizeof(time_taken)); - memset(count, 0, sizeof(count)); - } - float time_taken[MAX_CATEGORIES]; - int count[MAX_CATEGORIES]; +// 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 Profiler { - int historyPos; - int depth[MAX_THREADS]; - int parentCategory[MAX_THREADS][MAX_DEPTH]; - double eventStart[MAX_THREADS][MAX_CATEGORIES]; - double curFrameStart; +struct FrameTotals { + float seconds[MAX_LANES][MAX_CATEGORIES]; + int counts[MAX_LANES][MAX_CATEGORIES]; }; -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 +// 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; -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; +const char *g_categories[MAX_CATEGORIES]; +std::atomic g_numCategories; +std::mutex g_categoriesMutex; + +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; + +// 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; + ~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; +} + +// 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)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. +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 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); + LoseTrack(lane); + } + for (; i < written; i++) { + ProfilerEvent e; + if (!ReadEvent(lane, i, &e)) { + LoseTrack(lane); + 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); + const int level = e.level; + if (e.type == ProfilerEventType::Begin) { + 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 = 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; + 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); +} + +// 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); + 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) { + WriteString(firstLane ? "" : ",", f); + WriteJsonString(f, names[l]); + WriteString(":{", f); + firstLane = false; + } + 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; + } + if (!firstCat) { + fputc('}', 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]); + WriteString(",\"c\":", f); + WriteJsonString(f, g_categories[s.category]); + if (s.label) { + 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)); + } + 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; + } + 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); - } - 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; -} - -void internal_profiler_leave(int thread_id, int category) { - if (category == -1 || !history) { - return; - } - - int &depth = profiler.depth[thread_id]; - if (category < 0 || category >= MAX_CATEGORIES) { - ERROR_LOG(Log::System, "Bad category index %d", category); - depth--; - return; - } - - 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); + 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; } } + if (locked >= MAX_CATEGORIES) { + return -1; + } + g_categories[locked] = name; + g_numCategories.store(locked + 1, std::memory_order_release); + return locked; +} + +void Profiler_Enter(int category) { + if (category < 0 || !g_initialized) { + return; + } + Lane *lane = CurrentLane(); + if (!lane) { + return; + } + 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) { + 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 = std::min(--lane->depth, MAX_DEPTH - 1); + 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) { + 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(); + 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); + 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, 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) { - 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_SetEnabled(bool enabled) { + g_profilerEnabled.store(enabled, 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..a874eab86c 100644 --- a/Common/Profiler/Profiler.h +++ b/Common/Profiler/Profiler.h @@ -1,48 +1,134 @@ #pragma once +#include #include +#include -// #define USE_PROFILER +// 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 #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); +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); +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_(category) { + if (category_ >= 0) { + Profiler_Enter(category_); + } + } + ~ProfileThis() { + // Left even if the profiler was turned off meanwhile, so Begins and Ends pair up. + if (category_ >= 0) { + 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 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. 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); +#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); 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_; +// 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; + // 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. + 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_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/Common/SplineCommon.cpp b/GPU/Common/SplineCommon.cpp index 54ca27c4a2..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(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 93aa816aec..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); @@ -2611,6 +2609,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 +2656,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 +2698,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/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/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 { 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/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) diff --git a/Tools/profile_report.py b/Tools/profile_report.py new file mode 100644 index 0000000000..11cd887263 --- /dev/null +++ b/Tools/profile_report.py @@ -0,0 +1,207 @@ +#!/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))) + 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)) + + # 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/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/DevScreens.cpp b/UI/DevScreens.cpp index 5e11027ec5..87bce1da47 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -101,9 +101,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 35c0368260..8764b972ba 100644 --- a/UI/EmuScreen.cpp +++ b/UI/EmuScreen.cpp @@ -2044,11 +2044,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/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..d9c1a1db56 --- /dev/null +++ b/UI/ImDebugger/ImProfiler.cpp @@ -0,0 +1,455 @@ +// 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; + +// 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; + } +} + +// 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() { + TimelineView &view = g_view; + const uint64_t now = Profiler_Now(); + if (view.follow && Profiler_IsEnabled()) { + 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_IsEnabled()) { + 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; + 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++) { + 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, const char *label) { + 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; + 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, 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, open[e.level].valid ? open[e.level].label : nullptr); + 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), open[level].label); + } + } + 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%s%s\n%0.3f ms", hoveredName, hoveredLabel ? ": " : "", hoveredLabel ? hoveredLabel : "", 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 + TurnOnOnce(); + 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); + DrawScopeCount(); + 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 + TurnOnOnce(); + bool record = Profiler_IsEnabled(); + if (ImGui::Checkbox("Record", &record)) { + Profiler_SetEnabled(record); + } + 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); + DrawScopeCount(); + 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/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/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/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..4ac6a267a1 100644 --- a/docs/debugging.md +++ b/docs/debugging.md @@ -295,6 +295,31 @@ 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 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 +`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. 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/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 \ diff --git a/unittest/UnitTest.cpp b/unittest/UnitTest.cpp index fc73d518df..516fb102ad 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,129 @@ 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 + // 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(); + + // 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(); + + { + PROFILE_THIS_SCOPE("test_outer"); + spin(20); + { + PROFILE_THIS_SCOPE("test_inner"); + spin(30); + } + } + 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. + 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"); + spin(10); + PROFILE_END_FRAME(); + spin(10); + } + 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("test_c"); + PROFILE_LABEL((k & 1) ? "odd" : "even"); + } + } + }); + } + for (auto &t : threads) { + t.join(); + } + } + stop = true; + reader.join(); + EXPECT_TRUE(Profiler_GetNumThreads() <= 32); + Profiler_SetEnabled(false); +#endif + return true; +} + bool TestSymbolMapFiles() { const u32 kModStart = 0x08804000; const u32 kModSize = 0x00010000; @@ -4789,6 +4914,7 @@ TestItem availableTests[] = { TEST_ITEM(BlockAllocator), TEST_ITEM(SymbolMap), TEST_ITEM(SymbolMapFiles), + TEST_ITEM(Profiler), TEST_ITEM(Hashmaps), TEST_ITEM(Breakpoints), TEST_ITEM(TempBreakpoints),