Vulkan: Keep track of some timestamps in a frame

Common/Data/Collections/FastVec.h

@@ -155,3 +155,16 @@ private:
 	bool capacityLocked_ = false;
 #endif
 };
+
+// Simple cyclical vector.
+// Initially, doesn't do any sanity checking.
+template <class T, size_t size>
+class HistoryBuffer {
+public:
+	// Out of bounds (past size() - 1) is undefined behavior.
+	T &operator[] (const size_t index) { return data_[index % size]; }
+	const T &operator[] (const size_t index) const { return data_[index % size]; }
+
+private:
+	T data_[size]{};
+};

Common/Data/Collections/FixedSizeQueue.h

@@ -222,4 +222,3 @@ private:
 	volatile int curReadBlock;
 	volatile int curWriteBlock;
 };
-

Common/GPU/MiscTypes.h

@@ -2,6 +2,8 @@
 
 #include "Common/Common.h"
 
+// Flags and structs shared between backends that haven't found a good home.
+
 enum class InvalidationFlags {
 	CACHED_RENDER_STATE = 1,
 };
@@ -14,3 +16,12 @@ enum class InvalidationCallbackFlags {
 ENUM_CLASS_BITOPS(InvalidationCallbackFlags);
 
 typedef std::function<void(InvalidationCallbackFlags)> InvalidationCallback;
+
+// These are separate from FrameData because we store some history of these.
+// Also, this might be joined with more non-GPU timing information later.
+struct FrameTimeData {
+	double frameBegin;
+	double afterFenceWait;
+	double firstSubmit;
+	double queuePresent;
+};

Common/GPU/Vulkan/VulkanFrameData.h

@@ -95,6 +95,10 @@ struct FrameData {
 	// Swapchain.
 	uint32_t curSwapchainImage = -1;
 
+	// Frames need unique IDs to wait for present on, let's keep them here.
+	// Also used for indexing into the frame timing history buffer.
+	uint64_t frameId;
+
 	// Profiling.
 	QueueProfileContext profile{};
 

Common/GPU/Vulkan/VulkanRenderManager.cpp

@@ -532,6 +532,7 @@ void VulkanRenderManager::ThreadFunc() {
 }
 
 void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfiler) {
+	double frameBeginTime = time_now_d()
 	VLOG("BeginFrame");
 	VkDevice device = vulkan_->GetDevice();
 
@@ -563,6 +564,13 @@ void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfile
 	frameData.profile.enabled = enableProfiling;
 	frameData.profile.timestampsEnabled = enableProfiling && validBits > 0;
 
+	uint64_t frameId = ++frameIdGen_;
+	frameData.frameId = frameId;
+
+	frameTimeData_[frameId] = {};
+	frameTimeData_[frameId].frameBegin = frameBeginTime;
+	frameTimeData_[frameId].afterFenceWait = time_now_d();
+
 	uint64_t queryResults[MAX_TIMESTAMP_QUERIES];
 
 	if (enableProfiling) {
@@ -1302,6 +1310,10 @@ void VulkanRenderManager::Run(VKRRenderThreadTask &task) {
 	FrameData &frameData = frameData_[task.frame];
 
 	_dbg_assert_(!frameData.hasPresentCommands);
+
+	if (!frameTimeData_[frameData.frameId].firstSubmit) {
+		frameTimeData_[frameData.frameId].firstSubmit = time_now_d();
+	}
 	frameData.SubmitPending(vulkan_, FrameSubmitType::Pending, frameDataShared_);
 
 	if (!frameData.hasMainCommands) {
@@ -1338,6 +1350,7 @@ void VulkanRenderManager::Run(VKRRenderThreadTask &task) {
 
 		if (!frameData.skipSwap) {
 			VkResult res = frameData.QueuePresent(vulkan_, frameDataShared_);
+			frameTimeData_[frameData.frameId].queuePresent = time_now_d();
 			if (res == VK_ERROR_OUT_OF_DATE_KHR) {
 				// We clearly didn't get this in vkAcquireNextImageKHR because of the skipSwap check above.
 				// Do the increment.

Common/GPU/Vulkan/VulkanRenderManager.h

@@ -17,6 +17,7 @@
 #include "Common/System/Display.h"
 #include "Common/GPU/Vulkan/VulkanContext.h"
 #include "Common/Data/Convert/SmallDataConvert.h"
+#include "Common/Data/Collections/FastVec.h"
 #include "Common/Math/math_util.h"
 #include "Common/GPU/DataFormat.h"
 #include "Common/GPU/MiscTypes.h"
@@ -456,6 +457,17 @@ public:
 	void ResetStats();
 	void DrainCompileQueue();
 
+	// framesBack is the number of frames into the past to look.
+	FrameTimeData GetFrameTimeData(int framesBack) const {
+		FrameTimeData data;
+		if (framesBack >= frameIdGen_) {
+			data = {};
+			return data;
+		}
+		data = frameTimeData_[frameIdGen_ - framesBack];
+		return data;
+	}
+
 private:
 	void EndCurRenderStep();
 
@@ -532,4 +544,7 @@ private:
 	SimpleStat renderCPUTimeMs_;
 
 	std::function<void(InvalidationCallbackFlags)> invalidationCallback_;
+
+	uint64_t frameIdGen_ = 31;
+	HistoryBuffer<FrameTimeData, 32> frameTimeData_;
 };

Common/GPU/Vulkan/thin3d_vulkan.cpp

@@ -487,6 +487,10 @@ public:
 		return frameCount_;
 	}
 
+	FrameTimeData GetFrameTimeData(int framesBack) const override {
+		return renderManager_.GetFrameTimeData(framesBack);
+	}
+
 	void FlushState() override {}
 
 	void ResetStats() override {

Common/GPU/thin3d.h

@@ -844,6 +844,10 @@ public:
 	// Total amount of frames rendered. Unaffected by game pause, so more robust than gpuStats.numFlips
 	virtual int GetFrameCount() = 0;
 
+	virtual FrameTimeData GetFrameTimeData(int framesBack) const {
+		return FrameTimeData{};
+	}
+
 protected:
 	ShaderModule *vsPresets_[VS_MAX_PRESET];
 	ShaderModule *fsPresets_[FS_MAX_PRESET];

Core/Config.h

@@ -461,8 +461,10 @@ public:
 	bool bDisplayStatusBar;
 	bool bShowBottomTabTitles;
 	bool bShowDeveloperMenu;
+
 	// Double edged sword: much easier debugging, but not accurate.
 	bool bSkipDeadbeefFilling;
+
 	bool bFuncHashMap;
 	std::string sSkipFuncHashMap;
 	bool bDebugMemInfoDetailed;
@@ -470,6 +472,7 @@ public:
 	// Volatile development settings
 	// Overlays
 	DebugOverlay iDebugOverlay;
+
 	bool bGpuLogProfiler; // Controls the Vulkan logging profiler (profiles textures uploads etc).
 
 	// Retro Achievement settings

Core/ConfigValues.h

@@ -180,6 +180,7 @@ enum class DebugOverlay : int {
 	OFF,
 	DEBUG_STATS,
 	FRAME_GRAPH,
+	FRAME_TIMING,
 #ifdef USE_PROFILER
 	FRAME_PROFILE,
 #endif

UI/DebugOverlay.cpp

@@ -69,8 +69,8 @@ static void DrawControlDebug(UIContext *ctx, const ControlMapper &mapper, const
 
 static void DrawFrameTimes(UIContext *ctx, const Bounds &bounds) {
 	FontID ubuntu24("UBUNTU24");
-	int valid, pos;
 	double *sleepHistory;
+	int valid, pos;
 	double *history = __DisplayGetFrameTimes(&valid, &pos, &sleepHistory);
 	int scale = 7000;
 	int width = 600;
@@ -99,6 +99,40 @@ static void DrawFrameTimes(UIContext *ctx, const Bounds &bounds) {
 	ctx->RebindTexture();
 }
 
+static void DrawFrameTiming(UIContext *ctx, const Bounds &bounds) {
+	FontID ubuntu24("UBUNTU24");
+
+	char statBuf[1024]{};
+
+	FrameTimeData data = ctx->GetDrawContext()->GetFrameTimeData(4);
+
+	if (data.frameBegin == 0.0) {
+		snprintf(statBuf, sizeof(statBuf), "(Frame timing collection not supported on this backend)");
+	} else {
+		double fenceLatency_s = data.afterFenceWait - data.frameBegin;
+		double submitLatency_s = data.firstSubmit - data.frameBegin;
+		double queuePresentLatency_s = data.queuePresent - data.frameBegin;
+
+		snprintf(statBuf, sizeof(statBuf),
+			"Time from start of frame to event:\n"
+			"* Past the fence: %0.1f ms\n"
+			"* First submit: %0.1f ms\n"
+			"* Queue-present: %0.1f ms\n",
+			fenceLatency_s * 1000.0,
+			submitLatency_s * 1000.0,
+			queuePresentLatency_s * 1000.0
+		);
+	}
+
+	ctx->Flush();
+	ctx->BindFontTexture();
+	ctx->Draw()->SetFontScale(0.5f, 0.5f);
+	ctx->Draw()->DrawTextRect(ubuntu24, statBuf, bounds.x + 11, bounds.y + 51, bounds.w - 20, bounds.h - 30, 0xc0000000, FLAG_DYNAMIC_ASCII);
+	ctx->Draw()->DrawTextRect(ubuntu24, statBuf, bounds.x + 10, bounds.y + 50, bounds.w - 20, bounds.h - 30, 0xFFFFFFFF, FLAG_DYNAMIC_ASCII);
+	ctx->Draw()->SetFontScale(1.0f, 1.0f);
+	ctx->Flush();
+	ctx->RebindTexture();
+}
 
 void DrawDebugOverlay(UIContext *ctx, const Bounds &bounds, const ControlMapper &controlMapper, DebugOverlay overlay) {
 	switch (overlay) {
@@ -108,6 +142,9 @@ void DrawDebugOverlay(UIContext *ctx, const Bounds &bounds, const ControlMapper
 	case DebugOverlay::FRAME_GRAPH:
 		DrawFrameTimes(ctx, ctx->GetLayoutBounds());
 		break;
+	case DebugOverlay::FRAME_TIMING:
+		DrawFrameTiming(ctx, ctx->GetLayoutBounds());
+		break;
 	case DebugOverlay::AUDIO:
 		DrawAudioDebugStats(ctx, ctx->GetLayoutBounds());
 		break;

UI/DevScreens.cpp

@@ -92,6 +92,7 @@ static const char *g_debugOverlayList[] = {
 	"Off",
 	"Debug stats",
 	"Draw Frametimes Graph",
+	"Frame timing",
 #ifdef USE_PROFILER
 	"Frame profile",
 #endif

assets/lang/en_US.ini

@@ -310,6 +310,7 @@ Enter address = Enter address
 FPU = FPU
 Framedump tests = Framedump tests
 Frame Profiler = Frame profiler
+Frame timing = Frame timing
 GPU Driver Test = GPU driver test
 GPU Profile = GPU profile
 GPU log profiler = GPU log profiler