From a2b62613a2830fcef894b9f639e03b71633359fb Mon Sep 17 00:00:00 2001 From: Victor Zarubkin Date: Sun, 2 Apr 2017 14:23:11 +0300 Subject: [PATCH] (Core) Frame counter: significantly simplified interface - there is no need to start frame counter explicitly. Top block is frame. --- easy_profiler_core/include/easy/profiler.h | 181 ++------------------- easy_profiler_core/profile_manager.cpp | 142 ++++++++-------- easy_profiler_core/profile_manager.h | 12 +- sample/main.cpp | 8 +- 4 files changed, 83 insertions(+), 260 deletions(-) diff --git a/easy_profiler_core/include/easy/profiler.h b/easy_profiler_core/include/easy/profiler.h index 5f5a86e..5c524cf 100644 --- a/easy_profiler_core/include/easy/profiler.h +++ b/easy_profiler_core/include/easy/profiler.h @@ -161,108 +161,6 @@ int foo() */ # define EASY_END_BLOCK ::profiler::endBlock(); -/** Macro for starting 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. - -\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. @@ -445,11 +343,6 @@ 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(...) @@ -619,26 +512,6 @@ 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; @@ -793,31 +666,11 @@ namespace profiler { */ 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); + PROFILER_API timestamp_t this_thread_frameTime(Duration _durationCast = ::profiler::MICROSECONDS); /** Returns local max of frame duration for current thread. @@ -825,13 +678,13 @@ namespace profiler { \param _durationCast desired duration units (could be cpu-ticks or microseconds) */ - PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast); + PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS); /** 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); + PROFILER_API timestamp_t main_thread_frameTime(Duration _durationCast = ::profiler::MICROSECONDS); /** Returns local max of frame duration for main thread. @@ -839,7 +692,7 @@ namespace profiler { \param _durationCast desired duration units (could be cpu-ticks or microseconds) */ - PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration _durationCast); + PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS); } #else @@ -868,12 +721,10 @@ namespace profiler { 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; } + inline timestamp_t this_thread_frameTime(Duration = ::profiler::MICROSECONDS) { return 0; } + inline timestamp_t this_thread_frameTimeLocalMax(Duration = ::profiler::MICROSECONDS) { return 0; } + inline timestamp_t main_thread_frameTime(Duration = ::profiler::MICROSECONDS) { return 0; } + inline timestamp_t main_thread_frameTimeLocalMax(Duration = ::profiler::MICROSECONDS) { return 0; } #endif /** API functions binded to current thread. @@ -890,19 +741,11 @@ namespace profiler { return ::profiler::registerThreadScoped(_name, _threadGuard); } - inline void beginFrame(FrameCounterGuard& _frameCounter) { - ::profiler::beginFrame(_frameCounter); - } - - inline void endFrame() { - ::profiler::endFrame(); - } - - inline timestamp_t frameTime(Duration _durationCast) { + inline timestamp_t frameTime(Duration _durationCast = ::profiler::MICROSECONDS) { return ::profiler::this_thread_frameTime(_durationCast); } - inline timestamp_t frameTimeLocalMax(Duration _durationCast) { + inline timestamp_t frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS) { return ::profiler::this_thread_frameTimeLocalMax(_durationCast); } @@ -920,11 +763,11 @@ namespace profiler { */ namespace main_thread { - inline timestamp_t frameTime(Duration _durationCast) { + inline timestamp_t frameTime(Duration _durationCast = ::profiler::MICROSECONDS) { return ::profiler::main_thread_frameTime(_durationCast); } - inline timestamp_t frameTimeLocalMax(Duration _durationCast) { + inline timestamp_t frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS) { return ::profiler::main_thread_frameTimeLocalMax(_durationCast); } diff --git a/easy_profiler_core/profile_manager.cpp b/easy_profiler_core/profile_manager.cpp index a297cfb..2d9777f 100644 --- a/easy_profiler_core/profile_manager.cpp +++ b/easy_profiler_core/profile_manager.cpp @@ -196,8 +196,13 @@ const profiler::color_t EASY_COLOR_END = 0xfff44336; // profiler::colors::Red 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_FRAME = false; EASY_THREAD_LOCAL static bool THIS_THREAD_IS_MAIN = false; +EASY_THREAD_LOCAL static profiler::timestamp_t THIS_THREAD_FRAME_T_MAX = 0ULL; +EASY_THREAD_LOCAL static profiler::timestamp_t THIS_THREAD_FRAME_T_CUR = 0ULL; +EASY_THREAD_LOCAL static bool THIS_THREAD_FRAME_T_RESET = false; + ////////////////////////////////////////////////////////////////////////// #ifdef BUILD_WITH_EASY_PROFILER @@ -339,38 +344,24 @@ extern "C" { 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); + return THIS_THREAD_FRAME_T_CUR; + return TICKS_TO_US(THIS_THREAD_FRAME_T_CUR); } PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast) { - assert(THIS_THREAD != nullptr); - - THIS_THREAD->frameTime.reset = true; - + THIS_THREAD_FRAME_T_RESET = true; if (_durationCast == profiler::TICKS) - return THIS_THREAD->frameTime.maximum; - return TICKS_TO_US(THIS_THREAD->frameTime.maximum); + return THIS_THREAD_FRAME_T_MAX; + return TICKS_TO_US(THIS_THREAD_FRAME_T_MAX); } PROFILER_API timestamp_t main_thread_frameTime(Duration _durationCast) { - const auto ticks = THIS_THREAD_IS_MAIN ? THIS_THREAD->frameTime.current : MANAGER.frameDuration(); + const auto ticks = THIS_THREAD_IS_MAIN ? THIS_THREAD_FRAME_T_CUR : MANAGER.frameDuration(); if (_durationCast == profiler::TICKS) return ticks; return TICKS_TO_US(ticks); @@ -380,10 +371,10 @@ extern "C" { { if (THIS_THREAD_IS_MAIN) { - THIS_THREAD->frameTime.reset = true; + THIS_THREAD_FRAME_T_RESET = true; if (_durationCast == profiler::TICKS) - return THIS_THREAD->frameTime.maximum; - return TICKS_TO_US(THIS_THREAD->frameTime.maximum); + return THIS_THREAD_FRAME_T_MAX; + return TICKS_TO_US(THIS_THREAD_FRAME_T_MAX); } if (_durationCast == profiler::TICKS) @@ -398,8 +389,6 @@ 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 ""; } @@ -613,20 +602,6 @@ ThreadGuard::~ThreadGuard() ////////////////////////////////////////////////////////////////////////// -FrameCounterGuard::~FrameCounterGuard() -{ -#ifndef EASY_PROFILER_API_DISABLED - if (m_state & 2) - { - if (m_state & 1) - MANAGER.endFrame(); - THIS_THREAD->frameCounters.pop_back(); - } -#endif -} - -////////////////////////////////////////////////////////////////////////// - ProfileManager::ProfileManager() : #ifdef _WIN32 m_processId(GetProcessId(GetCurrentProcess())) @@ -839,9 +814,11 @@ void ProfileManager::beginBlock(Block& _block) const auto state = m_profilerStatus.load(std::memory_order_acquire); if (state == EASY_PROF_DISABLED) + { + beginFrame(); return; + } - THIS_THREAD_STACK_SIZE = 0; bool empty = true; if (state == EASY_PROF_DUMP) { @@ -858,6 +835,8 @@ void ProfileManager::beginBlock(Block& _block) empty = THIS_THREAD->blocks.openedList.empty(); } + THIS_THREAD_STACK_SIZE = 0; + #if EASY_ENABLE_BLOCK_STATUS != 0 if (THIS_THREAD->allowChildren) { @@ -879,7 +858,11 @@ void ProfileManager::beginBlock(Block& _block) #endif if (empty) + { + beginFrame(); THIS_THREAD->frame.store(true, std::memory_order_release); + } + THIS_THREAD->blocks.openedList.emplace(_block); } @@ -896,9 +879,15 @@ void ProfileManager::beginContextSwitch(profiler::thread_id_t _thread_id, profil void ProfileManager::endBlock() { - if (--THIS_THREAD_STACK_SIZE > 0 || m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_DISABLED) + if (--THIS_THREAD_STACK_SIZE > 0) return; + if (m_profilerStatus.load(std::memory_order_acquire) == EASY_PROF_DISABLED) + { + endFrame(); + return; + } + THIS_THREAD_STACK_SIZE = 0; if (THIS_THREAD == nullptr || THIS_THREAD->blocks.openedList.empty()) return; @@ -918,10 +907,18 @@ void ProfileManager::endBlock() THIS_THREAD->blocks.openedList.pop(); const bool empty = THIS_THREAD->blocks.openedList.empty(); if (empty) + { THIS_THREAD->frame.store(false, std::memory_order_release); - + endFrame(); #if EASY_ENABLE_BLOCK_STATUS != 0 - THIS_THREAD->allowChildren = empty || !(THIS_THREAD->blocks.openedList.top().get().m_status & profiler::OFF_RECURSIVE); + THIS_THREAD->allowChildren = true; + } + else + { + THIS_THREAD->allowChildren = !(THIS_THREAD->blocks.openedList.top().get().m_status & profiler::OFF_RECURSIVE); + } +#else + } #endif } @@ -947,54 +944,43 @@ void ProfileManager::endContextSwitch(profiler::thread_id_t _thread_id, processi ////////////////////////////////////////////////////////////////////////// -void ProfileManager::beginFrame(profiler::FrameCounterGuard& _frameCounter) +void ProfileManager::beginFrame() { - if (THIS_THREAD == nullptr) - THIS_THREAD = &threadStorage(getCurrentThreadId()); - - if (THIS_THREAD->frameCounters.empty()) + if (!THIS_THREAD_FRAME) { THIS_THREAD_FRAME_T = getCurrentTime(); - _frameCounter.m_state = 3; // in thread list and started + THIS_THREAD_FRAME = true; } - 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()); + if (!THIS_THREAD_FRAME) + return; - profiler::FrameCounterGuard& frameCounter = THIS_THREAD->frameCounters.back(); - if (frameCounter.m_state & 1) + const profiler::timestamp_t duration = getCurrentTime() - THIS_THREAD_FRAME_T; + + THIS_THREAD_FRAME = false; + + if (THIS_THREAD_FRAME_T_RESET) { - const profiler::timestamp_t duration = getCurrentTime() - THIS_THREAD_FRAME_T; + THIS_THREAD_FRAME_T_RESET = false; + THIS_THREAD_FRAME_T_MAX = 0; + } - frameCounter.m_state = 2; // stayed in thread list, but already finished + THIS_THREAD_FRAME_T_CUR = duration; + if (duration > THIS_THREAD_FRAME_T_MAX) + THIS_THREAD_FRAME_T_MAX = duration; - if (THIS_THREAD->frameTime.reset) { - THIS_THREAD->frameTime.reset = false; - THIS_THREAD->frameTime.maximum = 0; - } + 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; - 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); - } + if (duration > maxDuration) + m_frameMax.store(duration, std::memory_order_release); + m_frameCurr.store(duration, std::memory_order_release); } } diff --git a/easy_profiler_core/profile_manager.h b/easy_profiler_core/profile_manager.h index 55b283e..94ae00c 100644 --- a/easy_profiler_core/profile_manager.h +++ b/easy_profiler_core/profile_manager.h @@ -324,15 +324,8 @@ 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 @@ -422,8 +415,6 @@ 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); @@ -452,6 +443,9 @@ public: private: + void beginFrame(); + void endFrame(); + void enableEventTracer(); void disableEventTracer(); diff --git a/sample/main.cpp b/sample/main.cpp index 7629d15..8c8f4f1 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,9 +158,9 @@ void modellingThread(){ #else for (int i = 0; i < MODELLING_STEPS; i++){ #endif - EASY_FRAME_COUNTER; + //EASY_FRAME_COUNTER; modellingStep(); - EASY_END_FRAME_COUNTER; + //EASY_END_FRAME_COUNTER; localSleep(1200000); //std::this_thread::sleep_for(std::chrono::milliseconds(20)); @@ -231,7 +231,7 @@ int main(int argc, char* argv[]) { while (!stop.load(std::memory_order_acquire)) { - std::cout << "Frame time: " << profiler::main_thread::frameTimeLocalMax(profiler::MICROSECONDS) << " us\n"; + std::cout << "Frame time: " << profiler::main_thread::frameTimeLocalMax() << " us\n"; std::this_thread::sleep_for(std::chrono::seconds(1)); } });