From 10b04a4748205ca8f82e583492501d11e350770f Mon Sep 17 00:00:00 2001 From: Victor Zarubkin Date: Fri, 31 Mar 2017 21:17:08 +0300 Subject: [PATCH] (Core) First step for getting frame time at run-time. Now you can use EASY_FRAME_COUNTER (which is only frame-counter) or EASY_FRAME (which is EASY_FRAME_COUNTER + EASY_BLOCK) or EASY_FRAME_FUNCTION (which is EASY_FRAME_COUNTER + EASY_FUNCTION) to measure frame time even if profiler is disabled. To get frame time you can use profiler::main_thread::frameTimeLocalMax to get maximum frame duration since last call or profiler::main_thread::frameTime to get last frame time. --- NOTE: You have to put EASY_MAIN_THREAD to your main thread to be able to use profiler::main_thread functions. If you do not want to then you can use same functions from profiler::this_thread, but you will have to call them from your main thread. --- easy_profiler_core/include/easy/easy_net.h | 11 +- easy_profiler_core/include/easy/profiler.h | 267 +++++++++++++- .../include/easy/profiler_aux.h | 1 + easy_profiler_core/profile_manager.cpp | 339 ++++++++++++++---- easy_profiler_core/profile_manager.h | 15 +- sample/main.cpp | 19 +- 6 files changed, 564 insertions(+), 88 deletions(-) diff --git a/easy_profiler_core/include/easy/easy_net.h b/easy_profiler_core/include/easy/easy_net.h index e64e894..a04f9d2 100644 --- a/easy_profiler_core/include/easy/easy_net.h +++ b/easy_profiler_core/include/easy/easy_net.h @@ -73,7 +73,10 @@ enum MessageType : uint8_t MESSAGE_TYPE_EVENT_TRACING_STATUS, MESSAGE_TYPE_EVENT_TRACING_PRIORITY, - MESSAGE_TYPE_CHECK_CONNECTION + MESSAGE_TYPE_CHECK_CONNECTION, + + MESSAGE_TYPE_REQUEST_MAIN_FRAME_LOCAL_MAX_US, + MESSAGE_TYPE_REPLY_MAIN_FRAME_LOCAL_MAX_US, }; struct Message @@ -130,6 +133,12 @@ struct BoolMessage : public Message { BoolMessage() = default; }; +struct TimestampMessage : public Message { + uint64_t timestamp = 0; + TimestampMessage(MessageType _t, uint64_t _timestamp) : Message(_t), timestamp(_timestamp) { } + TimestampMessage() = default; +}; + #pragma pack(pop) }//net diff --git a/easy_profiler_core/include/easy/profiler.h b/easy_profiler_core/include/easy/profiler.h index e887672..5f5a86e 100644 --- a/easy_profiler_core/include/easy/profiler.h +++ b/easy_profiler_core/include/easy/profiler.h @@ -136,7 +136,7 @@ Name of the block automatically created with function name. ::profiler::Block EASY_UNIQUE_BLOCK(__LINE__)(EASY_UNIQUE_DESC(__LINE__), "");\ ::profiler::beginBlock(EASY_UNIQUE_BLOCK(__LINE__)); // this is to avoid compiler warning about unused variable -/** Macro for completion of last opened block. +/** Macro for completion of last opened block explicitly. \code #include @@ -161,11 +161,113 @@ int foo() */ # define EASY_END_BLOCK ::profiler::endBlock(); -/** Macro for creating event with custom name and color. +/** Macro for starting frame counter. -Event is a block with zero duration and special type. +Measures time even if profiler is disabled. +Use this if you want to observe your frame time at run-time to see if all is going right +or/and to find better moment to enable profiling. -\warning Event ends immidiately and calling EASY_END_BLOCK after EASY_EVENT +\warning This only changes value of profiler::this_thread::frameTime (or profiler::this_thread::frameTimeLocalMax). +This is not profiler::Block and is not saved to output file or sent via network. +You need to use this together with profiler::Block (or EASY_BLOCK, or EASY_FUNCTION). + +\note All following calls to EASY_FRAME_COUNTER would have no effect +until EASY_END_FRAME_COUNTER called or FrameCounter object destroyed. + +\note EASY_FRAME_COUNTER is not binded to Main thread only. +You are free to measure frame time of any thread you want. + +\code +#include +int main() +{ + EASY_MAIN_THREAD; + + // main application cycle + while (true) { + EASY_FRAME_COUNTER; // new frame counter which is used just to get frame time + EASY_BLOCK("Frame"); // this is Frame block which would be saved into file or sent via network + + // some code ... + + // frame ends here + } + + return 0; +} +\endcode + +\ingroup profiler +*/ +# define EASY_FRAME_COUNTER \ + ::profiler::FrameCounterGuard EASY_UNIQUE_FRAME_COUNTER(__LINE__);\ + ::profiler::beginFrame(EASY_UNIQUE_FRAME_COUNTER(__LINE__)); // this is to avoid compiler warning about unused variable + +/** Macro for stopping frame counter explicitly. + +\code +#include +int main() +{ + EASY_MAIN_THREAD; + + // main application cycle + while (true) { + EASY_FRAME_COUNTER; // new frame counter which is used just to get frame time + + // some code ... + + EASY_END_FRAME_COUNTER; // stop frame counter explicitly + + // some another code which we do not want to profile ... + + // frame really ends here, but we have explicitly said that it has ended earlier + } + + return 0; +} +\endcode + +\ingroup profiler +*/ +# define EASY_END_FRAME_COUNTER ::profiler::endFrame(); + +/** Macro combining EASY_BLOCK with EASY_FRAME_COUNTER + +\ingroup profiler +*/ +# define EASY_FRAME(name, ...)\ + EASY_LOCAL_STATIC_PTR(const ::profiler::BaseBlockDescriptor*, EASY_UNIQUE_DESC(__LINE__), ::profiler::registerDescription(::profiler::extract_enable_flag(__VA_ARGS__),\ + EASY_UNIQUE_LINE_ID, EASY_COMPILETIME_NAME(name), __FILE__, __LINE__, ::profiler::BLOCK_TYPE_BLOCK, ::profiler::extract_color(__VA_ARGS__),\ + ::std::is_base_of<::profiler::ForceConstStr, decltype(name)>::value));\ + ::profiler::Block EASY_UNIQUE_BLOCK(__LINE__)(EASY_UNIQUE_DESC(__LINE__), EASY_RUNTIME_NAME(name));\ + EASY_FRAME_COUNTER\ + ::profiler::beginBlock(EASY_UNIQUE_BLOCK(__LINE__)); // this is to avoid compiler warning about unused variable + +/** Macro combining EASY_FUNCTION with EASY_FRAME_COUNTER + +\ingroup profiler +*/ +# define EASY_FRAME_FUNCTION(...)\ + EASY_LOCAL_STATIC_PTR(const ::profiler::BaseBlockDescriptor*, EASY_UNIQUE_DESC(__LINE__), ::profiler::registerDescription(::profiler::extract_enable_flag(__VA_ARGS__),\ + EASY_UNIQUE_LINE_ID, __func__, __FILE__, __LINE__, ::profiler::BLOCK_TYPE_BLOCK, ::profiler::extract_color(__VA_ARGS__), false));\ + ::profiler::Block EASY_UNIQUE_BLOCK(__LINE__)(EASY_UNIQUE_DESC(__LINE__), "");\ + EASY_FRAME_COUNTER\ + ::profiler::beginBlock(EASY_UNIQUE_BLOCK(__LINE__)); // this is to avoid compiler warning about unused variable + +/** Macro combining EASY_END_BLOCK with EASY_END_FRAME_COUNTER + +\ingroup profiler +*/ +# define EASY_END_FRAME \ + EASY_END_BLOCK\ + EASY_END_FRAME_COUNTER + +/** Macro for creating event marker with custom name and color. + +Event marker is a block with zero duration and special type. + +\warning Event marker ends immidiately and calling EASY_END_BLOCK after EASY_EVENT will end previously opened EASY_BLOCK or EASY_FUNCTION. \ingroup profiler @@ -343,6 +445,11 @@ Otherwise, no log messages will be printed. # define EASY_BLOCK(...) # define EASY_FUNCTION(...) # define EASY_END_BLOCK +# define EASY_FRAME_COUNTER +# define EASY_END_FRAME_COUNTER +# define EASY_FRAME(...) +# define EASY_FRAME_FUNCTION(...) +# define EASY_END_FRAME # define EASY_PROFILER_ENABLE # define EASY_PROFILER_DISABLE # define EASY_EVENT(...) @@ -409,6 +516,12 @@ namespace profiler { }; typedef BlockType block_type_t; + enum Duration : uint8_t + { + TICKS = 0, ///< CPU ticks + MICROSECONDS ///< Microseconds + }; + //*********************************************** #pragma pack(push,1) @@ -506,12 +619,32 @@ namespace profiler { //*********************************************** + /** Scoped object used to stop frame timer implicitly. + + EasyProfiler frame counter measures time even if profiler is disabled. + Use this if you want to observe your frame time at run-time to see if + all is going right or/and to find better moment to enable profiling. + + \note It is not binded to Main thread only. + You are free to measure frame time of any thread you want. + + \ingroup profiler + */ + class PROFILER_API FrameCounterGuard EASY_FINAL { + friend ::ProfileManager; + int8_t m_state = 0; + public: + ~FrameCounterGuard(); + }; // END of class FrameCounterGuard. + + //*********************************************** + class PROFILER_API ThreadGuard EASY_FINAL { friend ::ProfileManager; thread_id_t m_id = 0; public: ~ThreadGuard(); - }; + }; // END of class ThreadGuard. ////////////////////////////////////////////////////////////////////// // Core API @@ -548,6 +681,8 @@ namespace profiler { /** Ends last started block. + Use this only if you want to finish block explicitly. + \ingroup profiler */ PROFILER_API void endBlock(); @@ -653,13 +788,66 @@ namespace profiler { */ PROFILER_API const char* versionName(); + /** Returns true if current thread has been marked as Main. + Otherwise, returns false. + */ + PROFILER_API bool isMainThread(); + + /** Begins Frame counter. + + Measures time even if profiler is disabled. + Use this if you want to observe your frame time at run-time to see + if all is going right or/and to find better moment to enable profiling. + + \note All following calls to beginFrame() would have no effect + until endFrame() called or FrameCounter object destroyed. + + \note It is not binded to Main thread only. + You are free to measure frame time of any thread you want. + */ + PROFILER_API void beginFrame(FrameCounterGuard& _frameCounter); + + /** Ends frame counter. + + Use this only if you want to stop frame timer explicitly before it really finished. + */ + PROFILER_API void endFrame(); + + /** Returns last frame duration for current thread. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t this_thread_frameTime(Duration _durationCast); + + /** Returns local max of frame duration for current thread. + + Local max is maximum frame duration since last frameTimeLocalMax() call. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast); + + /** Returns last frame duration for main thread. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t main_thread_frameTime(Duration _durationCast); + + /** Returns local max of frame duration for main thread. + + Local max is maximum frame duration since last frameTimeLocalMax() call. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration _durationCast); + } #else inline const BaseBlockDescriptor* registerDescription(EasyBlockStatus, const char*, const char*, const char*, int, block_type_t, color_t, bool = false) { return reinterpret_cast(0xbad); } inline void endBlock() { } inline void setEnabled(bool) { } - inline bool isEnabled(bool) { return false; } + inline bool isEnabled() { return false; } inline void storeEvent(const BaseBlockDescriptor*, const char*) { } inline void beginBlock(Block&) { } inline uint32_t dumpBlocksToFile(const char*) { return 0; } @@ -679,8 +867,75 @@ namespace profiler { inline uint16_t versionPatch() { return 0; } inline uint32_t version() { return 0; } inline const char* versionName() { return "v0.0.0_disabled"; } + inline bool isMainThread() { return false; } + inline void beginFrame(FrameCounterGuard&) { } + inline void endFrame() { } + inline timestamp_t this_thread_frameTime(Duration) { return 0; } + inline timestamp_t this_thread_frameTimeLocalMax(Duration) { return 0; } + inline timestamp_t main_thread_frameTime(Duration) { return 0; } + inline timestamp_t main_thread_frameTimeLocalMax(Duration) { return 0; } #endif + /** API functions binded to current thread. + + \ingroup profiler + */ + namespace this_thread { + + inline const char* registrate(const char* _name) { + return ::profiler::registerThread(_name); + } + + inline const char* registrate(const char* _name, ThreadGuard& _threadGuard) { + return ::profiler::registerThreadScoped(_name, _threadGuard); + } + + inline void beginFrame(FrameCounterGuard& _frameCounter) { + ::profiler::beginFrame(_frameCounter); + } + + inline void endFrame() { + ::profiler::endFrame(); + } + + inline timestamp_t frameTime(Duration _durationCast) { + return ::profiler::this_thread_frameTime(_durationCast); + } + + inline timestamp_t frameTimeLocalMax(Duration _durationCast) { + return ::profiler::this_thread_frameTimeLocalMax(_durationCast); + } + + inline bool isMain() { + return ::profiler::isMainThread(); + } + + } // END of namespace this_thread. + + /** API functions binded to main thread. + + Could be called from any thread. + + \ingroup profiler + */ + namespace main_thread { + + inline timestamp_t frameTime(Duration _durationCast) { + return ::profiler::main_thread_frameTime(_durationCast); + } + + inline timestamp_t frameTimeLocalMax(Duration _durationCast) { + return ::profiler::main_thread_frameTimeLocalMax(_durationCast); + } + + /** Always returns true. + */ + inline bool isMain() { + return true; + } + + } // END of namespace main_thread. + ////////////////////////////////////////////////////////////////////// } // END of namespace profiler. diff --git a/easy_profiler_core/include/easy/profiler_aux.h b/easy_profiler_core/include/easy/profiler_aux.h index f957480..73ccec7 100644 --- a/easy_profiler_core/include/easy/profiler_aux.h +++ b/easy_profiler_core/include/easy/profiler_aux.h @@ -91,6 +91,7 @@ namespace profiler { # define EASY_TOKEN_JOIN(x, y) x ## y # define EASY_TOKEN_CONCATENATE(x, y) EASY_TOKEN_JOIN(x, y) # define EASY_UNIQUE_BLOCK(x) EASY_TOKEN_CONCATENATE(unique_profiler_mark_name_, x) +# define EASY_UNIQUE_FRAME_COUNTER(x) EASY_TOKEN_CONCATENATE(unique_profiler_frame_mark_name_, x) # define EASY_UNIQUE_DESC(x) EASY_TOKEN_CONCATENATE(unique_profiler_descriptor_, x) #ifdef BUILD_WITH_EASY_PROFILER diff --git a/easy_profiler_core/profile_manager.cpp b/easy_profiler_core/profile_manager.cpp index 12ef0f2..a297cfb 100644 --- a/easy_profiler_core/profile_manager.cpp +++ b/easy_profiler_core/profile_manager.cpp @@ -50,6 +50,7 @@ #include #include +#include #include "profile_manager.h" #include @@ -148,6 +149,41 @@ const uint8_t FORCE_ON_FLAG = profiler::FORCE_ON & ~profiler::ON; #ifdef _WIN32 decltype(LARGE_INTEGER::QuadPart) const CPU_FREQUENCY = ([](){ LARGE_INTEGER freq; QueryPerformanceFrequency(&freq); return freq.QuadPart; })(); +# define TICKS_TO_US(ticks) ticks * 1000000LL / CPU_FREQUENCY +#elif defined(USE_STD_CHRONO) +# define TICKS_TO_US(ticks) ticks / 1000 +#else +int64_t calculate_cpu_frequency() +{ + double g_TicksPerNanoSec; + struct timespec begints, endts; + uint64_t begin = 0, end = 0; + clock_gettime(CLOCK_MONOTONIC, &begints); + begin = getCurrentTime(); + volatile uint64_t i; + for (i = 0; i < 100000000; i++); /* must be CPU intensive */ + end = getCurrentTime(); + clock_gettime(CLOCK_MONOTONIC, &endts); + struct timespec tmpts; + const int NANO_SECONDS_IN_SEC = 1000000000; + tmpts.tv_sec = endts.tv_sec - begints.tv_sec; + tmpts.tv_nsec = endts.tv_nsec - begints.tv_nsec; + if (tmpts.tv_nsec < 0) + { + tmpts.tv_sec--; + tmpts.tv_nsec += NANO_SECONDS_IN_SEC; + } + + uint64_t nsecElapsed = tmpts.tv_sec * 1000000000LL + tmpts.tv_nsec; + g_TicksPerNanoSec = (double)(end - begin) / (double)nsecElapsed; + + int64_t cpu_frequency = int(g_TicksPerNanoSec * 1000000); + + return cpu_frequency; +} + +static std::atomic CPU_FREQUENCY = ATOMIC_VAR_INIT(1); +# define TICKS_TO_US(ticks) ticks * 1000 / CPU_FREQUENCY.load(std::memory_order_acquire) #endif extern const profiler::color_t EASY_COLOR_INTERNAL_EVENT = 0xffffffff; // profiler::colors::White @@ -157,8 +193,10 @@ const profiler::color_t EASY_COLOR_END = 0xfff44336; // profiler::colors::Red ////////////////////////////////////////////////////////////////////////// -EASY_THREAD_LOCAL static ::ThreadStorage* THREAD_STORAGE = nullptr; -EASY_THREAD_LOCAL static int32_t THREAD_STACK_SIZE = 0; +EASY_THREAD_LOCAL static ::ThreadStorage* THIS_THREAD = nullptr; +EASY_THREAD_LOCAL static int32_t THIS_THREAD_STACK_SIZE = 0; +EASY_THREAD_LOCAL static profiler::timestamp_t THIS_THREAD_FRAME_T = 0ULL; +EASY_THREAD_LOCAL static bool THIS_THREAD_IS_MAIN = false; ////////////////////////////////////////////////////////////////////////// @@ -187,6 +225,9 @@ EASY_THREAD_LOCAL static int32_t THREAD_STACK_SIZE = 0; __FILE__, __LINE__, ::profiler::BLOCK_TYPE_EVENT, ::profiler::extract_color(__VA_ARGS__)));\ storeBlockForce2(ts, EASY_UNIQUE_DESC(__LINE__), EASY_RUNTIME_NAME(name), timestamp) #else +# ifndef EASY_PROFILER_API_DISABLED +# define EASY_PROFILER_API_DISABLED +# endif # define EASY_EVENT_RES(res, name, ...) # define EASY_FORCE_EVENT(timestamp, name, ...) # define EASY_FORCE_EVENT2(timestamp, name, ...) @@ -292,6 +333,64 @@ extern "C" { { return MANAGER.isListening(); } + + PROFILER_API bool isMainThread() + { + return THIS_THREAD_IS_MAIN; + } + + PROFILER_API void beginFrame(FrameCounterGuard& _frameCounter) + { + MANAGER.beginFrame(_frameCounter); + } + + PROFILER_API void endFrame() + { + MANAGER.endFrame(); + } + + PROFILER_API timestamp_t this_thread_frameTime(Duration _durationCast) + { + assert(THIS_THREAD != nullptr); + if (_durationCast == profiler::TICKS) + return THIS_THREAD->frameTime.current; + return TICKS_TO_US(THIS_THREAD->frameTime.current); + } + + PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast) + { + assert(THIS_THREAD != nullptr); + + THIS_THREAD->frameTime.reset = true; + + if (_durationCast == profiler::TICKS) + return THIS_THREAD->frameTime.maximum; + return TICKS_TO_US(THIS_THREAD->frameTime.maximum); + } + + PROFILER_API timestamp_t main_thread_frameTime(Duration _durationCast) + { + const auto ticks = THIS_THREAD_IS_MAIN ? THIS_THREAD->frameTime.current : MANAGER.frameDuration(); + if (_durationCast == profiler::TICKS) + return ticks; + return TICKS_TO_US(ticks); + } + + PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration _durationCast) + { + if (THIS_THREAD_IS_MAIN) + { + THIS_THREAD->frameTime.reset = true; + if (_durationCast == profiler::TICKS) + return THIS_THREAD->frameTime.maximum; + return TICKS_TO_US(THIS_THREAD->frameTime.maximum); + } + + if (_durationCast == profiler::TICKS) + return MANAGER.maxFrameDuration(); + return TICKS_TO_US(MANAGER.maxFrameDuration()); + } + #else PROFILER_API const BaseBlockDescriptor* registerDescription(EasyBlockStatus, const char*, const char*, const char*, int, block_type_t, color_t, bool) { return reinterpret_cast(0xbad); } PROFILER_API void endBlock() { } @@ -299,6 +398,8 @@ extern "C" { PROFILER_API bool isEnabled() { return false; } PROFILER_API void storeEvent(const BaseBlockDescriptor*, const char*) { } PROFILER_API void beginBlock(Block&) { } + PROFILER_API void beginFrame(FrameCounter&) { } + PROFILER_API void endFrame() { } PROFILER_API uint32_t dumpBlocksToFile(const char*) { return 0; } PROFILER_API const char* registerThreadScoped(const char*, ThreadGuard&) { return ""; } PROFILER_API const char* registerThread(const char*) { return ""; } @@ -311,6 +412,12 @@ extern "C" { PROFILER_API void startListen(uint16_t) { } PROFILER_API void stopListen() { } PROFILER_API bool isListening() { return false; } + + PROFILER_API bool isMainThread() { return false; } + PROFILER_API timestamp_t this_thread_frameTime(Duration) { return 0; } + PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration) { return 0; } + PROFILER_API timestamp_t main_thread_frameTime(Duration) { return 0; } + PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration) { return 0; } #endif PROFILER_API uint8_t versionMajor() @@ -493,13 +600,27 @@ void ThreadStorage::clearClosed() ThreadGuard::~ThreadGuard() { #ifndef EASY_PROFILER_API_DISABLED - if (m_id != 0 && THREAD_STORAGE != nullptr && THREAD_STORAGE->id == m_id) + if (m_id != 0 && THIS_THREAD != nullptr && THIS_THREAD->id == m_id) { bool isMarked = false; EASY_EVENT_RES(isMarked, "ThreadFinished", EASY_COLOR_THREAD_END, ::profiler::FORCE_ON); - THREAD_STORAGE->frame.store(false, std::memory_order_release); - THREAD_STORAGE->expired.store(isMarked ? 2 : 1, std::memory_order_release); - THREAD_STORAGE = nullptr; + THIS_THREAD->frame.store(false, std::memory_order_release); + THIS_THREAD->expired.store(isMarked ? 2 : 1, std::memory_order_release); + THIS_THREAD = nullptr; + } +#endif +} + +////////////////////////////////////////////////////////////////////////// + +FrameCounterGuard::~FrameCounterGuard() +{ +#ifndef EASY_PROFILER_API_DISABLED + if (m_state & 2) + { + if (m_state & 1) + MANAGER.endFrame(); + THIS_THREAD->frameCounters.pop_back(); } #endif } @@ -524,6 +645,11 @@ ProfileManager::ProfileManager() : #if !defined(EASY_PROFILER_API_DISABLED) && EASY_OPTION_START_LISTEN_ON_STARTUP != 0 startListen(profiler::DEFAULT_PORT); #endif + +#if !defined(EASY_PROFILER_API_DISABLED) && !defined(_WIN32) && !defined(USE_STD_CHRONO) + const int64_t cpu_frequency = calculate_cpu_frequency(); + CPU_FREQUENCY.store(cpu_frequency, std::memory_order_release); +#endif } ProfileManager::~ProfileManager() @@ -633,16 +759,16 @@ bool ProfileManager::storeBlock(const profiler::BaseBlockDescriptor* _desc, cons if (state == EASY_PROF_DUMP) { - if (THREAD_STORAGE == nullptr || THREAD_STORAGE->blocks.openedList.empty()) + if (THIS_THREAD == nullptr || THIS_THREAD->blocks.openedList.empty()) return false; } - else if (THREAD_STORAGE == nullptr) + else if (THIS_THREAD == nullptr) { - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + THIS_THREAD = &threadStorage(getCurrentThreadId()); } #if EASY_ENABLE_BLOCK_STATUS != 0 - if (!THREAD_STORAGE->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) + if (!THIS_THREAD->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) return false; #endif @@ -650,7 +776,7 @@ bool ProfileManager::storeBlock(const profiler::BaseBlockDescriptor* _desc, cons b.start(); b.m_end = b.m_begin; - THREAD_STORAGE->storeBlock(b); + THIS_THREAD->storeBlock(b); return true; } @@ -662,11 +788,11 @@ void ProfileManager::storeBlockForce(const profiler::BaseBlockDescriptor* _desc, if (!(_desc->m_status & profiler::ON)) return; - if (THREAD_STORAGE == nullptr) - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + if (THIS_THREAD == nullptr) + THIS_THREAD = &threadStorage(getCurrentThreadId()); #if EASY_ENABLE_BLOCK_STATUS != 0 - if (!THREAD_STORAGE->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) + if (!THIS_THREAD->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) return; #endif @@ -675,7 +801,7 @@ void ProfileManager::storeBlockForce(const profiler::BaseBlockDescriptor* _desc, b.m_end = b.m_begin; _timestamp = b.m_begin; - THREAD_STORAGE->storeBlock(b); + THIS_THREAD->storeBlock(b); } void ProfileManager::storeBlockForce2(const profiler::BaseBlockDescriptor* _desc, const char* _runtimeName, ::profiler::timestamp_t _timestamp) @@ -683,18 +809,18 @@ void ProfileManager::storeBlockForce2(const profiler::BaseBlockDescriptor* _desc if (!(_desc->m_status & profiler::ON)) return; - if (THREAD_STORAGE == nullptr) - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + if (THIS_THREAD == nullptr) + THIS_THREAD = &threadStorage(getCurrentThreadId()); #if EASY_ENABLE_BLOCK_STATUS != 0 - if (!THREAD_STORAGE->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) + if (!THIS_THREAD->allowChildren && !(_desc->m_status & FORCE_ON_FLAG)) return; #endif profiler::Block b(_desc, _runtimeName); b.m_end = b.m_begin = _timestamp; - THREAD_STORAGE->storeBlock(b); + THIS_THREAD->storeBlock(b); } void ProfileManager::storeBlockForce2(ThreadStorage& _registeredThread, const profiler::BaseBlockDescriptor* _desc, const char* _runtimeName, ::profiler::timestamp_t _timestamp) @@ -708,38 +834,38 @@ void ProfileManager::storeBlockForce2(ThreadStorage& _registeredThread, const pr void ProfileManager::beginBlock(Block& _block) { - if (++THREAD_STACK_SIZE > 1) + if (++THIS_THREAD_STACK_SIZE > 1) return; const auto state = m_profilerStatus.load(std::memory_order_acquire); if (state == EASY_PROF_DISABLED) return; - THREAD_STACK_SIZE = 0; + THIS_THREAD_STACK_SIZE = 0; bool empty = true; if (state == EASY_PROF_DUMP) { - if (THREAD_STORAGE == nullptr || THREAD_STORAGE->blocks.openedList.empty()) + if (THIS_THREAD == nullptr || THIS_THREAD->blocks.openedList.empty()) return; empty = false; } - else if (THREAD_STORAGE == nullptr) + else if (THIS_THREAD == nullptr) { - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + THIS_THREAD = &threadStorage(getCurrentThreadId()); } else { - empty = THREAD_STORAGE->blocks.openedList.empty(); + empty = THIS_THREAD->blocks.openedList.empty(); } #if EASY_ENABLE_BLOCK_STATUS != 0 - if (THREAD_STORAGE->allowChildren) + if (THIS_THREAD->allowChildren) { #endif if (_block.m_status & profiler::ON) _block.start(); #if EASY_ENABLE_BLOCK_STATUS != 0 - THREAD_STORAGE->allowChildren = !(_block.m_status & profiler::OFF_RECURSIVE); + THIS_THREAD->allowChildren = !(_block.m_status & profiler::OFF_RECURSIVE); } else if (_block.m_status & FORCE_ON_FLAG) { @@ -753,8 +879,8 @@ void ProfileManager::beginBlock(Block& _block) #endif if (empty) - THREAD_STORAGE->frame.store(true, std::memory_order_release); - THREAD_STORAGE->blocks.openedList.emplace(_block); + THIS_THREAD->frame.store(true, std::memory_order_release); + THIS_THREAD->blocks.openedList.emplace(_block); } void ProfileManager::beginContextSwitch(profiler::thread_id_t _thread_id, profiler::timestamp_t _time, profiler::thread_id_t _target_thread_id, const char* _target_process, bool _lockSpin) @@ -770,32 +896,32 @@ void ProfileManager::beginContextSwitch(profiler::thread_id_t _thread_id, profil void ProfileManager::endBlock() { - if (--THREAD_STACK_SIZE > 0 || m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_DISABLED) + if (--THIS_THREAD_STACK_SIZE > 0 || m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_DISABLED) return; - THREAD_STACK_SIZE = 0; - if (THREAD_STORAGE == nullptr || THREAD_STORAGE->blocks.openedList.empty()) + THIS_THREAD_STACK_SIZE = 0; + if (THIS_THREAD == nullptr || THIS_THREAD->blocks.openedList.empty()) return; - Block& lastBlock = THREAD_STORAGE->blocks.openedList.top(); + Block& lastBlock = THIS_THREAD->blocks.openedList.top(); if (lastBlock.m_status & profiler::ON) { if (!lastBlock.finished()) lastBlock.finish(); - THREAD_STORAGE->storeBlock(lastBlock); + THIS_THREAD->storeBlock(lastBlock); } else { lastBlock.m_end = lastBlock.m_begin; // this is to restrict endBlock() call inside ~Block() } - THREAD_STORAGE->blocks.openedList.pop(); - const bool empty = THREAD_STORAGE->blocks.openedList.empty(); + THIS_THREAD->blocks.openedList.pop(); + const bool empty = THIS_THREAD->blocks.openedList.empty(); if (empty) - THREAD_STORAGE->frame.store(false, std::memory_order_release); + THIS_THREAD->frame.store(false, std::memory_order_release); #if EASY_ENABLE_BLOCK_STATUS != 0 - THREAD_STORAGE->allowChildren = empty || !(THREAD_STORAGE->blocks.openedList.top().get().m_status & profiler::OFF_RECURSIVE); + THIS_THREAD->allowChildren = empty || !(THIS_THREAD->blocks.openedList.top().get().m_status & profiler::OFF_RECURSIVE); #endif } @@ -821,6 +947,71 @@ void ProfileManager::endContextSwitch(profiler::thread_id_t _thread_id, processi ////////////////////////////////////////////////////////////////////////// +void ProfileManager::beginFrame(profiler::FrameCounterGuard& _frameCounter) +{ + if (THIS_THREAD == nullptr) + THIS_THREAD = &threadStorage(getCurrentThreadId()); + + if (THIS_THREAD->frameCounters.empty()) + { + THIS_THREAD_FRAME_T = getCurrentTime(); + _frameCounter.m_state = 3; // in thread list and started + } + else + { + _frameCounter.m_state = 2; // in thread list, but not started + } + + THIS_THREAD->frameCounters.emplace_back(_frameCounter); +} + +void ProfileManager::endFrame() +{ + assert(THIS_THREAD != nullptr && !THIS_THREAD->frameCounters.empty()); + + profiler::FrameCounterGuard& frameCounter = THIS_THREAD->frameCounters.back(); + if (frameCounter.m_state & 1) + { + const profiler::timestamp_t duration = getCurrentTime() - THIS_THREAD_FRAME_T; + + frameCounter.m_state = 2; // stayed in thread list, but already finished + + if (THIS_THREAD->frameTime.reset) { + THIS_THREAD->frameTime.reset = false; + THIS_THREAD->frameTime.maximum = 0; + } + + THIS_THREAD->frameTime.current = duration; + if (duration > THIS_THREAD->frameTime.maximum) + THIS_THREAD->frameTime.maximum = duration; + + if (THIS_THREAD_IS_MAIN) + { + auto maxDuration = m_frameMax.load(std::memory_order_acquire); + if (m_frameReset.exchange(false, std::memory_order_release)) + maxDuration = 0; + + if (duration > maxDuration) + m_frameMax.store(duration, std::memory_order_release); + m_frameCurr.store(duration, std::memory_order_release); + } + } +} + +profiler::timestamp_t ProfileManager::maxFrameDuration() +{ + auto duration = m_frameMax.load(std::memory_order_acquire); + m_frameReset.store(true, std::memory_order_release); + return duration; +} + +profiler::timestamp_t ProfileManager::frameDuration() const +{ + return m_frameCurr.load(std::memory_order_acquire); +} + +////////////////////////////////////////////////////////////////////////// + void ProfileManager::enableEventTracer() { #ifdef _WIN32 @@ -1054,32 +1245,11 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo #if !defined(USE_STD_CHRONO) EASY_LOGMSG("Calculating CPU frequency\n"); - double g_TicksPerNanoSec; - struct timespec begints, endts; - uint64_t begin = 0, end = 0; - clock_gettime(CLOCK_MONOTONIC, &begints); - begin = getCurrentTime(); - volatile uint64_t i; - for (i = 0; i < 100000000; i++); /* must be CPU intensive */ - end = getCurrentTime(); - clock_gettime(CLOCK_MONOTONIC, &endts); - struct timespec tmpts; - const int NANO_SECONDS_IN_SEC = 1000000000; - tmpts.tv_sec = endts.tv_sec - begints.tv_sec; - tmpts.tv_nsec = endts.tv_nsec - begints.tv_nsec; - if (tmpts.tv_nsec < 0) { - tmpts.tv_sec--; - tmpts.tv_nsec += NANO_SECONDS_IN_SEC; - } + const int64_t cpu_frequency = calculate_cpu_frequency(); + _outputStream.write(cpu_frequency * 1000LL); + EASY_LOGMSG("Done calculating CPU frequency\n"); - uint64_t nsecElapsed = tmpts.tv_sec * 1000000000LL + tmpts.tv_nsec; - g_TicksPerNanoSec = (double)(end - begin)/(double)nsecElapsed; - - - - int64_t cpu_frequency = int(g_TicksPerNanoSec*1000000); - _outputStream.write(cpu_frequency*1000LL); - EASY_LOGMSG("Done calculating CPU frequency\n"); + CPU_FREQUENCY.store(cpu_frequency, std::memory_order_release); #else _outputStream.write(0LL); #endif @@ -1180,31 +1350,33 @@ uint32_t ProfileManager::dumpBlocksToFile(const char* _filename) const char* ProfileManager::registerThread(const char* name, ThreadGuard& threadGuard) { - if (THREAD_STORAGE == nullptr) - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + if (THIS_THREAD == nullptr) + THIS_THREAD = &threadStorage(getCurrentThreadId()); - THREAD_STORAGE->guarded = true; - if (!THREAD_STORAGE->named) { - THREAD_STORAGE->named = true; - THREAD_STORAGE->name = name; + THIS_THREAD->guarded = true; + if (!THIS_THREAD->named) { + THIS_THREAD->named = true; + THIS_THREAD->name = name; + THIS_THREAD_IS_MAIN = !strncmp(name, "Main", 4); } - threadGuard.m_id = THREAD_STORAGE->id; + threadGuard.m_id = THIS_THREAD->id; - return THREAD_STORAGE->name.c_str(); + return THIS_THREAD->name.c_str(); } const char* ProfileManager::registerThread(const char* name) { - if (THREAD_STORAGE == nullptr) - THREAD_STORAGE = &threadStorage(getCurrentThreadId()); + if (THIS_THREAD == nullptr) + THIS_THREAD = &threadStorage(getCurrentThreadId()); - if (!THREAD_STORAGE->named) { - THREAD_STORAGE->named = true; - THREAD_STORAGE->name = name; + if (!THIS_THREAD->named) { + THIS_THREAD->named = true; + THIS_THREAD->name = name; + THIS_THREAD_IS_MAIN = !strncmp(name, "Main", 4); } - return THREAD_STORAGE->name.c_str(); + return THIS_THREAD->name.c_str(); } void ProfileManager::setBlockStatus(block_id_t _id, EasyBlockStatus _status) @@ -1278,8 +1450,8 @@ void ProfileManager::listen(uint16_t _port) #else false; #endif - profiler::net::EasyProfilerStatus connectionReply(m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_ENABLED, m_isEventTracingEnabled.load(std::memory_order_acquire), wasLowPriorityET); - bytes = socket.send(&connectionReply, sizeof(connectionReply)); + const profiler::net::EasyProfilerStatus connectionReply(m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_ENABLED, m_isEventTracingEnabled.load(std::memory_order_acquire), wasLowPriorityET); + bytes = socket.send(&connectionReply, sizeof(profiler::net::EasyProfilerStatus)); hasConnect = bytes > 0; } @@ -1308,6 +1480,15 @@ void ProfileManager::listen(uint16_t _port) break; } + case profiler::net::MESSAGE_TYPE_REQUEST_MAIN_FRAME_LOCAL_MAX_US: + { + const profiler::timestamp_t duration = TICKS_TO_US(MANAGER.maxFrameDuration()); + const profiler::net::TimestampMessage reply(profiler::net::MESSAGE_TYPE_REPLY_MAIN_FRAME_LOCAL_MAX_US, duration); + bytes = socket.send(&reply, sizeof(profiler::net::TimestampMessage)); + hasConnect = bytes > 0; + break; + } + case profiler::net::MESSAGE_TYPE_REQUEST_START_CAPTURE: { EASY_LOGMSG("receive REQUEST_START_CAPTURE\n"); diff --git a/easy_profiler_core/profile_manager.h b/easy_profiler_core/profile_manager.h index 106df50..55b283e 100644 --- a/easy_profiler_core/profile_manager.h +++ b/easy_profiler_core/profile_manager.h @@ -320,13 +320,19 @@ struct BlocksList } }; - struct ThreadStorage { BlocksList, SIZEOF_CSWITCH * (uint16_t)128U> blocks; BlocksList sync; + std::vector > frameCounters; std::string name; + struct { + profiler::timestamp_t maximum = 0; + profiler::timestamp_t current = 0; + bool reset = false; + } frameTime; + #ifndef _WIN32 const pthread_t pthread_id; #endif @@ -379,12 +385,15 @@ class ProfileManager uint64_t m_usedMemorySize; profiler::timestamp_t m_beginTime; profiler::timestamp_t m_endTime; + std::atomic m_frameMax; + std::atomic m_frameCurr; profiler::spin_lock m_spin; profiler::spin_lock m_storedSpin; profiler::spin_lock m_dumpSpin; std::atomic m_profilerStatus; std::atomic_bool m_isEventTracingEnabled; std::atomic_bool m_isAlreadyListening; + std::atomic_bool m_frameReset; std::string m_csInfoFilename = "/tmp/cs_profiling_info.log"; @@ -413,6 +422,10 @@ public: bool storeBlock(const profiler::BaseBlockDescriptor* _desc, const char* _runtimeName); void beginBlock(profiler::Block& _block); void endBlock(); + void beginFrame(profiler::FrameCounterGuard& _frameCounter); + void endFrame(); + profiler::timestamp_t maxFrameDuration(); + profiler::timestamp_t frameDuration() const; void setEnabled(bool isEnable); bool isEnabled() const; void setEventTracingEnabled(bool _isEnable); diff --git a/sample/main.cpp b/sample/main.cpp index 152285e..7629d15 100644 --- a/sample/main.cpp +++ b/sample/main.cpp @@ -19,7 +19,7 @@ int MODELLING_STEPS = 1500; int RENDER_STEPS = 1500; int RESOURCE_LOADING_COUNT = 50; -#define SAMPLE_NETWORK_TEST +//#define SAMPLE_NETWORK_TEST void localSleep(int magic=200000) { @@ -158,7 +158,10 @@ void modellingThread(){ #else for (int i = 0; i < MODELLING_STEPS; i++){ #endif + EASY_FRAME_COUNTER; modellingStep(); + EASY_END_FRAME_COUNTER; + localSleep(1200000); //std::this_thread::sleep_for(std::chrono::milliseconds(20)); } @@ -223,11 +226,25 @@ int main(int argc, char* argv[]) cv_m.unlock(); cv.notify_all(); + std::atomic_bool stop = ATOMIC_VAR_INIT(false); + auto ttt = std::thread([&stop]() + { + while (!stop.load(std::memory_order_acquire)) + { + std::cout << "Frame time: " << profiler::main_thread::frameTimeLocalMax(profiler::MICROSECONDS) << " us\n"; + std::this_thread::sleep_for(std::chrono::seconds(1)); + } + }); + modellingThread(); + stop.store(true, std::memory_order_release); + for(auto& t : threads) t.join(); + ttt.join(); + auto end = std::chrono::system_clock::now(); auto elapsed = std::chrono::duration_cast(end - start);