Merge pull request #716 from tomaz82/profiling

Adding ProfilingUtil

CMakeLists.txt

@@ -4,6 +4,7 @@ option(GLES "Set to ON if targeting Embedded OpenGL" ${GLES})
 option(GL "Set to ON if targeting Desktop OpenGL" ${GL})
 option(RPI "Set to ON to enable the Raspberry PI video player (omxplayer) and audio options" ${RPI})
 option(CEC "Set to ON to enable CEC" ${CEC})
+option(PROFILING "Set to ON to enable profiling" ${PROFILING})
 
 # GLES implementation overrides
 option(USE_MESA_GLES "Set to ON to select the MESA OpenGL ES driver" ${USE_MESA_GLES})
@@ -113,6 +114,10 @@ if(DEFINED libCEC_FOUND)
     add_definitions(-DHAVE_LIBCEC)
 endif()
 
+if(PROFILING)
+    add_definitions(-DUSE_PROFILING)
+endif()
+
 #-------------------------------------------------------------------------------
 
 if(MSVC)

es-app/src/main.cpp

@@ -4,6 +4,7 @@
 #include "guis/GuiDetectDevice.h"
 #include "guis/GuiMsgBox.h"
 #include "utils/FileSystemUtil.h"
+#include "utils/ProfilingUtil.h"
 #include "views/ViewController.h"
 #include "CollectionSystemManager.h"
 #include "EmulationStation.h"
@@ -460,6 +461,8 @@ int main(int argc, char* argv[])
 
 	processQuitMode();
 
+	ProfileDump();
+
 	LOG(LogInfo) << "EmulationStation cleanly shutting down.";
 
 	return 0;

es-core/CMakeLists.txt

