From c1dd8faa29136b30272e26042d24f079d5ec2b7c Mon Sep 17 00:00:00 2001 From: Richard Harrison Date: Sun, 10 Feb 2019 17:44:45 +0100 Subject: [PATCH] Improved subsystem performance monitoring and overrun detection This is to help diagnose where performance is being used and augments the current performance monitor. The easiest way to active this is to open the performance monitor; however setting the enable property will enable less intrusive logging and overrun detection. Using the GUI performance monitor itself affects the performance when it updates. Properties /sim/performance-monitor/enabled - need to be true to be active (unchanged) /sim/performance-monitor/dump-stats - hierarchical dump to console of all current timing stats for all subsysems /sim/performance-monitor/interval-s - reporting interval (unchanged) /sim/performance-monitor/max-time-per-frame-ms - any subsystem that takes more than this amount of will be logged to the console --- simgear/structure/SGPerfMon.cxx | 12 +- simgear/structure/SGPerfMon.hxx | 2 + simgear/structure/event_mgr.cxx | 20 +-- simgear/structure/event_mgr.hxx | 4 +- simgear/structure/subsystem_mgr.cxx | 182 +++++++++++++++++++++++++--- simgear/structure/subsystem_mgr.hxx | 35 +++++- 6 files changed, 221 insertions(+), 34 deletions(-) diff --git a/simgear/structure/SGPerfMon.cxx b/simgear/structure/SGPerfMon.cxx index ae8191b5..c4d7caed 100644 --- a/simgear/structure/SGPerfMon.cxx +++ b/simgear/structure/SGPerfMon.cxx @@ -51,7 +51,10 @@ SGPerformanceMonitor::bind(void) { _statiticsSubsystems = _root->getChild("subsystems", 0, true); _statisticsFlag = _root->getChild("enabled", 0, true); + _timingDetailsFlag = _root->getChild("dump-stats", 0, true); + _timingDetailsFlag->setBoolValue(false); _statisticsInterval = _root->getChild("interval-s", 0, true); + _maxTimePerFrame_ms = _root->getChild("max-time-per-frame-ms", 0, true); } void @@ -60,6 +63,7 @@ SGPerformanceMonitor::unbind(void) _statiticsSubsystems = 0; _statisticsFlag = 0; _statisticsInterval = 0; + _maxTimePerFrame_ms = 0; } void @@ -83,7 +87,10 @@ SGPerformanceMonitor::update(double dt) else _subSysMgr->setReportTimingCb(this,0); } - + if (_timingDetailsFlag->getBoolValue()) { + _subSysMgr->setReportTimingStats(true); + _timingDetailsFlag->setBoolValue(false); + } if (!_isEnabled) return; @@ -94,6 +101,9 @@ SGPerformanceMonitor::update(double dt) _subSysMgr->reportTiming(); _lastUpdate.stamp(); } + if (_maxTimePerFrame_ms) { + SGSubsystem::maxTimePerFrame_ms = _maxTimePerFrame_ms->getIntValue(); + } } /** Callback hooked into the subsystem manager. */ diff --git a/simgear/structure/SGPerfMon.hxx b/simgear/structure/SGPerfMon.hxx index d7e4ed59..32d642cc 100644 --- a/simgear/structure/SGPerfMon.hxx +++ b/simgear/structure/SGPerfMon.hxx @@ -52,8 +52,10 @@ private: SGSubsystemMgr* _subSysMgr; SGPropertyNode_ptr _root; SGPropertyNode_ptr _statiticsSubsystems; + SGPropertyNode_ptr _timingDetailsFlag; SGPropertyNode_ptr _statisticsFlag; SGPropertyNode_ptr _statisticsInterval; + SGPropertyNode_ptr _maxTimePerFrame_ms; bool _isEnabled; int _count; diff --git a/simgear/structure/event_mgr.cxx b/simgear/structure/event_mgr.cxx index 435b18f8..dead48b7 100644 --- a/simgear/structure/event_mgr.cxx +++ b/simgear/structure/event_mgr.cxx @@ -47,7 +47,7 @@ SGEventMgr::SGEventMgr() : _inited(false), _shutdown(false) { - +_name = "EventMgr"; } SGEventMgr::~SGEventMgr() @@ -86,10 +86,10 @@ void SGEventMgr::shutdown() void SGEventMgr::update(double delta_time_sec) { - _simQueue.update(delta_time_sec); - + _simQueue.update(delta_time_sec, _timerStats); + double rt = _rtProp ? _rtProp->getDoubleValue() : 0; - _rtQueue.update(rt); + _rtQueue.update(rt, _timerStats); } void SGEventMgr::removeTask(const std::string& name) @@ -169,19 +169,23 @@ void SGTimerQueue::clear() _table[i].timer = 0; } } - -void SGTimerQueue::update(double deltaSecs) +int maxTimerQueuePerItem_us = 30; +void SGTimerQueue::update(double deltaSecs, std::map &timingStats) { _now += deltaSecs; - while(_numEntries && nextTime() <= _now) { + + while (_numEntries && nextTime() <= _now) { SGTimer* t = remove(); - if(t->repeat) + if (t->repeat) insert(t, t->interval); // warning: this is not thread safe // but the entire timer queue isn't either + SGTimeStamp timeStamp; + timeStamp.stamp(); t->running = true; t->run(); t->running = false; + timingStats[t->name] += timeStamp.elapsedMSec() / 1000.0; if (!t->repeat) delete t; } diff --git a/simgear/structure/event_mgr.hxx b/simgear/structure/event_mgr.hxx index eaaec7f0..70d516fb 100644 --- a/simgear/structure/event_mgr.hxx +++ b/simgear/structure/event_mgr.hxx @@ -24,9 +24,8 @@ class SGTimerQueue { public: SGTimerQueue(int preSize=1); ~SGTimerQueue(); - void clear(); - void update(double deltaSecs); + void update(double deltaSecs, std::map &timingStats); double now() { return _now; } @@ -78,7 +77,6 @@ public: virtual void update(double delta_time_sec); virtual void unbind(); virtual void shutdown(); - void setRealtimeProperty(SGPropertyNode* node) { _rtProp = node; } /** diff --git a/simgear/structure/subsystem_mgr.cxx b/simgear/structure/subsystem_mgr.cxx index fc29e883..799457f4 100644 --- a/simgear/structure/subsystem_mgr.cxx +++ b/simgear/structure/subsystem_mgr.cxx @@ -45,8 +45,10 @@ using State = SGSubsystem::State; SGSubsystemTimingCb SGSubsystem::reportTimingCb = NULL; void* SGSubsystem::reportTimingUserData = NULL; +bool SGSubsystem::reportTimingStatsRequest = false; +int SGSubsystem::maxTimePerFrame_ms = 7; -SGSubsystem::SGSubsystem () +SGSubsystem::SGSubsystem () : _executionTime(0), _lastExecutionTime(0) { } @@ -202,16 +204,20 @@ std::string SGSubsystem::nameForState(State s) class SGSubsystemGroup::Member { private: - Member (const Member &member); + Member(const Member &member); public: - Member (); + Member(); ~Member (); void update (double delta_time_sec); void reportTiming(void) { if (reportTimingCb) reportTimingCb(reportTimingUserData, name, &timeStat); } - void updateExecutionTime(double time) { timeStat += time;} + void reportTimingStats(TimerStats *_lastValues) { + if (subsystem) + subsystem->reportTimingStats(_lastValues); + } + void updateExecutionTime(double time) { timeStat += time;} SampleStatistic timeStat; std::string name; SGSubsystemRef subsystem; @@ -220,15 +226,18 @@ public: bool collectTimeStats; int exceptionCount; int initTime; + + void mergeTimerStats(SGSubsystem::TimerStats &stats); }; -SGSubsystemGroup::SGSubsystemGroup () : - _fixedUpdateTime(-1.0), - _updateTimeRemainder(0.0), - _initPosition(-1) +SGSubsystemGroup::SGSubsystemGroup(const std::string &name) : + _fixedUpdateTime(-1.0), + _updateTimeRemainder(0.0), + _initPosition(-1) { + _name = name; } SGSubsystemGroup::~SGSubsystemGroup () @@ -377,21 +386,145 @@ SGSubsystemGroup::update (double delta_time_sec) const bool recordTime = (reportTimingCb != nullptr); SGTimeStamp timeStamp; + TimerStats lvTimerStats(_timerStats); + TimerStats overrunItems; + bool overrun = false; + + SGTimeStamp outerTimeStamp; + outerTimeStamp.stamp(); while (loopCount-- > 0) { for (auto member : _members) { - if (recordTime) - timeStamp = SGTimeStamp::now(); + timeStamp.stamp(); + if (member->subsystem->_timerStats.size()) { + member->subsystem->_lastTimerStats.clear(); + member->subsystem->_lastTimerStats.insert(member->subsystem->_timerStats.begin(), member->subsystem->_timerStats.end()); + } member->update(delta_time_sec); // indirect call + if (member->name.size()) + _timerStats[member->name] += timeStamp.elapsedMSec() / 1000.0; if (recordTime && reportTimingCb) { - timeStamp = SGTimeStamp::now() - timeStamp; - member->updateExecutionTime(timeStamp.toUSecs()); + member->updateExecutionTime(timeStamp.elapsedMSec()*1000); + if (timeStamp.elapsedMSec() > SGSubsystemMgr::maxTimePerFrame_ms) { + overrunItems[member->name] += timeStamp.elapsedMSec(); + overrun = true; + } } } } // of multiple update loop + _lastExecutionTime = _executionTime; + _executionTime += outerTimeStamp.elapsedMSec(); + if (overrun) { + for (auto overrunItem : overrunItems) { + SG_LOG(SG_EVENT, SG_ALERT, "Subsystem " + << overrunItem.first + << " total " + << std::setw(6) << std::fixed << std::setprecision(2) << std::right << _timerStats[overrunItem.first] + << "s overrun " + << std::setw(6) << std::fixed << std::setprecision(2) << std::right << overrunItem.second + << "ms"); + auto m = std::find_if(_members.begin(), _members.end(), [overrunItem](const Member* m) { + if (m->name == overrunItem.first) + return true; + return false; + }); + if (m != _members.end()) { + auto member = *m; + if (overrunItems[member->name]) { + TimerStats sst; + member->reportTimingStats(&_lastTimerStats); + //if (lvTimerStats[member->name] != _timerStats[member->name]) { + // SG_LOG(SG_EVENT, SG_ALERT, + // " +" << std::setw(6) << std::left << (_timerStats[member->name] - lvTimerStats[member->name]) + // << " total " << std::setw(6) << std::left << _timerStats[member->name] + // << " " << member->name + // ); + //} + } + } + } + } + + if (reportTimingStatsRequest) { + reportTimingStats(nullptr); + //for (auto member : _members) { + // member->mergeTimerStats(_timerStats); + // if (_timerStats.size()) { + // SG_LOG(SG_EVENT, SG_ALERT, "" << std::setw(6) << std::fixed << std::setprecision(2) << std::left << _timerStats[member->name] + // << ": " << member->name); + // for (auto item : _timerStats) { + // if (item.second > 0) + // SG_LOG(SG_EVENT, SG_ALERT, " " << std::setw(6) << std::left << item.second << " " << item.first); + // } + // } + //} + } + _lastTimerStats.clear(); + _lastTimerStats.insert(_timerStats.begin(), _timerStats.end()); + +} +void SGSubsystem::reportTimingStats(TimerStats *__lastValues) { + std::string _name = ""; + + bool reportDeltas = __lastValues != nullptr; + __lastValues = &_lastTimerStats; + std::ostringstream t; + if (reportDeltas) { + auto deltaT = _executionTime - _lastExecutionTime; + if (deltaT != 0) { + t << name() << "(+" << std::setprecision(2) << std::right << deltaT << "ms)."; + _name = t.str(); + } + } + else { + SG_LOG(SG_EVENT, SG_ALERT, "SubSystem: " << _name << " " << std::setw(6) << std::setprecision(4) << std::right << _executionTime / 1000.0 << "s"); + } + for (auto item : _timerStats) { + std::ostringstream output; + if (item.second > 0) { + if (reportDeltas) + { + auto delta = item.second - (*__lastValues)[item.first]; + if (delta != 0) { + output + << " +" << std::setw(6) << std::setprecision(4) << std::left << (delta * 1000.0) + << _name << item.first + << " total " << std::setw(6) << std::setprecision(4) << std::right << item.second << "s " + ; + } + } + else + output << " " << std::setw(6) << std::setprecision(4) << std::right << item.second << "s " << item.first; + if (output.str().size()) + SG_LOG(SG_EVENT, SG_ALERT, output.str()); + } + } } +void SGSubsystemGroup::reportTimingStats(TimerStats *_lastValues) { + SGSubsystem::reportTimingStats(_lastValues); + + std::string _name = name(); + if (!_name.size()) + _name = typeid(this).name(); + if (_lastValues) { + auto deltaT = _executionTime - _lastExecutionTime; + if (deltaT != 0) { + SG_LOG(SG_EVENT, SG_ALERT, + " +" << std::setw(6) << std::setprecision(4) << std::right << deltaT << "ms " + << name() ); + } + } + else + SG_LOG(SG_EVENT, SG_ALERT, "SubSystemGroup: " << name() << " " << std::setw(6) << std::setprecision(4) << std::right << _executionTime / 1000.0 << "s"); + for (auto member : _members) { + member->reportTimingStats(_lastValues); + } + _lastTimerStats.clear(); + _lastTimerStats.insert(_timerStats.begin(), _timerStats.end()); + +} void SGSubsystemGroup::reportTiming(void) { @@ -609,6 +742,7 @@ auto SGSubsystemGroup::get_member(const string &name, bool create) -> Member* Member* m = new Member; m->name = name; + _timerStats[name] = 0; _members.push_back(m); return _members.back(); } @@ -653,6 +787,11 @@ SGSubsystemGroup::Member::Member (const Member &) SGSubsystemGroup::Member::~Member () { } +void SGSubsystemGroup::Member::mergeTimerStats(SGSubsystem::TimerStats &stats) { + stats.insert(subsystem->_timerStats.begin(), subsystem->_timerStats.end()); + //for (auto ts : subsystem->_timerStats) + // ts.second = 0; +} void SGSubsystemGroup::Member::update (double delta_time_sec) @@ -666,10 +805,15 @@ SGSubsystemGroup::Member::update (double delta_time_sec) return; } + SGTimeStamp oTimer; try { - subsystem->update(elapsed_sec); - elapsed_sec = 0; - } catch (sg_exception& e) { + oTimer.stamp(); + subsystem->update(elapsed_sec); + subsystem->_lastExecutionTime = subsystem->_executionTime; + subsystem->_executionTime += oTimer.elapsedMSec(); + elapsed_sec = 0; + } + catch (sg_exception& e) { SG_LOG(SG_GENERAL, SG_ALERT, "caught exception processing subsystem:" << name << "\nmessage:" << e.getMessage()); @@ -693,7 +837,7 @@ namespace { } // end of anonymous namespace -SGSubsystemMgr::SGSubsystemMgr () : +SGSubsystemMgr::SGSubsystemMgr (const std::string &name) : _groups(MAX_GROUPS) { if (global_defaultSubsystemManager == nullptr) { @@ -710,7 +854,7 @@ SGSubsystemMgr::SGSubsystemMgr () : #endif for (int i = 0; i < MAX_GROUPS; i++) { - auto g = new SGSubsystemGroup; + auto g = new SGSubsystemGroup(name); g->set_manager(this); _groups[i].reset(g); } @@ -746,6 +890,7 @@ SGSubsystemMgr::init () _groups[i]->init(); } + SGSubsystem::InitStatus SGSubsystemMgr::incrementalInit() { @@ -802,9 +947,12 @@ SGSubsystemMgr::unbind () void SGSubsystemMgr::update (double delta_time_sec) { + SGTimeStamp timeStamp; + for (int i = 0; i < MAX_GROUPS; i++) { _groups[i]->update(delta_time_sec); } + reportTimingStatsRequest = false; } void diff --git a/simgear/structure/subsystem_mgr.hxx b/simgear/structure/subsystem_mgr.hxx index 95cd5a46..3a5c4013 100644 --- a/simgear/structure/subsystem_mgr.hxx +++ b/simgear/structure/subsystem_mgr.hxx @@ -130,7 +130,8 @@ typedef void (*SGSubsystemTimingCb)(void* userData, const std::string& name, Sam class SGSubsystem : public SGReferenced { public: - /** + using TimerStats = std::map; + /** * Default constructor. */ SGSubsystem (); @@ -270,6 +271,7 @@ public: */ void reportTiming(void); + virtual void reportTimingStats(TimerStats *_lastValues); /** * Place time stamps at strategic points in the execution of subsystems * update() member functions. Predominantly for debugging purposes. @@ -323,6 +325,20 @@ public: * debug helper, print a state as a string */ static std::string nameForState(State s); + + /** + * gets fine grained stats of time elapsed since last clear + * returns map of ident and time + */ + virtual const TimerStats &getTimerStats() { + return _timerStats; + } + + /** + * clear fine grained stats that are over the specified value. + */ + virtual void resetTimerStats(double val = 0) { } + protected: friend class SGSubsystemMgr; friend class SGSubsystemGroup; @@ -342,9 +358,16 @@ protected: static SGSubsystemTimingCb reportTimingCb; static void* reportTimingUserData; - + static bool reportTimingStatsRequest; + static int maxTimePerFrame_ms; + private: SGSubsystemGroup* _group = nullptr; +protected: + TimerStats _timerStats, _lastTimerStats; + double _executionTime; + double _lastExecutionTime; + }; typedef SGSharedPtr SGSubsystemRef; @@ -355,7 +378,7 @@ typedef SGSharedPtr SGSubsystemRef; class SGSubsystemGroup : public SGSubsystem { public: - SGSubsystemGroup (); + SGSubsystemGroup (const std::string &name); virtual ~SGSubsystemGroup (); void init() override; @@ -380,6 +403,7 @@ public: bool remove_subsystem (const std::string &name); virtual bool has_subsystem (const std::string &name) const; + void reportTimingStats(TimerStats *_lastValues) override; /** * Remove all subsystems. */ @@ -477,7 +501,7 @@ public: MAX_GROUPS }; - SGSubsystemMgr (); + SGSubsystemMgr (const std::string &name); virtual ~SGSubsystemMgr (); void init () override; @@ -510,7 +534,8 @@ public: SGSubsystem* get_subsystem(const std::string &name, const std::string& instanceName) const; void reportTiming(); - void setReportTimingCb(void* userData,SGSubsystemTimingCb cb) {reportTimingCb = cb;reportTimingUserData = userData;} + void setReportTimingCb(void* userData, SGSubsystemTimingCb cb) { reportTimingCb = cb; reportTimingUserData = userData; } + void setReportTimingStats(bool v) { reportTimingStatsRequest = v; } /** * @brief set the root property node for this subsystem manager