diff --git a/CMakeLists.txt b/CMakeLists.txt index 934f8520f6..eb9f403ccf 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/es-app/src/main.cpp b/es-app/src/main.cpp index 9cec9b0c64..26faeb2191 100644 --- a/es-app/src/main.cpp +++ b/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; diff --git a/es-core/CMakeLists.txt b/es-core/CMakeLists.txt index ebd97ab13c..c22459fd7c 100644 --- a/es-core/CMakeLists.txt +++ b/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 diff --git a/es-core/src/utils/ProfilingUtil.cpp b/es-core/src/utils/ProfilingUtil.cpp new file mode 100644 index 0000000000..0e4a290980 --- /dev/null +++ b/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 + +#if defined(_WIN32) +// because windows... +#include +#define snprintf _snprintf +#else // _WIN32 +#include +#endif // !_WIN32 + +////////////////////////////////////////////////////////////////////////// + +namespace Utils +{ + namespace Profiling + { + std::vector profiles; + std::vector 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(tv.tv_sec) * 1000000u + static_cast(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 diff --git a/es-core/src/utils/ProfilingUtil.h b/es-core/src/utils/ProfilingUtil.h new file mode 100644 index 0000000000..0cdbae0750 --- /dev/null +++ b/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 +#include +#include +#include +#include + +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 stack; + std::thread::id id; + + }; // ThreadStack + + extern std::vector profiles; + extern std::vector 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