@@ -75,6 +75,7 @@ set(CORE_HEADERS
 
 	# Utils
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/FileSystemUtil.h
+	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/ProfilingUtil.h
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/StringUtil.h
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/ThreadPool.h
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/TimeUtil.h
@@ -154,6 +155,7 @@ set(CORE_SOURCES
 
 	# Utils
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/FileSystemUtil.cpp
+	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/ProfilingUtil.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/StringUtil.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/ThreadPool.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/utils/TimeUtil.cpp

es-core/src/utils/ProfilingUtil.cpp

@@ -0,0 +1,225 @@
+
+#if defined(USE_PROFILING)
+
+#include "utils/ProfilingUtil.h"
+
+#include "math/Misc.h"
+#include "Log.h"
+
+#include <algorithm>
+
+#if defined(_WIN32)
+// because windows...
+#include <Windows.h>
+#define snprintf _snprintf
+#else // _WIN32
+#include <sys/time.h>
+#endif // !_WIN32
+
+//////////////////////////////////////////////////////////////////////////
+
+namespace Utils
+{
+	namespace Profiling
+	{
+		std::vector<Profile*>     profiles;
+		std::vector<ThreadStack*> threadStacks;
+		std::recursive_mutex      mutex;
+		unsigned int              counter = 0;
+
+//////////////////////////////////////////////////////////////////////////
+
+		static double getFrequency( void )
+		{
+#if defined(_WIN32)
+			uint64_t qpFrequency;
+			QueryPerformanceFrequency((LARGE_INTEGER*)&qpFrequency);
+			return 1.0 / qpFrequency;
+#else // _WIN32
+			return 1.0 / 1000000.0;
+#endif // _WIN32
+		} // getFrequency
+
+//////////////////////////////////////////////////////////////////////////
+
+	static uint64_t getCounter( void )
+	{
+#if defined(_WIN32)
+			uint64_t qpCounter;
+			QueryPerformanceCounter((LARGE_INTEGER*)&qpCounter);
+			return qpCounter;
+#else // _WIN32
+			timeval tv;
+			gettimeofday(&tv, nullptr);
+			return static_cast<uint64_t>(tv.tv_sec) * 1000000u + static_cast<uint64_t>(tv.tv_usec);
+#endif // !_WIN32
+	} // getCounter
+
+//////////////////////////////////////////////////////////////////////////
+
+		static double getTime(void)
+		{
+			return getCounter() * getFrequency();
+
+		} // getTime
+
+//////////////////////////////////////////////////////////////////////////
+
+		static bool _sortProfiles(const Profile* _a, const Profile* _b)
+		{
+			return _a->message < _b->message;
+
+		} // _sortProfiles
+
+//////////////////////////////////////////////////////////////////////////
+
+		unsigned int _generateIndex(void)
+		{
+			mutex.lock();
+			unsigned int index = counter++;
+			mutex.unlock();
+
+			return index;
+
+		} // _generateIndex
+
+//////////////////////////////////////////////////////////////////////////
+
+		void _begin(const unsigned int _index, const std::string& _message)
+		{
+			const std::thread::id threadId    = std::this_thread::get_id();
+			ThreadStack*          threadStack = nullptr;
+			Profile*              profile     = nullptr;
+
+			mutex.lock();
+
+			for( ThreadStack* threadStackIt : threadStacks )
+				if(threadStackIt->id == threadId)
+					threadStack = threadStackIt;
+
+			if(!threadStack)
+			{
+				threadStack     = new ThreadStack;
+				threadStack->id = threadId;
+
+				threadStacks.push_back(threadStack);
+			}
+
+			while(profiles.size() < counter)
+			{
+				profile               = new Profile;
+				profile->message      = "";
+				profile->timeBegin    = 0.0;
+				profile->timeTotal    = 0.0;
+				profile->timeExternal = 0.0;
+				profile->timeMin      = 999999999.0;
+				profile->timeMax      = 0.0;
+				profile->callCount    = 0;
+
+				profiles.push_back(profile);
+			}
+
+			profile = profiles[_index];
+
+			threadStack->stack.push(profile);
+
+			profile->message   = _message;
+			profile->timeBegin = getTime();
+
+			mutex.unlock();
+
+		} // _begin
+
+//////////////////////////////////////////////////////////////////////////
+
+		int _end(void)
+		{
+			const double          timeEnd     = getTime();
+			const std::thread::id threadId    = std::this_thread::get_id();
+			ThreadStack*          threadStack = nullptr;
+			Profile*              profile     = nullptr;
+
+			mutex.lock();
+
+			for( ThreadStack* threadStackIt : threadStacks )
+				if(threadStackIt->id == threadId)
+					threadStack = threadStackIt;
+
+			profile = threadStack->stack.top();
+			threadStack->stack.pop();
+
+			// timer wrapped (~24 days)
+			if(timeEnd < profile->timeBegin)
+			{
+				mutex.unlock();
+				return 0;
+			}
+
+			const double timeElapsed = timeEnd - profile->timeBegin;
+
+			profile->timeTotal += timeElapsed;
+			profile->timeMin    = (profile->timeMin < timeElapsed) ? profile->timeMin : timeElapsed;
+			profile->timeMax    = (profile->timeMax > timeElapsed) ? profile->timeMax : timeElapsed;
+			profile->callCount++;
+
+			if(!threadStack->stack.empty())
+				threadStack->stack.top()->timeExternal += timeElapsed;
+
+			mutex.unlock();
+
+			return timeElapsed;
+
+		} // _end
+
+//////////////////////////////////////////////////////////////////////////
+
+		void _dump(void)
+		{
+			std::sort(profiles.begin(), profiles.end(), _sortProfiles);
+
+			if(!profiles.empty())
+			{
+				char buffer[1024];
+				int  longestMessage = 0;
+
+				for(Profile* profile : profiles)
+					longestMessage = Math::max(longestMessage, (int)profile->message.length());
+
+				char format1[1024];
+				snprintf(format1, 1024, "%%-%ds\t%%12s\t%%12s\t%%12s\t%%12s\t%%12s\t%%20s\t%%20s", longestMessage);
+
+				snprintf(buffer, 1024, format1, "Message", "Calls", "Total Time", "Avg Time", "Min Time", "Max Time", "Internal Total Time", "Internal Avg Time");
+				LOG(LogDebug) << buffer;
+
+				char format2[1024];
+				snprintf(format2, 1024, "%%-%ds\t%%12d\t%%12.6f\t%%12.6f\t%%12.6f\t%%12.6f\t%%20.6f\t%%20.6f", longestMessage);
+
+				for(Profile* profile : profiles)
+				{
+					if(profile->message.length())
+					{
+						snprintf(buffer, 1024, format2, profile->message.c_str(), profile->callCount, profile->timeTotal, profile->timeTotal / profile->callCount, profile->timeMin, profile->timeMax, profile->timeTotal - profile->timeExternal, (profile->timeTotal - profile->timeExternal) / profile->callCount);
+						LOG(LogDebug) << buffer;
+					}
+
+					delete profile;
+				}
+
+				profiles.clear();
+			}
+
+			if(!threadStacks.empty())
+			{
+				for(ThreadStack* threadStack : threadStacks)
+					delete threadStack;
+
+				threadStacks.clear();
+			}
+
+		} // _dump
+
+	} // Profiling::
+
+} // Utils::
+
+#endif // USE_PROFILING

es-core/src/utils/ProfilingUtil.h

@@ -0,0 +1,87 @@
+#pragma once
+#ifndef ES_CORE_UTILS_PROFILING_UTIL_H
+#define ES_CORE_UTILS_PROFILING_UTIL_H
+
+#if defined(USE_PROFILING)
+
+#include <mutex>
+#include <stack>
+#include <string>
+#include <thread>
+#include <vector>
+
+namespace Utils
+{
+	namespace Profiling
+	{
+		struct Profile
+		{
+			std::string  message;
+			double       timeBegin;
+			double       timeTotal;
+			double       timeExternal;
+			double       timeMin;
+			double       timeMax;
+			unsigned int callCount;
+
+		}; // Profile
+
+		struct ThreadStack
+		{
+			std::stack<Profile*> stack;
+			std::thread::id      id;
+
+		}; // ThreadStack
+
+		extern std::vector<Profile*>     profiles;
+		extern std::vector<ThreadStack*> threadStacks;
+		extern std::recursive_mutex      mutex;
+		extern unsigned int              counter;
+
+//////////////////////////////////////////////////////////////////////////
+
+		unsigned int _generateIndex(void);
+		void         _begin        (const unsigned int _index, const std::string& _message);
+		int          _end          (void);
+		void         _dump         (void);
+
+//////////////////////////////////////////////////////////////////////////
+
+		class Scope
+		{
+		public:
+
+			 Scope(const unsigned int _index, const std::string& _message) { _begin(_index, _message); }
+			~Scope(void)                                                   { _end(); }
+
+		}; // Scope
+
+	}; // Profiling::
+
+} // Utils::
+
+#define _profilingUnique(_name, _line) _name ## _line
+#define _profilingUniqueIndex(_line)   _profilingUnique(uniqueIndex, _line)
+#define _profilingUniqueScope(_line)   _profilingUnique(uniqueScope, _line)
+#define __profilingUniqueIndex         _profilingUniqueIndex(__LINE__)
+#define __profilingUniqueScope         _profilingUniqueScope(__LINE__)
+
+#define ProfileBegin(_message) static const unsigned int __profilingUniqueIndex = Utils::Profiling::_generateIndex(); Utils::Profiling::_begin(__profilingUniqueIndex, _message)
+#define ProfileEnd()           Utils::Profiling::_end()
+#define ProfileScope(_message) static const unsigned int __profilingUniqueIndex = Utils::Profiling::_generateIndex(); const Utils::Profiling::Scope __profilingUniqueScope(__profilingUniqueIndex, _message)
+#define ProfileDump()          Utils::Profiling::_dump()
+
+#else // USE_PROFILING
+
+#define ProfileBegin(_message)
+#define ProfileEnd()
+#define ProfileScope(_message)
+#define ProfileDump()
+
+#endif // !USE_PROFILING
+
+#if !defined(__PRETTY_FUNCTION__)
+#define __PRETTY_FUNCTION__ __FUNCTION__
+#endif // !__PRETTY_FUNCTION__
+
+#endif // ES_CORE_UTILS_TIME_UTIL_H