From 94d9d138d9b8547dc63a705014a5f5b874472613 Mon Sep 17 00:00:00 2001 From: degasus Date: Wed, 19 Nov 2014 19:57:12 +0100 Subject: [PATCH] Common: Add a built-in profiler --- Source/Core/Common/CMakeLists.txt | 1 + Source/Core/Common/Common.vcxproj | 2 + Source/Core/Common/Common.vcxproj.filters | 2 + Source/Core/Common/Profiler.cpp | 138 ++++++++++++++++++++++ Source/Core/Common/Profiler.h | 59 +++++++++ Source/Core/Common/Timer.cpp | 23 ++++ Source/Core/Common/Timer.h | 1 + Source/Core/VideoBackends/D3D/Render.cpp | 7 ++ Source/Core/VideoBackends/OGL/Render.cpp | 3 + 9 files changed, 236 insertions(+) create mode 100644 Source/Core/Common/Profiler.cpp create mode 100644 Source/Core/Common/Profiler.h diff --git a/Source/Core/Common/CMakeLists.txt b/Source/Core/Common/CMakeLists.txt index 9a0d508f4c..2a2146b9e7 100644 --- a/Source/Core/Common/CMakeLists.txt +++ b/Source/Core/Common/CMakeLists.txt @@ -15,6 +15,7 @@ set(SRCS BreakPoints.cpp Network.cpp PcapFile.cpp PerformanceCounter.cpp + Profiler.cpp SettingsHandler.cpp SDCardUtil.cpp StringUtil.cpp diff --git a/Source/Core/Common/Common.vcxproj b/Source/Core/Common/Common.vcxproj index 5d7a31904d..301c61524f 100644 --- a/Source/Core/Common/Common.vcxproj +++ b/Source/Core/Common/Common.vcxproj @@ -70,6 +70,7 @@ + @@ -105,6 +106,7 @@ + diff --git a/Source/Core/Common/Common.vcxproj.filters b/Source/Core/Common/Common.vcxproj.filters index ac5b5c454f..2f121ca882 100644 --- a/Source/Core/Common/Common.vcxproj.filters +++ b/Source/Core/Common/Common.vcxproj.filters @@ -42,6 +42,7 @@ + @@ -88,6 +89,7 @@ + diff --git a/Source/Core/Common/Profiler.cpp b/Source/Core/Common/Profiler.cpp new file mode 100644 index 0000000000..2752b0d23c --- /dev/null +++ b/Source/Core/Common/Profiler.cpp @@ -0,0 +1,138 @@ +// Copyright 2014 Dolphin Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +static const u32 PROFILER_FIELD_LENGTH = 8; +static const u32 PROFILER_FIELD_LENGTH_FP = PROFILER_FIELD_LENGTH+3; +static const int PROFILER_LAZY_DELAY = 60; // in frames + +#include +#include +#include +#include +#include +#include + +#include "Common/Profiler.h" +#include "Common/Timer.h" + +std::list Profiler::s_all_profilers; +u32 Profiler::s_max_length = 0; +u64 Profiler::s_frame_time; +u64 Profiler::s_usecs_frame; + +std::string Profiler::s_lazy_result = ""; +int Profiler::s_lazy_delay = 0; + +Profiler::Profiler(const std::string& name) +: m_name(name), m_usecs(0), m_usecs_min(-1), m_usecs_max(0), m_usecs_quad(0), m_calls(0), m_depth(0) +{ + m_time = Common::Timer::GetTimeUs(); + s_max_length = std::max(s_max_length, u32(m_name.length())); + + s_all_profilers.push_back(this); +} + +Profiler::~Profiler() +{ + s_all_profilers.remove(this); +} + +std::string Profiler::ToString() +{ + if (s_lazy_delay > 0) + { + s_lazy_delay--; + return s_lazy_result; + } + s_lazy_delay = PROFILER_LAZY_DELAY - 1; + + // don't write anything if no profilation is enabled + if (s_all_profilers.empty()) + return ""; + + u64 end = Common::Timer::GetTimeUs(); + s_usecs_frame = end - s_frame_time; + s_frame_time = end; + + std::ostringstream buffer; + buffer << std::setw(s_max_length) << std::left << "" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << "calls" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << "sum" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << "rel" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << "min" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << "avg" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << "stdev" << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << "max" << " "; + buffer << "/ usec" << std::endl; + + for (auto profiler : s_all_profilers) + { + buffer << profiler->Read() << std::endl; + } + s_lazy_result = buffer.str(); + return s_lazy_result; +} + +void Profiler::Start() +{ + if (!m_depth++) + { + m_time = Common::Timer::GetTimeUs(); + } +} + +void Profiler::Stop() +{ + if (!--m_depth) + { + u64 end = Common::Timer::GetTimeUs(); + + u64 diff = end - m_time; + + m_usecs += diff; + m_usecs_min = std::min(m_usecs_min, diff); + m_usecs_max = std::max(m_usecs_max, diff); + m_usecs_quad += diff * diff; + m_calls++; + } +} + +std::string Profiler::Read() +{ + double avg = 0; + double stdev = 0; + double time_rel = 0; + if(m_calls) + { + avg = double(m_usecs)/m_calls; + stdev = std::sqrt(double(m_usecs_quad)/m_calls - avg*avg); + } + else + { + m_usecs_min = 0; + } + if(s_usecs_frame) + { + time_rel = double(m_usecs)*100/s_usecs_frame; + } + + std::ostringstream buffer; + + buffer << std::setw(s_max_length) << std::left << m_name << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << m_calls << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << m_usecs << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << time_rel << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << m_usecs_min << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << std::fixed << std::setprecision(2) << avg << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH_FP) << std::right << std::fixed << std::setprecision(2) << stdev << " "; + buffer << std::setw(PROFILER_FIELD_LENGTH) << std::right << m_usecs_max; + + m_usecs = 0; + m_usecs_min = -1; + m_usecs_max = 0; + m_usecs_quad = 0; + m_calls = 0; + + return buffer.str(); +} diff --git a/Source/Core/Common/Profiler.h b/Source/Core/Common/Profiler.h new file mode 100644 index 0000000000..0b1a41dde3 --- /dev/null +++ b/Source/Core/Common/Profiler.h @@ -0,0 +1,59 @@ +// Copyright 2014 Dolphin Emulator Project +// Licensed under GPLv2+ +// Refer to the license.txt file included. + +#pragma once + +#include +#include + +#include "CommonTypes.h" + +class Profiler +{ +public: + Profiler(const std::string& name); + ~Profiler(); + + static std::string ToString(); + + void Start(); + void Stop(); + std::string Read(); + +private: + static std::list s_all_profilers; + static u32 s_max_length; + static u64 s_frame_time; + static u64 s_usecs_frame; + + static std::string s_lazy_result; + static int s_lazy_delay; + + std::string m_name; + u64 m_usecs; + u64 m_usecs_min; + u64 m_usecs_max; + u64 m_usecs_quad; + u64 m_calls; + u64 m_time; + int m_depth; +}; + +class ProfilerExecuter +{ +public: + ProfilerExecuter(Profiler* _p) : m_p(_p) + { + m_p->Start(); + } + ~ProfilerExecuter() + { + m_p->Stop(); + } +private: + Profiler* m_p; +}; + +// Warning: This profiler isn't thread safe. Only profile functions which doesn't run simultaneously +#define PROFILE(name) static Profiler prof_gen(name); ProfilerExecuter prof_e(&prof_gen); diff --git a/Source/Core/Common/Timer.cpp b/Source/Core/Common/Timer.cpp index 1ba750ae99..025fddeba6 100644 --- a/Source/Core/Common/Timer.cpp +++ b/Source/Core/Common/Timer.cpp @@ -32,6 +32,29 @@ u32 Timer::GetTimeMs() #endif } +#ifdef _WIN32 +double GetFreq() +{ + LARGE_INTEGER freq; + QueryPerformanceFrequency(&freq); + return 1000000.0 / double(freq.QuadPart); +} +#endif + +u64 Timer::GetTimeUs() +{ +#ifdef _WIN32 + LARGE_INTEGER time; + static double freq = GetFreq(); + QueryPerformanceCounter(&time); + return u64(double(time.QuadPart) * freq); +#else + struct timeval t; + (void)gettimeofday(&t, nullptr); + return ((u64)(t.tv_sec * 1000000 + t.tv_usec)); +#endif +} + // -------------------------------------------- // Initiate, Start, Stop, and Update the time // -------------------------------------------- diff --git a/Source/Core/Common/Timer.h b/Source/Core/Common/Timer.h index 6e0d666299..1df0f11601 100644 --- a/Source/Core/Common/Timer.h +++ b/Source/Core/Common/Timer.h @@ -33,6 +33,7 @@ public: u64 GetTimeElapsed(); static u32 GetTimeMs(); + static u64 GetTimeUs(); private: u64 m_LastTime; diff --git a/Source/Core/VideoBackends/D3D/Render.cpp b/Source/Core/VideoBackends/D3D/Render.cpp index 0441e63d7b..024c1d2604 100644 --- a/Source/Core/VideoBackends/D3D/Render.cpp +++ b/Source/Core/VideoBackends/D3D/Render.cpp @@ -8,6 +8,7 @@ #include #include +#include "Common/Profiler.h" #include "Common/Timer.h" #include "Core/ConfigManager.h" @@ -876,6 +877,12 @@ void Renderer::SwapImpl(u32 xfbAddr, u32 fbWidth, u32 fbStride, u32 fbHeight, co D3D::font.DrawTextScaled(0, 36, 20, 0.0f, 0xFF00FFFF, Statistics::ToStringProj()); } + std::string profile_output = Profiler::ToString(); + if (!profile_output.empty()) + { + D3D::font.DrawTextScaled(0, 44, 20, 0.0f, 0xFF00FFFF, profile_output); + } + OSD::DrawMessages(); D3D::EndFrame(); diff --git a/Source/Core/VideoBackends/OGL/Render.cpp b/Source/Core/VideoBackends/OGL/Render.cpp index 91be592b0e..186c663a89 100644 --- a/Source/Core/VideoBackends/OGL/Render.cpp +++ b/Source/Core/VideoBackends/OGL/Render.cpp @@ -12,6 +12,7 @@ #include "Common/Atomic.h" #include "Common/CommonPaths.h" #include "Common/FileUtil.h" +#include "Common/Profiler.h" #include "Common/StringUtil.h" #include "Common/Thread.h" #include "Common/Timer.h" @@ -764,6 +765,8 @@ void Renderer::DrawDebugInfo() if (SConfig::GetInstance().m_ShowInputDisplay) debug_info += Movie::GetInputDisplay(); + debug_info += Profiler::ToString(); + if (GLInterface->GetMode() == GLInterfaceMode::MODE_OPENGL && g_ActiveConfig.bShowEFBCopyRegions) { // Set Line Size