From a262f18bd7facfade926ad1c20feba25b30e785a Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 11:15:10 -0700 Subject: [PATCH 1/6] Fix profiler labels when skipping UI. Example: adb shell am start -n org.ppsspp.ppsspp/.PpssppActivity -e org.ppsspp.ppsspp.Shortcuts /storage/emulated/0/gamefile.cso --- UI/DevScreens.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/UI/DevScreens.cpp b/UI/DevScreens.cpp index 7b44a1f420..623f990692 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -810,6 +810,8 @@ void DrawProfile(UIContext &ui) { int numCategories = Profiler_GetNumCategories(); int historyLength = Profiler_GetHistoryLength(); + ui.SetFontStyle(ui.theme->uiFont); + float legendWidth = 80.0f; for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); From 8fdceba7cafe6aa6174688e99939a078cec2324d Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 12:05:08 -0700 Subject: [PATCH 2/6] Add timing for all the basics. This way we can see overall stats for a frame. --- Core/CoreTiming.cpp | 2 ++ Core/HLE/HLE.cpp | 2 ++ Core/HLE/sceDisplay.cpp | 4 ++++ Core/MIPS/ARM/ArmCompBranch.cpp | 8 ++++++++ Core/MIPS/ARM/ArmJit.cpp | 6 ++++-- Core/MIPS/ARM64/Arm64CompBranch.cpp | 8 ++++++++ Core/MIPS/ARM64/Arm64Jit.cpp | 3 +++ Core/MIPS/MIPS/MipsJit.cpp | 3 +++ Core/MIPS/x86/CompBranch.cpp | 7 +++++++ Core/MIPS/x86/Jit.cpp | 3 +++ GPU/GLES/GLES_GPU.cpp | 2 +- GPU/GLES/TransformPipeline.cpp | 1 + 12 files changed, 46 insertions(+), 3 deletions(-) diff --git a/Core/CoreTiming.cpp b/Core/CoreTiming.cpp index 6c8f08e98e..57093d17ae 100644 --- a/Core/CoreTiming.cpp +++ b/Core/CoreTiming.cpp @@ -20,6 +20,7 @@ #include #include "base/logging.h" +#include "profiler/profiler.h" #include "Common/MsgHandler.h" #include "Common/StdMutex.h" @@ -583,6 +584,7 @@ void ForceCheck() void Advance() { + PROFILE_THIS_SCOPE("advance"); int cyclesExecuted = slicelength - currentMIPS->downcount; globalTimer += cyclesExecuted; currentMIPS->downcount = slicelength; diff --git a/Core/HLE/HLE.cpp b/Core/HLE/HLE.cpp index 34c7496e0b..f02d806de8 100644 --- a/Core/HLE/HLE.cpp +++ b/Core/HLE/HLE.cpp @@ -22,6 +22,7 @@ #include "base/logging.h" #include "base/timeutil.h" +#include "profiler/profiler.h" #include "Core/Config.h" #include "Core/CoreTiming.h" @@ -521,6 +522,7 @@ 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) { diff --git a/Core/HLE/sceDisplay.cpp b/Core/HLE/sceDisplay.cpp index e9217dd10e..ee99333eb2 100644 --- a/Core/HLE/sceDisplay.cpp +++ b/Core/HLE/sceDisplay.cpp @@ -31,6 +31,7 @@ // and move everything into native... #include "base/logging.h" #include "base/timeutil.h" +#include "profiler/profiler.h" #ifndef _XBOX #include "gfx_es2/gl_state.h" @@ -489,6 +490,7 @@ static bool FrameTimingThrottled() { // Let's collect all the throttling and frameskipping logic here. static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { + PROFILE_THIS_SCOPE("timing"); int fpsLimiter = PSP_CoreParameter().fpsLimit; throttle = FrameTimingThrottled(); skipFrame = false; @@ -568,6 +570,7 @@ static void DoFrameTiming(bool &throttle, bool &skipFrame, float timestep) { } static void DoFrameIdleTiming() { + PROFILE_THIS_SCOPE("timing"); if (!FrameTimingThrottled() || !g_Config.bEnableSound || wasPaused) { return; } @@ -727,6 +730,7 @@ void hleLagSync(u64 userdata, int cyclesLate) { // The goal here is to prevent network, audio, and input lag from the real world. // Our normal timing is very "stop and go". This is efficient, but causes real world lag. // This event (optionally) runs every 1ms to sync with the real world. + PROFILE_THIS_SCOPE("timing"); if (!FrameTimingThrottled()) { lagSyncScheduled = false; diff --git a/Core/MIPS/ARM/ArmCompBranch.cpp b/Core/MIPS/ARM/ArmCompBranch.cpp index 9fd5093179..920fceab52 100644 --- a/Core/MIPS/ARM/ArmCompBranch.cpp +++ b/Core/MIPS/ARM/ArmCompBranch.cpp @@ -15,6 +15,8 @@ // Official git repository and contact information can be found at // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. +#include "profiler/profiler.h" + #include "Core/Reporting.h" #include "Core/Config.h" #include "Core/MemMap.h" @@ -607,6 +609,11 @@ void ArmJit::Comp_Syscall(MIPSOpcode op) FlushAll(); SaveDowncount(); +#ifdef USE_PROFILER + // When profiling, we can't skip CallSyscall, since it times syscalls. + gpr.SetRegImm(R0, op.encoding); + QuickCallFunction(R1, (void *)&CallSyscall); +#else // Skip the CallSyscall where possible. void *quickFunc = GetQuickSyscallFunc(op); if (quickFunc) @@ -620,6 +627,7 @@ void ArmJit::Comp_Syscall(MIPSOpcode op) gpr.SetRegImm(R0, op.encoding); QuickCallFunction(R1, (void *)&CallSyscall); } +#endif ApplyRoundingMode(); RestoreDowncount(); diff --git a/Core/MIPS/ARM/ArmJit.cpp b/Core/MIPS/ARM/ArmJit.cpp index 998b4e3b28..506c16a10e 100644 --- a/Core/MIPS/ARM/ArmJit.cpp +++ b/Core/MIPS/ARM/ArmJit.cpp @@ -16,6 +16,7 @@ // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. #include "base/logging.h" +#include "profiler/profiler.h" #include "Common/ChunkFile.h" #include "Core/Reporting.h" @@ -195,6 +196,7 @@ void ArmJit::CompileDelaySlot(int flags) void ArmJit::Compile(u32 em_address) { + PROFILE_THIS_SCOPE("jitc"); if (GetSpaceLeft() < 0x10000 || blocks.IsFull()) { ClearCache(); } @@ -230,8 +232,8 @@ void ArmJit::Compile(u32 em_address) { } } -void ArmJit::RunLoopUntil(u64 globalticks) -{ +void ArmJit::RunLoopUntil(u64 globalticks) { + PROFILE_THIS_SCOPE("jit"); ((void (*)())enterCode)(); } diff --git a/Core/MIPS/ARM64/Arm64CompBranch.cpp b/Core/MIPS/ARM64/Arm64CompBranch.cpp index dfe2e9315b..afae6ec40e 100644 --- a/Core/MIPS/ARM64/Arm64CompBranch.cpp +++ b/Core/MIPS/ARM64/Arm64CompBranch.cpp @@ -15,6 +15,8 @@ // Official git repository and contact information can be found at // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. +#include "profiler/profiler.h" + #include "Core/Reporting.h" #include "Core/Config.h" #include "Core/MemMap.h" @@ -590,6 +592,11 @@ void Arm64Jit::Comp_Syscall(MIPSOpcode op) FlushAll(); SaveDowncount(); +#ifdef USE_PROFILER + // When profiling, we can't skip CallSyscall, since it times syscalls. + MOVI2R(W0, op.encoding); + QuickCallFunction(X1, (void *)&CallSyscall); +#else // Skip the CallSyscall where possible. void *quickFunc = GetQuickSyscallFunc(op); if (quickFunc) { @@ -600,6 +607,7 @@ void Arm64Jit::Comp_Syscall(MIPSOpcode op) MOVI2R(W0, op.encoding); QuickCallFunction(X1, (void *)&CallSyscall); } +#endif ApplyRoundingMode(); RestoreDowncount(); diff --git a/Core/MIPS/ARM64/Arm64Jit.cpp b/Core/MIPS/ARM64/Arm64Jit.cpp index 25705bc269..c31e48de74 100644 --- a/Core/MIPS/ARM64/Arm64Jit.cpp +++ b/Core/MIPS/ARM64/Arm64Jit.cpp @@ -16,6 +16,7 @@ // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. #include "base/logging.h" +#include "profiler/profiler.h" #include "Common/ChunkFile.h" #include "Common/CPUDetect.h" @@ -179,6 +180,7 @@ void Arm64Jit::CompileDelaySlot(int flags) { void Arm64Jit::Compile(u32 em_address) { + PROFILE_THIS_SCOPE("jitc"); if (GetSpaceLeft() < 0x10000 || blocks.IsFull()) { INFO_LOG(JIT, "Space left: %i", GetSpaceLeft()); ClearCache(); @@ -217,6 +219,7 @@ void Arm64Jit::Compile(u32 em_address) { } void Arm64Jit::RunLoopUntil(u64 globalticks) { + PROFILE_THIS_SCOPE("jit"); ((void (*)())enterCode)(); } diff --git a/Core/MIPS/MIPS/MipsJit.cpp b/Core/MIPS/MIPS/MipsJit.cpp index b98b827314..c06405b020 100644 --- a/Core/MIPS/MIPS/MipsJit.cpp +++ b/Core/MIPS/MIPS/MipsJit.cpp @@ -16,6 +16,7 @@ // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. #include "base/logging.h" +#include "profiler/profiler.h" #include "Common/ChunkFile.h" #include "Core/Reporting.h" #include "Core/Config.h" @@ -137,6 +138,7 @@ void MipsJit::CompileDelaySlot(int flags) void MipsJit::Compile(u32 em_address) { + PROFILE_THIS_SCOPE("jitc"); if (GetSpaceLeft() < 0x10000 || blocks.IsFull()) { ClearCache(); } @@ -163,6 +165,7 @@ void MipsJit::Compile(u32 em_address) { void MipsJit::RunLoopUntil(u64 globalticks) { + PROFILE_THIS_SCOPE("jit"); ((void (*)())enterCode)(); } diff --git a/Core/MIPS/x86/CompBranch.cpp b/Core/MIPS/x86/CompBranch.cpp index a725a7012f..d4dfffde81 100644 --- a/Core/MIPS/x86/CompBranch.cpp +++ b/Core/MIPS/x86/CompBranch.cpp @@ -15,6 +15,8 @@ // Official git repository and contact information can be found at // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. +#include "profiler/profiler.h" + #include "Core/Reporting.h" #include "Core/Config.h" #include "Core/HLE/HLE.h" @@ -775,12 +777,17 @@ void Jit::Comp_Syscall(MIPSOpcode op) RestoreRoundingMode(); js.downcountAmount = -offset; +#ifdef USE_PROFILER + // When profiling, we can't skip CallSyscall, since it times syscalls. + ABI_CallFunctionC(&CallSyscall, op.encoding); +#else // Skip the CallSyscall where possible. void *quickFunc = GetQuickSyscallFunc(op); if (quickFunc) ABI_CallFunctionP(quickFunc, (void *)GetSyscallInfo(op)); else ABI_CallFunctionC(&CallSyscall, op.encoding); +#endif ApplyRoundingMode(); WriteSyscallExit(); diff --git a/Core/MIPS/x86/Jit.cpp b/Core/MIPS/x86/Jit.cpp index 7d77292727..84d270e00d 100644 --- a/Core/MIPS/x86/Jit.cpp +++ b/Core/MIPS/x86/Jit.cpp @@ -19,6 +19,7 @@ #include #include "math/math_util.h" +#include "profiler/profiler.h" #include "Common/ChunkFile.h" #include "Core/Core.h" @@ -347,6 +348,7 @@ void Jit::EatInstruction(MIPSOpcode op) void Jit::Compile(u32 em_address) { + PROFILE_THIS_SCOPE("jitc"); if (GetSpaceLeft() < 0x10000 || blocks.IsFull()) { ClearCache(); @@ -385,6 +387,7 @@ void Jit::Compile(u32 em_address) void Jit::RunLoopUntil(u64 globalticks) { + PROFILE_THIS_SCOPE("jit"); ((void (*)())asm_.enterCode)(); } diff --git a/GPU/GLES/GLES_GPU.cpp b/GPU/GLES/GLES_GPU.cpp index aa5ab008d7..9cfacb7e58 100644 --- a/GPU/GLES/GLES_GPU.cpp +++ b/GPU/GLES/GLES_GPU.cpp @@ -804,7 +804,7 @@ void GLES_GPU::Execute_Prim(u32 op, u32 diff) { return; } - // This also make skipping drawing very effective. + // This also makes skipping drawing very effective. framebufferManager_.SetRenderFrameBuffer(); if (gstate_c.skipDrawReason & (SKIPDRAW_SKIPFRAME | SKIPDRAW_NON_DISPLAYED_FB)) { transformDraw_.SetupVertexDecoder(gstate.vertType); diff --git a/GPU/GLES/TransformPipeline.cpp b/GPU/GLES/TransformPipeline.cpp index aec9acc0d8..f34be585f9 100644 --- a/GPU/GLES/TransformPipeline.cpp +++ b/GPU/GLES/TransformPipeline.cpp @@ -578,6 +578,7 @@ void TransformDrawEngine::FreeBuffer(GLuint buf) { } void TransformDrawEngine::DoFlush() { + PROFILE_THIS_SCOPE("flush"); gpuStats.numFlushes++; gpuStats.numTrackedVertexArrays = (int)vai_.size(); From 0f0c16f25f2275a6fd491f4b13b3dba3815bcca1 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 12:06:17 -0700 Subject: [PATCH 3/6] Skip "timing" categories in graph. --- UI/DevScreens.cpp | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/UI/DevScreens.cpp b/UI/DevScreens.cpp index 623f990692..a6f7102636 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -815,6 +815,10 @@ void DrawProfile(UIContext &ui) { float legendWidth = 80.0f; for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); + if (!strcmp(name, "timing")) { + continue; + } + float w = 0.0f, h = 0.0f; ui.MeasureText(ui.GetFontStyle(), name, &w, &h); if (w > legendWidth) { @@ -832,6 +836,9 @@ void DrawProfile(UIContext &ui) { for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); + if (!strcmp(name, "timing")) { + continue; + } uint32_t color = nice_colors[i % ARRAY_SIZE(nice_colors)]; float y = legendStartY + i * rowH; @@ -877,6 +884,10 @@ void DrawProfile(UIContext &ui) { maxVal = 0.0f; float maxTotal = 0.0f; for (int i = 0; i < numCategories; i++) { + const char *name = Profiler_GetCategoryName(i); + if (!strcmp(name, "timing")) { + continue; + } Profiler_GetHistory(i, &history[0], historyLength); float x = 10; From 2a0068764397bbc9a7e4d44d4253ddfd28ab116f Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 12:08:12 -0700 Subject: [PATCH 4/6] Skip categories that are small slices of the time. --- UI/DevScreens.cpp | 34 +++++++++++++++++++++++++--------- 1 file changed, 25 insertions(+), 9 deletions(-) diff --git a/UI/DevScreens.cpp b/UI/DevScreens.cpp index a6f7102636..3c392d3e3b 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -832,8 +832,15 @@ void DrawProfile(UIContext &ui) { float legendStartY = legendHeight > ui.GetBounds().centerY() ? ui.GetBounds().y2() - legendHeight : ui.GetBounds().centerY(); float legendStartX = ui.GetBounds().x2() - std::min(legendWidth, 200.0f); + static float lastMaxVal = 1.0f / 60.0f; + std::vector history; + std::vector total; + history.resize(historyLength); + total.resize(historyLength); + const uint32_t opacity = 140 << 24; + int legendNum = 0; for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); if (!strcmp(name, "timing")) { @@ -841,19 +848,29 @@ void DrawProfile(UIContext &ui) { } uint32_t color = nice_colors[i % ARRAY_SIZE(nice_colors)]; - float y = legendStartY + i * rowH; - ui.FillRect(UI::Drawable(opacity | color), Bounds(legendStartX, y, rowH - 2, rowH - 2)); - ui.DrawTextShadow(name, legendStartX + rowH + 2, y, 0xFFFFFFFF, ALIGN_VBASELINE); + Profiler_GetHistory(i, &history[0], historyLength); + float sum = 0.0f; + bool show = false; + for (int j = 0; j < historyLength; ++j) { + sum += history[j]; + if (history[j] > (lastMaxVal / 120.0f)) { + show = true; + } + } + if ((sum / historyLength) >= (lastMaxVal / 120.0f)) { + show = true; + } + + if (show) { + float y = legendStartY + legendNum++ * rowH; + ui.FillRect(UI::Drawable(opacity | color), Bounds(legendStartX, y, rowH - 2, rowH - 2)); + ui.DrawTextShadow(name, legendStartX + rowH + 2, y, 0xFFFFFFFF, ALIGN_VBASELINE); + } } float graphWidth = ui.GetBounds().x2() - legendWidth - 20.0f; float graphHeight = ui.GetBounds().h * 0.8f; - std::vector history; - std::vector total; - history.resize(historyLength); - total.resize(historyLength); - float dx = graphWidth / historyLength; /* @@ -863,7 +880,6 @@ void DrawProfile(UIContext &ui) { */ bool area = true; - static float lastMaxVal = 1.0f / 60.0f; float minVal = 0.0f; float maxVal = lastMaxVal; // TODO - adjust to frame length if (maxVal < 0.001f) From 12ca8f724b6521099a41969c508c4a039d05690b Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 12:12:19 -0700 Subject: [PATCH 5/6] Update native with higher frame cat count. --- native | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/native b/native index 670b2ff1e2..ad5301873f 160000 --- a/native +++ b/native @@ -1 +1 @@ -Subproject commit 670b2ff1e2506db44eb36141626b73bb45908420 +Subproject commit ad5301873f7db44eb4b13bc7592ffe511928325a From 3f9b5ee1a3feac586774e4454c8be7e69abbc6a8 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Fri, 3 Jul 2015 12:43:02 -0700 Subject: [PATCH 6/6] Clean up legend placement in profiler. --- UI/DevScreens.cpp | 60 ++++++++++++++++++++++++++--------------------- 1 file changed, 33 insertions(+), 27 deletions(-) diff --git a/UI/DevScreens.cpp b/UI/DevScreens.cpp index 3c392d3e3b..4f19690470 100644 --- a/UI/DevScreens.cpp +++ b/UI/DevScreens.cpp @@ -805,6 +805,12 @@ static const uint32_t nice_colors[] = { 0x33FFFF, }; +enum ProfileCatStatus { + PROFILE_CAT_VISIBLE = 0, + PROFILE_CAT_IGNORE = 1, + PROFILE_CAT_NOLEGEND = 2, +}; + void DrawProfile(UIContext &ui) { #ifdef USE_PROFILER int numCategories = Profiler_GetNumCategories(); @@ -812,56 +818,54 @@ void DrawProfile(UIContext &ui) { ui.SetFontStyle(ui.theme->uiFont); + static float lastMaxVal = 1.0f / 60.0f; + float legendMinVal = lastMaxVal * (1.0f / 120.0f); + + std::vector history; + std::vector catStatus; + history.resize(historyLength); + catStatus.resize(numCategories); + + float rowH = 30.0f; + float legendHeight = 0.0f; float legendWidth = 80.0f; for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); if (!strcmp(name, "timing")) { + catStatus[i] = PROFILE_CAT_IGNORE; continue; } + Profiler_GetHistory(i, &history[0], historyLength); + catStatus[i] = PROFILE_CAT_NOLEGEND; + for (int j = 0; j < historyLength; ++j) { + if (history[j] > legendMinVal) { + catStatus[i] = PROFILE_CAT_VISIBLE; + break; + } + } + + // So they don't move horizontally, we always measure. float w = 0.0f, h = 0.0f; ui.MeasureText(ui.GetFontStyle(), name, &w, &h); if (w > legendWidth) { legendWidth = w; } + legendHeight += rowH; } legendWidth += 20.0f; - float rowH = 30.0f; - float legendHeight = rowH * numCategories; float legendStartY = legendHeight > ui.GetBounds().centerY() ? ui.GetBounds().y2() - legendHeight : ui.GetBounds().centerY(); float legendStartX = ui.GetBounds().x2() - std::min(legendWidth, 200.0f); - static float lastMaxVal = 1.0f / 60.0f; - std::vector history; - std::vector total; - history.resize(historyLength); - total.resize(historyLength); - const uint32_t opacity = 140 << 24; int legendNum = 0; for (int i = 0; i < numCategories; i++) { const char *name = Profiler_GetCategoryName(i); - if (!strcmp(name, "timing")) { - continue; - } uint32_t color = nice_colors[i % ARRAY_SIZE(nice_colors)]; - Profiler_GetHistory(i, &history[0], historyLength); - float sum = 0.0f; - bool show = false; - for (int j = 0; j < historyLength; ++j) { - sum += history[j]; - if (history[j] > (lastMaxVal / 120.0f)) { - show = true; - } - } - if ((sum / historyLength) >= (lastMaxVal / 120.0f)) { - show = true; - } - - if (show) { + if (catStatus[i] == PROFILE_CAT_VISIBLE) { float y = legendStartY + legendNum++ * rowH; ui.FillRect(UI::Drawable(opacity | color), Bounds(legendStartX, y, rowH - 2, rowH - 2)); ui.DrawTextShadow(name, legendStartX + rowH + 2, y, 0xFFFFFFFF, ALIGN_VBASELINE); @@ -897,11 +901,13 @@ void DrawProfile(UIContext &ui) { ui.DrawTextShadow("1/60s", 5, y_60th, 0x80FFFF00); ui.DrawTextShadow("1ms", 5, y_1ms, 0x80FFFF00); + std::vector total; + total.resize(historyLength); + maxVal = 0.0f; float maxTotal = 0.0f; for (int i = 0; i < numCategories; i++) { - const char *name = Profiler_GetCategoryName(i); - if (!strcmp(name, "timing")) { + if (catStatus[i] == PROFILE_CAT_IGNORE) { continue; } Profiler_GetHistory(i, &history[0], historyLength);