Merge pull request #9492 from unknownbrackets/frame-drops

Allow debug logging of frame drops

Core/Config.cpp

@@ -520,6 +520,7 @@ static ConfigSetting graphicsSettings[] = {
 	ReportedConfigSetting("FragmentTestCache", &g_Config.bFragmentTestCache, true, true, true),
 
 	ConfigSetting("GfxDebugOutput", &g_Config.bGfxDebugOutput, false, false, false),
+	ConfigSetting("LogFrameDrops", &g_Config.bLogFrameDrops, false, true, false),
 
 	ConfigSetting(false),
 };

Core/Config.h

@@ -235,6 +235,7 @@ public:
 	bool bShowDebuggerOnLoad;
 	int iShowFPSCounter;
 
+	bool bLogFrameDrops;
 	bool bShowDebugStats;
 	bool bShowAudioDebug;
 	bool bAudioResampler;

Core/HLE/HLE.cpp

@@ -493,18 +493,16 @@ const HLEFunction *GetSyscallFuncPointer(MIPSOpcode op)
 	return &moduleDB[modulenum].funcTable[funcnum];
 }
 
-void *GetQuickSyscallFunc(MIPSOpcode op)
-{
-	// TODO: Clear jit cache on g_Config.bShowDebugStats change?
-	if (g_Config.bShowDebugStats)
-		return NULL;
+void *GetQuickSyscallFunc(MIPSOpcode op) {
+	if (coreCollectDebugStats)
+		return nullptr;
 
 	const HLEFunction *info = GetSyscallFuncPointer(op);
 	if (!info || !info->func)
-		return NULL;
+		return nullptr;
 
 	// TODO: Do this with a flag?
-	if (op == GetSyscallOp("FakeSysCalls", NID_IDLE))
+	if (op == idleOp)
 		return (void *)info->func;
 	if (info->flags != 0)
 		return (void *)&CallSyscallWithFlags;
@@ -520,8 +518,8 @@ void hleSetSteppingTime(double t)
 void CallSyscall(MIPSOpcode op)
 {
 	PROFILE_THIS_SCOPE("syscall");
-	double start = 0.0;  // need to initialize to fix the race condition where g_Config.bShowDebugStats is enabled in the middle of this func.
-	if (g_Config.bShowDebugStats)
+	double start = 0.0;  // need to initialize to fix the race condition where coreCollectDebugStats is enabled in the middle of this func.
+	if (coreCollectDebugStats)
 	{
 		time_update();
 		start = time_now_d();
@@ -546,7 +544,7 @@ void CallSyscall(MIPSOpcode op)
 		ERROR_LOG_REPORT(HLE, "Unimplemented HLE function %s", info->name ? info->name : "(\?\?\?)");
 	}
 
-	if (g_Config.bShowDebugStats)
+	if (coreCollectDebugStats)
 	{
 		time_update();
 		u32 callno = (op >> 6) & 0xFFFFF; //20 bits

Core/HLE/sceDisplay.cpp

@@ -477,6 +477,19 @@ static bool FrameTimingThrottled() {
 	return !PSP_CoreParameter().unthrottle;
 }
 
+static void DoFrameDropLogging(float scaledTimestep) {
+	if (lastFrameTime != 0.0 && !wasPaused && lastFrameTime + scaledTimestep < curFrameTime) {
+		const double actualTimestep = curFrameTime - lastFrameTime;
+
+		char stats[4096];
+		__DisplayGetDebugStats(stats, sizeof(stats));
+		NOTICE_LOG(HLE, "Dropping frames - budget = %.2fms / %.1ffps, actual = %.2fms (+%.2fms) / %.1ffps\n%s", scaledTimestep * 1000.0, 1.0 / scaledTimestep, actualTimestep * 1000.0, (actualTimestep - scaledTimestep) * 1000.0, 1.0 / actualTimestep, stats);
+	} else {
+		gpuStats.ResetFrame();
+		kernelStats.ResetFrame();
+	}
+}
+
 // Let's collect all the throttling and frameskipping logic here.
 static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) {
 	PROFILE_THIS_SCOPE("timing");
@@ -509,8 +522,6 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) {
 
 	if (lastFrameTime == 0.0 || wasPaused) {
 		nextFrameTime = time_now_d() + scaledTimestep;
-		if (wasPaused)
-			wasPaused = false;
 	} else {
 		// Advance lastFrameTime by a constant amount each frame,
 		// but don't let it get too far behind as things can get very jumpy.
@@ -520,6 +531,10 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) {
 	}
 	curFrameTime = time_now_d();
 
+	if (g_Config.bLogFrameDrops) {
+		DoFrameDropLogging(scaledTimestep);
+	}
+
 	// Auto-frameskip automatically if speed limit is set differently than the default.
 	bool useAutoFrameskip = g_Config.bAutoFrameSkip && g_Config.iRenderingMode != FB_NON_BUFFERED_MODE;
 	if (g_Config.bAutoFrameSkip || (g_Config.iFrameSkip == 0 && fpsLimiter == FPS_LIMIT_CUSTOM && g_Config.iFpsLimit > 60)) {
@@ -556,6 +571,7 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) {
 	}
 
 	lastFrameTime = nextFrameTime;
+	wasPaused = false;
 }
 
 static void DoFrameIdleTiming() {

Core/System.cpp

@@ -86,6 +86,9 @@ static std::condition_variable cpuThreadReplyCond;
 static u64 cpuThreadUntil;
 bool audioInitialized;
 
+bool coreCollectDebugStats = false;
+bool coreCollectDebugStatsForced = false;
+
 // This can be read and written from ANYWHERE.
 volatile CoreState coreState = CORE_STEPPING;
 // Note: intentionally not used for CORE_NEXTFRAME.
@@ -367,6 +370,13 @@ void Core_UpdateState(CoreState newState) {
 	Core_UpdateSingleStep();
 }
 
+static void Core_UpdateCollectDebugStats(bool flag) {
+	if (coreCollectDebugStats != flag) {
+		coreCollectDebugStats = flag;
+		mipsr4k.ClearJitCache();
+	}
+}
+
 void System_Wake() {
 	// Ping the threads so they check coreState.
 	CPU_NextStateNot(CPU_THREAD_NOT_RUNNING, CPU_THREAD_SHUTDOWN);
@@ -517,6 +527,8 @@ void PSP_EndHostFrame() {
 }
 
 void PSP_RunLoopUntil(u64 globalticks) {
+	Core_UpdateCollectDebugStats(g_Config.bShowDebugStats || g_Config.bLogFrameDrops);
+
 	SaveState::Process();
 	if (coreState == CORE_POWERDOWN || coreState == CORE_ERROR) {
 		return;

Core/System.h

@@ -97,6 +97,8 @@ enum CoreState
 	CORE_ERROR,
 };
 
+extern bool coreCollectDebugStats;
+
 extern volatile CoreState coreState;
 extern volatile bool coreStatePending;
 void Core_UpdateState(CoreState newState);

GPU/GPUCommon.cpp

@@ -848,13 +848,13 @@ u32 GPUCommon::Break(int mode) {
 }
 
 void GPUCommon::NotifySteppingEnter() {
-	if (g_Config.bShowDebugStats) {
+	if (coreCollectDebugStats) {
 		time_update();
 		timeSteppingStarted_ = time_now_d();
 	}
 }
 void GPUCommon::NotifySteppingExit() {
-	if (g_Config.bShowDebugStats) {
+	if (coreCollectDebugStats) {
 		if (timeSteppingStarted_ <= 0.0) {
 			ERROR_LOG(G3D, "Mismatched stepping enter/exit.");
 		}
@@ -867,7 +867,7 @@ void GPUCommon::NotifySteppingExit() {
 bool GPUCommon::InterpretList(DisplayList &list) {
 	// Initialized to avoid a race condition with bShowDebugStats changing.
 	double start = 0.0;
-	if (g_Config.bShowDebugStats) {
+	if (coreCollectDebugStats) {
 		time_update();
 		start = time_now_d();
 	}
@@ -936,7 +936,7 @@ bool GPUCommon::InterpretList(DisplayList &list) {
 
 	list.offsetAddr = gstate_c.offsetAddr;
 
-	if (g_Config.bShowDebugStats) {
+	if (coreCollectDebugStats) {
 		time_update();
 		double total = time_now_d() - start - timeSpentStepping_;
 		hleSetSteppingTime(timeSpentStepping_);
@@ -984,7 +984,7 @@ void GPUCommon::UpdatePC(u32 currentPC, u32 newPC) {
 	cyclesExecuted += 2 * executed;
 	cycleLastPC = newPC;
 
-	if (g_Config.bShowDebugStats) {
+	if (coreCollectDebugStats) {
 		gpuStats.otherGPUCycles += 2 * executed;
 		gpuStats.gpuCommandsAtCallLevel[std::min(currentList->stackptr, 3)] += executed;
 	}
@@ -2459,4 +2459,4 @@ bool GPUCommon::GetOutputFramebuffer(GPUDebugBuffer &buffer) {
 
 bool GPUCommon::GetCurrentTexture(GPUDebugBuffer &buffer, int level) {
 	return textureCache_->GetCurrentTextureDebug(buffer, level);
-}
+}

UI/GameSettingsScreen.cpp

@@ -1225,6 +1225,7 @@ void DeveloperToolsScreen::CreateViews() {
 #endif
 
 	list->Add(new CheckBox(&g_Config.bEnableLogging, dev->T("Enable Logging")))->OnClick.Handle(this, &DeveloperToolsScreen::OnLoggingChanged);
+	list->Add(new CheckBox(&g_Config.bLogFrameDrops, dev->T("Log Dropped Frame Statistics")));
 	list->Add(new Choice(dev->T("Logging Channels")))->OnClick.Handle(this, &DeveloperToolsScreen::OnLogConfig);
 	list->Add(new ItemHeader(dev->T("Language")));
 	list->Add(new Choice(dev->T("Load language ini")))->OnClick.Handle(this, &DeveloperToolsScreen::OnLoadLanguageIni);