Merge pull request #23041 from hrydgard/profiler-timeline

Profiler: Replace with a per-thread timeline profiler, compiled into every build

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 |

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) {

Common/GPU/Vulkan/VulkanRenderManager.cpp

@@ -5,6 +5,7 @@
 #include <sstream>
 
 #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<std::mutex> 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<std::mutex> lock(syncMutex_);
 			// Wait for the flush to be hit, since we're syncing.
 			while (!frameData.syncDone) {

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 <mutex>
-#include <vector>
+#include <algorithm>
+#include <atomic>
 #include <cstring>
+#include <mutex>
 
 #include "ppsspp_config.h"
 
-#include "Common/Render/DrawBuffer.h"
-
-#include "Common/TimeUtil.h"
 #include "Common/Profiler/Profiler.h"
+
+#ifdef USE_PROFILER
+
+#include <cstdio>
+#include <vector>
+
+#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<uint64_t> written{};
+	std::atomic<bool> 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<int> 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<int> 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<Span> 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<std::mutex> 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<std::mutex> 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<std::mutex> 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<const Span *> 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<bool> 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<std::mutex> 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<std::mutex> 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<uint64_t>(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<std::mutex> 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<ProfilerEvent> *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<uint64_t> *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

Common/Profiler/Profiler.h

@@ -1,48 +1,134 @@
 #pragma once
 
+#include <atomic>
 #include <cstdint>
+#include <vector>
 
-// #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<bool> 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<ProfilerEvent> *events);
+// When each of the history's frames ended, oldest first.
+void Profiler_GetFrameEnds(std::vector<uint64_t> *ends);
 
 #else
 
 #define PROFILE_INIT()
 #define PROFILE_THIS_SCOPE(cat)
 #define PROFILE_END_FRAME()
+#define PROFILE_LABEL(text)
+#define PROFILE_LABEL_COPY(text)
 
 #endif

Common/TimeUtil.cpp

@@ -5,6 +5,7 @@
 #include <cstdint>
 
 #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

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);

Core/CmdLine.h

@@ -219,6 +219,10 @@ struct CommandLineOptions {
 	std::optional<int> adhocDelayMs;
 	std::optional<int> adhocJitterMs;
 	std::optional<int> adhocLossPercent;
+	// Frame profiler logging (builds with USE_PROFILER). See Profiler_SetLogging.
+	std::optional<std::string> profileLog;
+	std::optional<double> profileHitchMs;
+	std::optional<double> profileSpanMs;
 
 	std::optional<std::string> screenshotFilename;
 	std::optional<std::string> screenshotFilenameSave;

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,

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);

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)

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.

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) {

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();

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();

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.

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();

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();

GPU/Common/FramebufferManagerCommon.cpp

@@ -20,6 +20,7 @@
 #include <cmath>
 
 #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) {

GPU/Common/SplineCommon.cpp

@@ -1371,7 +1371,8 @@ template void DrawEngineCommon::SubmitCurve<SplineSurface>(const void *control_p
 
 template<class Surface>
 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.

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();
 

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();
 

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();
 

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);

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();
 

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();

GPU/Software/BinManager.cpp

@@ -21,7 +21,6 @@
 #include <thread>
 
 #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()) {

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 {
 

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<true, true> : &DrawTriangleSlice<false, true>) :
 		(state.pixelID.clearMode ? &DrawTriangleSlice<true, false> : &DrawTriangleSlice<false, false>);
@@ -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<int> 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<int>(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)

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"

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);

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 {

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);

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)
 
 

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()

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

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",

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.

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", &paramSFOOpen, 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);

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;

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 <algorithm>
+#include <cmath>
+#include <cstring>
+#include <vector>
+
+#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<int> 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<int> counts(historyLength);
+	std::vector<int> 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<ProfilerEvent> 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<int64_t>(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>((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<uint64_t> 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<float> history(historyLength);
+	std::vector<int> 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<std::vector<std::vector<float>>> history(numThreads);
+	std::vector<std::vector<float>> totals(numThreads);
+	std::vector<int> shownThreads;
+	std::vector<bool> 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();
+}

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);

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();

UI/UI.vcxproj

@@ -57,6 +57,7 @@
     <ClCompile Include="ImDebugger\ImDisasmView.cpp" />
     <ClCompile Include="ImDebugger\ImGe.cpp" />
     <ClCompile Include="ImDebugger\ImJitViewer.cpp" />
+    <ClCompile Include="ImDebugger\ImProfiler.cpp" />
     <ClCompile Include="ImDebugger\ImMemView.cpp" />
     <ClCompile Include="ImDebugger\ImStructViewer.cpp" />
     <ClCompile Include="JitCompareScreen.cpp" />
@@ -135,6 +136,7 @@
     <ClInclude Include="ImDebugger\ImDisasmView.h" />
     <ClInclude Include="ImDebugger\ImGe.h" />
     <ClInclude Include="ImDebugger\ImJitViewer.h" />
+    <ClInclude Include="ImDebugger\ImProfiler.h" />
     <ClInclude Include="ImDebugger\ImMemView.h" />
     <ClInclude Include="ImDebugger\ImStructViewer.h" />
     <ClInclude Include="JitCompareScreen.h" />

UI/UI.vcxproj.filters

@@ -181,6 +181,9 @@
     <ClCompile Include="ImDebugger\ImJitViewer.cpp">
       <Filter>ImDebugger</Filter>
     </ClCompile>
+    <ClCompile Include="ImDebugger\ImProfiler.cpp">
+      <Filter>ImDebugger</Filter>
+    </ClCompile>
     <ClCompile Include="UploadScreen.cpp">
       <Filter>Screens</Filter>
     </ClCompile>
@@ -360,6 +363,9 @@
     <ClInclude Include="ImDebugger\ImJitViewer.h">
       <Filter>ImDebugger</Filter>
     </ClInclude>
+    <ClInclude Include="ImDebugger\ImProfiler.h">
+      <Filter>ImDebugger</Filter>
+    </ClInclude>
     <ClInclude Include="UploadScreen.h">
       <Filter>Screens</Filter>
     </ClInclude>

UWP/UI_UWP/UI_UWP.vcxproj

@@ -115,6 +115,7 @@
     <ClInclude Include="..\..\UI\ImDebugger\ImDisasmView.h" />
     <ClInclude Include="..\..\UI\ImDebugger\ImGe.h" />
     <ClInclude Include="..\..\UI\ImDebugger\ImJitViewer.h" />
+    <ClInclude Include="..\..\UI\ImDebugger\ImProfiler.h" />
     <ClInclude Include="..\..\UI\ImDebugger\ImMemView.h" />
     <ClInclude Include="..\..\UI\ImDebugger\ImStructViewer.h" />
     <ClInclude Include="..\..\UI\InstallPkgScreen.h" />
@@ -184,6 +185,7 @@
     <ClCompile Include="..\..\UI\ImDebugger\ImDisasmView.cpp" />
     <ClCompile Include="..\..\UI\ImDebugger\ImGe.cpp" />
     <ClCompile Include="..\..\UI\ImDebugger\ImJitViewer.cpp" />
+    <ClCompile Include="..\..\UI\ImDebugger\ImProfiler.cpp" />
     <ClCompile Include="..\..\UI\ImDebugger\ImMemView.cpp" />
     <ClCompile Include="..\..\UI\ImDebugger\ImStructViewer.cpp" />
     <ClCompile Include="..\..\UI\InstallPkgScreen.cpp" />

UWP/UI_UWP/UI_UWP.vcxproj.filters

@@ -35,6 +35,9 @@
     <ClCompile Include="..\..\UI\ImDebugger\ImJitViewer.cpp">
       <Filter>ImDebugger</Filter>
     </ClCompile>
+    <ClCompile Include="..\..\UI\ImDebugger\ImProfiler.cpp">
+      <Filter>ImDebugger</Filter>
+    </ClCompile>
     <ClCompile Include="..\..\UI\ChatScreen.cpp">
       <Filter>Screens</Filter>
     </ClCompile>
@@ -228,6 +231,9 @@
     <ClInclude Include="..\..\UI\ImDebugger\ImJitViewer.h">
       <Filter>ImDebugger</Filter>
     </ClInclude>
+    <ClInclude Include="..\..\UI\ImDebugger\ImProfiler.h">
+      <Filter>ImDebugger</Filter>
+    </ClInclude>
     <ClInclude Include="..\..\UI\ChatScreen.h">
       <Filter>Screens</Filter>
     </ClInclude>

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 \

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

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.

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) {

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 \

unittest/UnitTest.cpp

@@ -47,6 +47,7 @@
 #include <vector>
 #include <string>
 #include <sstream>
+#include <thread>
 
 #include <map>
 #include <unordered_map>
@@ -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<float> outer(len), inner(len);
+	std::vector<int> 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<bool> stop{};
+	std::thread reader([&] {
+		std::vector<ProfilerEvent> 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<std::thread> 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),