From 438af2f4fa858a21064cfab1d9be148a9ec72ea0 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Thu, 23 Mar 2017 18:57:18 -0700 Subject: [PATCH 1/3] Core: Separate collecting and displaying stats. --- Core/HLE/HLE.cpp | 18 ++++++++---------- Core/System.cpp | 19 +++++++++++++++++++ Core/System.h | 3 +++ GPU/GPUCommon.cpp | 12 ++++++------ 4 files changed, 36 insertions(+), 16 deletions(-) diff --git a/Core/HLE/HLE.cpp b/Core/HLE/HLE.cpp index 0a2531a5d7..32aefdd462 100644 --- a/Core/HLE/HLE.cpp +++ b/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 diff --git a/Core/System.cpp b/Core/System.cpp index 8211a675ff..159d212fe5 100644 --- a/Core/System.cpp +++ b/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,20 @@ void Core_UpdateState(CoreState newState) { Core_UpdateSingleStep(); } +void Core_ForceCollectDebugStats(bool flag) { + // Don't set the real flag yet, since it may trigger clearing jit cache. + coreCollectDebugStatsForced = flag; +} + +static void Core_UpdateCollectDebugStats(bool flag) { + bool newFlag = flag || coreCollectDebugStatsForced; + + if (coreCollectDebugStats != newFlag) { + coreCollectDebugStats = newFlag; + mipsr4k.ClearJitCache(); + } +} + void System_Wake() { // Ping the threads so they check coreState. CPU_NextStateNot(CPU_THREAD_NOT_RUNNING, CPU_THREAD_SHUTDOWN); @@ -517,6 +534,8 @@ void PSP_EndHostFrame() { } void PSP_RunLoopUntil(u64 globalticks) { + Core_UpdateCollectDebugStats(g_Config.bShowDebugStats); + SaveState::Process(); if (coreState == CORE_POWERDOWN || coreState == CORE_ERROR) { return; diff --git a/Core/System.h b/Core/System.h index b9c5feadf6..87851ee20a 100644 --- a/Core/System.h +++ b/Core/System.h @@ -97,6 +97,9 @@ enum CoreState CORE_ERROR, }; +extern bool coreCollectDebugStats; +void Core_ForceCollectDebugStats(bool flag); + extern volatile CoreState coreState; extern volatile bool coreStatePending; void Core_UpdateState(CoreState newState); diff --git a/GPU/GPUCommon.cpp b/GPU/GPUCommon.cpp index dac13fe626..4e28d5f1d9 100644 --- a/GPU/GPUCommon.cpp +++ b/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); -} \ No newline at end of file +} From 47565e1a9ebea5337dfabd98796d4a252e17d3fb Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Thu, 23 Mar 2017 19:02:19 -0700 Subject: [PATCH 2/3] Core: Add a feature to log stats on any frame drop. --- Core/HLE/sceDisplay.cpp | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/Core/HLE/sceDisplay.cpp b/Core/HLE/sceDisplay.cpp index 5f06011f0d..611e288d44 100644 --- a/Core/HLE/sceDisplay.cpp +++ b/Core/HLE/sceDisplay.cpp @@ -56,6 +56,9 @@ #include "GPU/Common/FramebufferCommon.h" #include "GPU/Common/PostShader.h" +// Enable to log info about any dropped frames. +static const bool logFrameDrops = true; + struct FrameBufferState { u32 topaddr; GEBufferFormat fmt; @@ -479,6 +482,19 @@ static bool FrameTimingThrottled() { return !PSP_CoreParameter().unthrottle; } +static void DoFrameDropLogging(float scaledTimestep) { + // Make sure we're collecting so we can log. + Core_ForceCollectDebugStats(true); + + if (lastFrameTime != 0.0 && 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); + } +} + // Let's collect all the throttling and frameskipping logic here. static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { PROFILE_THIS_SCOPE("timing"); @@ -522,6 +538,10 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { } curFrameTime = time_now_d(); + if (logFrameDrops) { + 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)) { From 01703f7ffc53de0a165bece2ad2d81c0827707ad Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Thu, 23 Mar 2017 19:16:17 -0700 Subject: [PATCH 3/3] Core: Add UI option to enable frame drop logging. --- Core/Config.cpp | 1 + Core/Config.h | 1 + Core/HLE/sceDisplay.cpp | 18 +++++++----------- Core/System.cpp | 13 +++---------- Core/System.h | 1 - UI/GameSettingsScreen.cpp | 1 + 6 files changed, 13 insertions(+), 22 deletions(-) diff --git a/Core/Config.cpp b/Core/Config.cpp index fc198df165..41a76f23f0 100644 --- a/Core/Config.cpp +++ b/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), }; diff --git a/Core/Config.h b/Core/Config.h index 67c406a125..8031dbf128 100644 --- a/Core/Config.h +++ b/Core/Config.h @@ -235,6 +235,7 @@ public: bool bShowDebuggerOnLoad; int iShowFPSCounter; + bool bLogFrameDrops; bool bShowDebugStats; bool bShowAudioDebug; bool bAudioResampler; diff --git a/Core/HLE/sceDisplay.cpp b/Core/HLE/sceDisplay.cpp index 611e288d44..6bf8a92f00 100644 --- a/Core/HLE/sceDisplay.cpp +++ b/Core/HLE/sceDisplay.cpp @@ -56,9 +56,6 @@ #include "GPU/Common/FramebufferCommon.h" #include "GPU/Common/PostShader.h" -// Enable to log info about any dropped frames. -static const bool logFrameDrops = true; - struct FrameBufferState { u32 topaddr; GEBufferFormat fmt; @@ -483,15 +480,15 @@ static bool FrameTimingThrottled() { } static void DoFrameDropLogging(float scaledTimestep) { - // Make sure we're collecting so we can log. - Core_ForceCollectDebugStats(true); - - if (lastFrameTime != 0.0 && lastFrameTime + scaledTimestep < curFrameTime) { + 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); + 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(); } } @@ -527,8 +524,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. @@ -538,7 +533,7 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { } curFrameTime = time_now_d(); - if (logFrameDrops) { + if (g_Config.bLogFrameDrops) { DoFrameDropLogging(scaledTimestep); } @@ -578,6 +573,7 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { } lastFrameTime = nextFrameTime; + wasPaused = false; } static void DoFrameIdleTiming() { diff --git a/Core/System.cpp b/Core/System.cpp index 159d212fe5..62e5303b0a 100644 --- a/Core/System.cpp +++ b/Core/System.cpp @@ -370,16 +370,9 @@ void Core_UpdateState(CoreState newState) { Core_UpdateSingleStep(); } -void Core_ForceCollectDebugStats(bool flag) { - // Don't set the real flag yet, since it may trigger clearing jit cache. - coreCollectDebugStatsForced = flag; -} - static void Core_UpdateCollectDebugStats(bool flag) { - bool newFlag = flag || coreCollectDebugStatsForced; - - if (coreCollectDebugStats != newFlag) { - coreCollectDebugStats = newFlag; + if (coreCollectDebugStats != flag) { + coreCollectDebugStats = flag; mipsr4k.ClearJitCache(); } } @@ -534,7 +527,7 @@ void PSP_EndHostFrame() { } void PSP_RunLoopUntil(u64 globalticks) { - Core_UpdateCollectDebugStats(g_Config.bShowDebugStats); + Core_UpdateCollectDebugStats(g_Config.bShowDebugStats || g_Config.bLogFrameDrops); SaveState::Process(); if (coreState == CORE_POWERDOWN || coreState == CORE_ERROR) { diff --git a/Core/System.h b/Core/System.h index 87851ee20a..f8f6472d25 100644 --- a/Core/System.h +++ b/Core/System.h @@ -98,7 +98,6 @@ enum CoreState }; extern bool coreCollectDebugStats; -void Core_ForceCollectDebugStats(bool flag); extern volatile CoreState coreState; extern volatile bool coreStatePending; diff --git a/UI/GameSettingsScreen.cpp b/UI/GameSettingsScreen.cpp index 3149a489d6..5709c7ffa7 100644 --- a/UI/GameSettingsScreen.cpp +++ b/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);