Implement frame time measurement on Android using VK_GOOGLE_display_timing

Common/GPU/MiscTypes.h

@@ -20,13 +20,14 @@ 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 {
+	uint64_t frameId;
 	double frameBegin;
 	double afterFenceWait;
 	double firstSubmit;
 	double queuePresent;
+
 	double actualPresent;
 	double desiredPresentTime;
-	double actualPresentTime;
 	double earliestPresentTime;
 	double presentMargin;
 };

Common/GPU/Vulkan/VulkanFrameData.cpp

@@ -113,9 +113,9 @@ VkResult FrameData::QueuePresent(VulkanContext *vulkan, FrameDataShared &shared)
 	// Can't move these into the if.
 	VkPresentIdKHR presentID{ VK_STRUCTURE_TYPE_PRESENT_ID_KHR };
 	VkPresentTimesInfoGOOGLE presentGOOGLE{ VK_STRUCTURE_TYPE_PRESENT_TIMES_INFO_GOOGLE };
-	VkPresentTimeGOOGLE presentTimeGOOGLE{ (uint32_t)frameID, 0 };  // it's ok to truncate this. it'll wrap around and work (if we ever reach 4 billion frames..)
+	VkPresentTimeGOOGLE presentTimeGOOGLE{ (uint32_t)frameId, 0 };  // it's ok to truncate this. it'll wrap around and work (if we ever reach 4 billion frames..)
 	if (vulkan->Extensions().KHR_present_id && vulkan->GetDeviceFeatures().enabled.presentId.presentId) {
-		presentID.pPresentIds = &frameID;
+		presentID.pPresentIds = &frameId;
 		presentID.swapchainCount = 1;
 		present.pNext = &presentID;
 	} else if (vulkan->Extensions().GOOGLE_display_timing) {

Common/GPU/Vulkan/VulkanFrameData.h

@@ -72,7 +72,6 @@ struct FrameData {
 	std::mutex fenceMutex;
 	std::condition_variable fenceCondVar;
 	bool readyForFence = true;
-	uint64_t frameID;  // always incrementing, set at the start of each frame.
 
 	VkFence fence = VK_NULL_HANDLE;
 

Common/GPU/Vulkan/VulkanRenderManager.cpp

@@ -546,16 +546,42 @@ void VulkanRenderManager::PresentWaitThreadFunc() {
 	uint64_t waitedId = frameIdGen_;
 	while (run_) {
 		const uint64_t timeout = 1000000000ULL;  // 1 sec
-		vkWaitForPresentKHR(vulkan_->GetDevice(), vulkan_->GetSwapchain(), waitedId, timeout);
-		frameTimeData_[waitedId].actualPresent = time_now_d();
-		waitedId++;
-
+		if (VK_SUCCESS == vkWaitForPresentKHR(vulkan_->GetDevice(), vulkan_->GetSwapchain(), waitedId, timeout)) {
+			frameTimeData_[waitedId].actualPresent = time_now_d();
+			waitedId++;
+		}
 		_dbg_assert_(waitedId <= frameIdGen_);
 	}
 
 	INFO_LOG(G3D, "Leaving PresentWaitThreadFunc()");
 }
 
+void VulkanRenderManager::PollPresentTiming() {
+	// For VK_GOOGLE_display_timing, we need to poll.
+
+	// Poll for information about completed frames.
+	// NOTE: We seem to get the information pretty late! Like after 6 frames, which is quite weird.
+	// Tested on POCO F4.
+	if (vulkan_->Extensions().GOOGLE_display_timing) {
+		uint32_t count = 0;
+		vkGetPastPresentationTimingGOOGLE(vulkan_->GetDevice(), vulkan_->GetSwapchain(), &count, nullptr);
+		if (count > 0) {
+			VkPastPresentationTimingGOOGLE *timings = new VkPastPresentationTimingGOOGLE[count];
+			vkGetPastPresentationTimingGOOGLE(vulkan_->GetDevice(), vulkan_->GetSwapchain(), &count, timings);
+			for (uint32_t i = 0; i < count; i++) {
+				uint64_t presentId = timings[i].presentID;
+				frameTimeData_[presentId].actualPresent = from_time_raw(timings[i].actualPresentTime);
+				frameTimeData_[presentId].desiredPresentTime = from_time_raw(timings[i].desiredPresentTime);
+				frameTimeData_[presentId].earliestPresentTime = from_time_raw(timings[i].earliestPresentTime);
+				double presentMargin = from_time_raw_relative(timings[i].presentMargin);
+				frameTimeData_[presentId].presentMargin = presentMargin;
+			}
+			delete[] timings;
+		}
+	}
+}
+
+
 void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfiler) {
 	double frameBeginTime = time_now_d()
 	VLOG("BeginFrame");
@@ -582,36 +608,19 @@ void VulkanRenderManager::BeginFrame(bool enableProfiling, bool enableLogProfile
 	}
 	vkResetFences(device, 1, &frameData.fence);
 
-	// Poll for information about completed frames.
-	if (vulkan_->Extensions().GOOGLE_display_timing) {
-		uint32_t count = 0;
-		vkGetPastPresentationTimingGOOGLE(vulkan_->GetDevice(), vulkan_->GetSwapchain(), &count, nullptr);
-		if (count > 0) {
-			VkPastPresentationTimingGOOGLE *timings = new VkPastPresentationTimingGOOGLE[count];
-			vkGetPastPresentationTimingGOOGLE(vulkan_->GetDevice(), vulkan_->GetSwapchain(), &count, timings);
-			for (uint32_t i = 0; i < count; i++) {
-				uint64_t presentId = timings[i].presentID;
-				frameTimeData_[presentId].actualPresent = from_time_raw(timings[i].actualPresentTime);
-				frameTimeData_[presentId].desiredPresentTime = from_time_raw(timings[i].desiredPresentTime);
-				frameTimeData_[presentId].earliestPresentTime = from_time_raw(timings[i].earliestPresentTime);
-				frameTimeData_[presentId].presentMargin = from_time_raw(timings[i].presentMargin);
-				INFO_LOG(G3D, "presentID: %llu : %f", (unsigned long long)presentId, frameTimeData_[presentId].actualPresent);
-			}
-			delete[] timings;
-		}
-	}
+	uint64_t frameId = frameIdGen_++;
+
+	PollPresentTiming();
 
 	int validBits = vulkan_->GetQueueFamilyProperties(vulkan_->GetGraphicsQueueFamilyIndex()).timestampValidBits;
 
 	// Can't set this until after the fence.
 	frameData.profile.enabled = enableProfiling;
 	frameData.profile.timestampsEnabled = enableProfiling && validBits > 0;
-	frameData.frameID = frameIdGen_++;
-
-	uint64_t frameId = ++frameIdGen_;
 	frameData.frameId = frameId;
 
 	frameTimeData_[frameId] = {};
+	frameTimeData_[frameId].frameId = frameId;
 	frameTimeData_[frameId].frameBegin = frameBeginTime;
 	frameTimeData_[frameId].afterFenceWait = time_now_d();
 

Common/GPU/Vulkan/VulkanRenderManager.h

@@ -481,6 +481,7 @@ private:
 	void StopThread();
 
 	void PresentWaitThreadFunc();
+	void PollPresentTiming();
 
 	FrameDataShared frameDataShared_;
 

Common/TimeUtil.cpp

@@ -54,6 +54,9 @@ double from_time_raw(uint64_t raw_time) {
 	return (double)raw_time * (1.0 / nanos);
 }
 
+double from_time_raw_relative(uint64_t raw_time) {
+	return from_time_raw(raw_time);
+}
 
 #elif PPSSPP_PLATFORM(ANDROID) || PPSSPP_PLATFORM(LINUX) || PPSSPP_PLATFORM(MAC) || PPSSPP_PLATFORM(IOS)
 
@@ -78,6 +81,10 @@ double time_now_d() {
 	return from_time_raw(raw_time);
 }
 
+double from_time_raw_relative(uint64_t raw_time) {
+	return (double)raw_time * (1.0 / nanos);
+}
+
 #else
 
 double time_now_d() {
@@ -99,6 +106,10 @@ double from_time_raw(uint64_t raw_time) {
 	return (double)raw_time * (1.0 / nanos);
 }
 
+double from_time_raw_relative(uint64_t raw_time) {
+	return from_time_raw(raw_time);
+}
+
 #endif
 
 void sleep_ms(int ms) {

Common/TimeUtil.h

@@ -11,6 +11,7 @@ uint64_t time_now_raw();
 
 // This is only interesting for Linux, in relation to VK_GOOGLE_display_timing.
 double from_time_raw(uint64_t raw_time);
+double from_time_raw_relative(uint64_t raw_time);
 
 // Sleep. Does not necessarily have millisecond granularity, especially on Windows.
 void sleep_ms(int ms);

UI/DebugOverlay.cpp

@@ -104,45 +104,47 @@ static void DrawFrameTiming(UIContext *ctx, const Bounds &bounds) {
 
 	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;
-		double actualPresentLatency_s = data.actualPresent - data.frameBegin;
-		double margin = data.presentMargin;
-		double computedMargin = data.actualPresent - data.queuePresent;
-
-		char presentStats[256] = "";
-		if (data.actualPresent != 0.0) {
-			snprintf(presentStats, sizeof(presentStats),
-				"* Actual present: %0.1f ms\n"
-				"* Margin: %0.1f ms (%0.1f computed)\n",
-				actualPresentLatency_s * 1000.0,
-				margin * 1000.0,
-				computedMargin * 1000.0);
-		}
-		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"
-			"%s",
-			fenceLatency_s * 1000.0,
-			submitLatency_s * 1000.0,
-			queuePresentLatency_s * 1000.0,
-			presentStats
-		);
-	}
-
 	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);
+
+	for (int i = 0; i < 8; i++) {
+		FrameTimeData data = ctx->GetDrawContext()->GetFrameTimeData(6 + i);
+		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;
+			double actualPresentLatency_s = data.actualPresent - data.frameBegin;
+			double presentMargin = data.presentMargin;
+			double computedMargin = data.actualPresent - data.queuePresent;
+
+			char presentStats[256] = "";
+			if (data.actualPresent != 0.0) {
+				snprintf(presentStats, sizeof(presentStats),
+					"* Present: %0.1f ms\n"
+					"* Margin: %0.1f ms\n"
+					"* Margin(c): %0.1f ms\n",
+					actualPresentLatency_s * 1000.0,
+					presentMargin * 1000.0,
+					computedMargin * 1000.0);
+			}
+			snprintf(statBuf, sizeof(statBuf),
+				"%llu: From start of frame to event:\n"
+				"* Past fence: %0.1f ms\n"
+				"* Submit #1: %0.1f ms\n"
+				"* Queue-p: %0.1f ms\n"
+				"%s",
+				(long long)data.frameId,
+				fenceLatency_s * 1000.0,
+				submitLatency_s * 1000.0,
+				queuePresentLatency_s * 1000.0,
+				presentStats
+			);
+		}
+		ctx->Draw()->DrawTextRect(ubuntu24, statBuf, bounds.x + 10 + i * 150, bounds.y + 50, bounds.w - 20, bounds.h - 30, 0xFFFFFFFF, FLAG_DYNAMIC_ASCII);
+	}
 	ctx->Draw()->SetFontScale(1.0f, 1.0f);
 	ctx->Flush();
 	ctx->RebindTexture();

UI/RetroAchievementScreens.cpp

@@ -388,15 +388,15 @@ void RetroAchievementsSettingsScreen::CreateCustomizeTab(UI::ViewGroup *viewGrou
 	viewGroup->Add(new AudioFileChooser(&g_Config.sAchievementsUnlockAudioFile, ac->T("Achievement unlocked"), UISound::ACHIEVEMENT_UNLOCKED));
 	viewGroup->Add(new AudioFileChooser(&g_Config.sAchievementsLeaderboardSubmitAudioFile, ac->T("Leaderboard score submission"), UISound::LEADERBOARD_SUBMITTED));
 
-	static const char *positions[] = { "Bottom Left", "Bottom Center", "Bottom Right", "Top Left", "Top Center", "Top Right", "Center Left", "Center Right", "None" };
+	static const char *positions[] = { "None", "Bottom Left", "Bottom Center", "Bottom Right", "Top Left", "Top Center", "Top Right", "Center Left", "Center Right" };
 
 	viewGroup->Add(new ItemHeader(ac->T("Notifications")));
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardStartedOrFailedPos, ac->T("Leaderboard attempt started or failed"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardSubmittedPos, ac->T("Leaderboard result submitted"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardTrackerPos, ac->T("Leaderboard tracker"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsUnlockedPos, ac->T("Achievement unlocked"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsChallengePos, ac->T("Challenge indicator"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
-	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsProgressPos, ac->T("Achievement progress"), positions, 0, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardStartedOrFailedPos, ac->T("Leaderboard attempt started or failed"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardSubmittedPos, ac->T("Leaderboard result submitted"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsLeaderboardTrackerPos, ac->T("Leaderboard tracker"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsUnlockedPos, ac->T("Achievement unlocked"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsChallengePos, ac->T("Challenge indicator"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
+	viewGroup->Add(new PopupMultiChoice(&g_Config.iAchievementsProgressPos, ac->T("Achievement progress"), positions, -1, ARRAY_SIZE(positions), I18NCat::DIALOG, screenManager()))->SetEnabledPtr(&g_Config.bAchievementsEnable);
 }
 
 void RetroAchievementsSettingsScreen::CreateDeveloperToolsTab(UI::ViewGroup *viewGroup) {