Merge pull request #1574 from degasus/profiler

Common: Add a built-in profiler

9 files changed, 236 insertions, 0 deletions

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 @@
     <ClInclude Include="NandPaths.h" />
     <ClInclude Include="Network.h" />
     <ClInclude Include="PcapFile.h" />
+    <ClInclude Include="Profiler.h" />
     <ClInclude Include="SDCardUtil.h" />
     <ClInclude Include="SettingsHandler.h" />
     <ClInclude Include="StdMakeUnique.h" />
@@ -105,6 +106,7 @@
     <ClCompile Include="NandPaths.cpp" />
     <ClCompile Include="Network.cpp" />
     <ClCompile Include="PcapFile.cpp" />
+    <ClCompile Include="Profiler.cpp" />
     <ClCompile Include="SDCardUtil.cpp" />
     <ClCompile Include="SettingsHandler.cpp" />
     <ClCompile Include="StringUtil.cpp" />
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 @@
     <ClInclude Include="NandPaths.h" />
     <ClInclude Include="Network.h" />
     <ClInclude Include="PcapFile.h" />
+    <ClInclude Include="Profiler.h" />
     <ClInclude Include="SDCardUtil.h" />
     <ClInclude Include="SettingsHandler.h" />
     <ClInclude Include="StdMakeUnique.h" />
@@ -88,6 +89,7 @@
     <ClCompile Include="NandPaths.cpp" />
     <ClCompile Include="Network.cpp" />
     <ClCompile Include="PcapFile.cpp" />
+    <ClCompile Include="Profiler.cpp" />
     <ClCompile Include="SDCardUtil.cpp" />
     <ClCompile Include="SettingsHandler.cpp" />
     <ClCompile Include="StringUtil.cpp" />
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 <cmath>
+#include <cstdio>
+#include <cstring>
+#include <iomanip>
+#include <ios>
+#include <sstream>
+
+#include "Common/Profiler.h"
+#include "Common/Timer.h"
+
+std::list<Profiler*> 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<u32>(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 <list>
+#include <string>
+
+#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<Profiler*> 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 5db7b8b4ec..6adf3ac52f 100644
--- a/Source/Core/VideoBackends/D3D/Render.cpp
+++ b/Source/Core/VideoBackends/D3D/Render.cpp
@@ -8,6 +8,7 @@
 #include <strsafe.h>
 #include <unordered_map>
 
+#include "Common/Profiler.h"
 #include "Common/Timer.h"
 
 #include "Core/ConfigManager.h"
@@ -875,6 +876,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