From 8b7a68266caf4a6837658db43725215e19c4cf03 Mon Sep 17 00:00:00 2001 From: Victor Zarubkin Date: Mon, 3 Apr 2017 23:08:52 +0300 Subject: [PATCH] (Core) Added new API functions for requesting local-average frame duration (like local-max) --- easy_profiler_core/include/easy/easy_net.h | 9 +- easy_profiler_core/include/easy/profiler.h | 26 +++++ easy_profiler_core/profile_manager.cpp | 106 ++++++++++++++++++--- easy_profiler_core/profile_manager.h | 9 +- 4 files changed, 129 insertions(+), 21 deletions(-) diff --git a/easy_profiler_core/include/easy/easy_net.h b/easy_profiler_core/include/easy/easy_net.h index a04f9d2..ad8c382 100644 --- a/easy_profiler_core/include/easy/easy_net.h +++ b/easy_profiler_core/include/easy/easy_net.h @@ -75,8 +75,8 @@ enum MessageType : uint8_t MESSAGE_TYPE_EVENT_TRACING_PRIORITY, MESSAGE_TYPE_CHECK_CONNECTION, - MESSAGE_TYPE_REQUEST_MAIN_FRAME_LOCAL_MAX_US, - MESSAGE_TYPE_REPLY_MAIN_FRAME_LOCAL_MAX_US, + MESSAGE_TYPE_REQUEST_MAIN_FRAME_TIME_MAX_AVG_US, + MESSAGE_TYPE_REPLY_MAIN_FRAME_TIME_MAX_AVG_US, }; struct Message @@ -134,8 +134,9 @@ struct BoolMessage : public Message { }; struct TimestampMessage : public Message { - uint64_t timestamp = 0; - TimestampMessage(MessageType _t, uint64_t _timestamp) : Message(_t), timestamp(_timestamp) { } + uint32_t maxValue = 0; + uint32_t avgValue = 0; + TimestampMessage(MessageType _t, uint32_t _maxValue, uint32_t _avgValue) : Message(_t), maxValue(_maxValue), avgValue(_avgValue) { } TimestampMessage() = default; }; diff --git a/easy_profiler_core/include/easy/profiler.h b/easy_profiler_core/include/easy/profiler.h index 5c524cf..778ba5f 100644 --- a/easy_profiler_core/include/easy/profiler.h +++ b/easy_profiler_core/include/easy/profiler.h @@ -680,6 +680,14 @@ namespace profiler { */ PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS); + /** Returns local average of frame duration for current thread. + + Local average is average frame duration since last frameTimeLocalAvg() call. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t this_thread_frameTimeLocalAvg(Duration _durationCast = ::profiler::MICROSECONDS); + /** Returns last frame duration for main thread. \param _durationCast desired duration units (could be cpu-ticks or microseconds) @@ -694,6 +702,14 @@ namespace profiler { */ PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration _durationCast = ::profiler::MICROSECONDS); + /** Returns local average of frame duration for main thread. + + Local average is average frame duration since last frameTimeLocalAvg() call. + + \param _durationCast desired duration units (could be cpu-ticks or microseconds) + */ + PROFILER_API timestamp_t main_thread_frameTimeLocalAvg(Duration _durationCast = ::profiler::MICROSECONDS); + } #else inline const BaseBlockDescriptor* registerDescription(EasyBlockStatus, const char*, const char*, const char*, int, block_type_t, color_t, bool = false) @@ -723,8 +739,10 @@ namespace profiler { inline bool isMainThread() { return false; } 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 this_thread_frameTimeLocalAvg(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; } + inline timestamp_t main_thread_frameTimeLocalAvg(Duration = ::profiler::MICROSECONDS) { return 0; } #endif /** API functions binded to current thread. @@ -749,6 +767,10 @@ namespace profiler { return ::profiler::this_thread_frameTimeLocalMax(_durationCast); } + inline timestamp_t frameTimeLocalAvg(Duration _durationCast = ::profiler::MICROSECONDS) { + return ::profiler::this_thread_frameTimeLocalAvg(_durationCast); + } + inline bool isMain() { return ::profiler::isMainThread(); } @@ -771,6 +793,10 @@ namespace profiler { return ::profiler::main_thread_frameTimeLocalMax(_durationCast); } + inline timestamp_t frameTimeLocalAvg(Duration _durationCast = ::profiler::MICROSECONDS) { + return ::profiler::main_thread_frameTimeLocalAvg(_durationCast); + } + /** Always returns true. */ inline bool isMain() { diff --git a/easy_profiler_core/profile_manager.cpp b/easy_profiler_core/profile_manager.cpp index 2d9777f..b9ac99a 100644 --- a/easy_profiler_core/profile_manager.cpp +++ b/easy_profiler_core/profile_manager.cpp @@ -201,7 +201,10 @@ 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; +EASY_THREAD_LOCAL static profiler::timestamp_t THIS_THREAD_FRAME_T_ACC = 0ULL; +EASY_THREAD_LOCAL static uint32_t THIS_THREAD_N_FRAMES = 0; +EASY_THREAD_LOCAL static bool THIS_THREAD_FRAME_T_RESET_MAX = false; +EASY_THREAD_LOCAL static bool THIS_THREAD_FRAME_T_RESET_AVG = false; ////////////////////////////////////////////////////////////////////////// @@ -353,15 +356,24 @@ extern "C" { PROFILER_API timestamp_t this_thread_frameTimeLocalMax(Duration _durationCast) { - THIS_THREAD_FRAME_T_RESET = true; + THIS_THREAD_FRAME_T_RESET_MAX = true; if (_durationCast == profiler::TICKS) return THIS_THREAD_FRAME_T_MAX; return TICKS_TO_US(THIS_THREAD_FRAME_T_MAX); } + PROFILER_API timestamp_t this_thread_frameTimeLocalAvg(Duration _durationCast) + { + THIS_THREAD_FRAME_T_RESET_AVG = true; + auto avgDuration = THIS_THREAD_N_FRAMES > 0 ? THIS_THREAD_FRAME_T_ACC / THIS_THREAD_N_FRAMES : 0; + if (_durationCast == profiler::TICKS) + return avgDuration; + return TICKS_TO_US(avgDuration); + } + PROFILER_API timestamp_t main_thread_frameTime(Duration _durationCast) { - const auto ticks = THIS_THREAD_IS_MAIN ? THIS_THREAD_FRAME_T_CUR : MANAGER.frameDuration(); + const auto ticks = THIS_THREAD_IS_MAIN ? THIS_THREAD_FRAME_T_CUR : MANAGER.curFrameDuration(); if (_durationCast == profiler::TICKS) return ticks; return TICKS_TO_US(ticks); @@ -371,7 +383,7 @@ extern "C" { { if (THIS_THREAD_IS_MAIN) { - THIS_THREAD_FRAME_T_RESET = true; + THIS_THREAD_FRAME_T_RESET_MAX = true; if (_durationCast == profiler::TICKS) return THIS_THREAD_FRAME_T_MAX; return TICKS_TO_US(THIS_THREAD_FRAME_T_MAX); @@ -382,6 +394,22 @@ extern "C" { return TICKS_TO_US(MANAGER.maxFrameDuration()); } + PROFILER_API timestamp_t main_thread_frameTimeLocalAvg(Duration _durationCast) + { + if (THIS_THREAD_IS_MAIN) + { + THIS_THREAD_FRAME_T_RESET_AVG = true; + auto avgDuration = THIS_THREAD_N_FRAMES > 0 ? THIS_THREAD_FRAME_T_ACC / THIS_THREAD_N_FRAMES : 0; + if (_durationCast == profiler::TICKS) + return avgDuration; + return TICKS_TO_US(avgDuration); + } + + if (_durationCast == profiler::TICKS) + return MANAGER.avgFrameDuration(); + return TICKS_TO_US(MANAGER.avgFrameDuration()); + } + #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() { } @@ -405,8 +433,10 @@ extern "C" { 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 this_thread_frameTimeLocalAvg(Duration) { return 0; } PROFILER_API timestamp_t main_thread_frameTime(Duration) { return 0; } PROFILER_API timestamp_t main_thread_frameTimeLocalMax(Duration) { return 0; } + PROFILER_API timestamp_t main_thread_frameTimeLocalAvg(Duration) { return 0; } #endif PROFILER_API uint8_t versionMajor() @@ -617,6 +647,12 @@ ProfileManager::ProfileManager() : m_isAlreadyListening = ATOMIC_VAR_INIT(false); m_stopListen = ATOMIC_VAR_INIT(false); + m_frameMax = ATOMIC_VAR_INIT(0); + m_frameAvg = ATOMIC_VAR_INIT(0); + m_frameCur = ATOMIC_VAR_INIT(0); + m_frameMaxReset = ATOMIC_VAR_INIT(false); + m_frameAvgReset = ATOMIC_VAR_INIT(false); + #if !defined(EASY_PROFILER_API_DISABLED) && EASY_OPTION_START_LISTEN_ON_STARTUP != 0 startListen(profiler::DEFAULT_PORT); #endif @@ -962,9 +998,9 @@ void ProfileManager::endFrame() THIS_THREAD_FRAME = false; - if (THIS_THREAD_FRAME_T_RESET) + if (THIS_THREAD_FRAME_T_RESET_MAX) { - THIS_THREAD_FRAME_T_RESET = false; + THIS_THREAD_FRAME_T_RESET_MAX = false; THIS_THREAD_FRAME_T_MAX = 0; } @@ -972,28 +1008,68 @@ void ProfileManager::endFrame() if (duration > THIS_THREAD_FRAME_T_MAX) THIS_THREAD_FRAME_T_MAX = duration; + if (THIS_THREAD_N_FRAMES > 10000) + THIS_THREAD_FRAME_T_RESET_AVG = true; + if (THIS_THREAD_IS_MAIN) { + if (m_frameAvgReset.exchange(false, std::memory_order_release) || THIS_THREAD_FRAME_T_RESET_AVG) + { + if (THIS_THREAD_N_FRAMES > 0) + m_frameAvg.store(THIS_THREAD_FRAME_T_ACC / THIS_THREAD_N_FRAMES, std::memory_order_release); + THIS_THREAD_FRAME_T_RESET_AVG = false; + THIS_THREAD_FRAME_T_ACC = duration; + THIS_THREAD_N_FRAMES = 1; + } + else + { + THIS_THREAD_FRAME_T_ACC += duration; + ++THIS_THREAD_N_FRAMES; + m_frameAvg.store(THIS_THREAD_FRAME_T_ACC / THIS_THREAD_N_FRAMES, std::memory_order_release); + } + auto maxDuration = m_frameMax.load(std::memory_order_acquire); - if (m_frameReset.exchange(false, std::memory_order_release)) + if (m_frameMaxReset.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 (m_frameMaxReset.exchange(false, std::memory_order_release)) + maxDuration = 0; + + m_frameCur.store(duration, std::memory_order_release); + } + else if (THIS_THREAD_FRAME_T_RESET_AVG) + { + THIS_THREAD_FRAME_T_RESET_AVG = false; + THIS_THREAD_FRAME_T_ACC = duration; + THIS_THREAD_N_FRAMES = 1; + } + else + { + THIS_THREAD_FRAME_T_ACC += duration; + ++THIS_THREAD_N_FRAMES; } } profiler::timestamp_t ProfileManager::maxFrameDuration() { auto duration = m_frameMax.load(std::memory_order_acquire); - m_frameReset.store(true, std::memory_order_release); + m_frameMaxReset.store(true, std::memory_order_release); return duration; } -profiler::timestamp_t ProfileManager::frameDuration() const +profiler::timestamp_t ProfileManager::avgFrameDuration() { - return m_frameCurr.load(std::memory_order_acquire); + auto duration = m_frameAvg.load(std::memory_order_acquire); + m_frameAvgReset.store(true, std::memory_order_release); + return duration; +} + +profiler::timestamp_t ProfileManager::curFrameDuration() const +{ + return m_frameCur.load(std::memory_order_acquire); } ////////////////////////////////////////////////////////////////////////// @@ -1466,10 +1542,12 @@ void ProfileManager::listen(uint16_t _port) break; } - case profiler::net::MESSAGE_TYPE_REQUEST_MAIN_FRAME_LOCAL_MAX_US: + case profiler::net::MESSAGE_TYPE_REQUEST_MAIN_FRAME_TIME_MAX_AVG_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); + profiler::timestamp_t maxDuration = maxFrameDuration(), avgDuration = avgFrameDuration(); + maxDuration = TICKS_TO_US(maxDuration); + avgDuration = TICKS_TO_US(avgDuration); + const profiler::net::TimestampMessage reply(profiler::net::MESSAGE_TYPE_REPLY_MAIN_FRAME_TIME_MAX_AVG_US, (uint32_t)maxDuration, (uint32_t)avgDuration); bytes = socket.send(&reply, sizeof(profiler::net::TimestampMessage)); hasConnect = bytes > 0; break; diff --git a/easy_profiler_core/profile_manager.h b/easy_profiler_core/profile_manager.h index 94ae00c..2eb176b 100644 --- a/easy_profiler_core/profile_manager.h +++ b/easy_profiler_core/profile_manager.h @@ -379,14 +379,16 @@ class ProfileManager profiler::timestamp_t m_beginTime; profiler::timestamp_t m_endTime; std::atomic m_frameMax; - std::atomic m_frameCurr; + std::atomic m_frameAvg; + std::atomic m_frameCur; 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::atomic_bool m_frameMaxReset; + std::atomic_bool m_frameAvgReset; std::string m_csInfoFilename = "/tmp/cs_profiling_info.log"; @@ -416,7 +418,8 @@ public: void beginBlock(profiler::Block& _block); void endBlock(); profiler::timestamp_t maxFrameDuration(); - profiler::timestamp_t frameDuration() const; + profiler::timestamp_t avgFrameDuration(); + profiler::timestamp_t curFrameDuration() const; void setEnabled(bool isEnable); bool isEnabled() const; void setEventTracingEnabled(bool _isEnable);