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