FGFS-4.1/simgear
4
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Improved subsystem performance monitoring and overrun detection

Browse Source 
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
This commit is contained in:
Richard Harrison 2019-02-10 17:44:45 +01:00
parent 95d065b3d7
commit c1dd8faa29
6 changed files with 221 additions and 34 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
simgear/structure/SGPerfMon.cxx
View File

@ -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. */

2
simgear/structure/SGPerfMon.hxx
View File

@ -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;

20
simgear/structure/event_mgr.cxx
View File

@ -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<std::string, double> &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;
}

4
simgear/structure/event_mgr.hxx
View File

@ -24,9 +24,8 @@ class SGTimerQueue {
public:
SGTimerQueue(int preSize=1);
~SGTimerQueue();
void clear();
void update(double deltaSecs);
void update(double deltaSecs, std::map<std::string, double> &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; }
/**

182
simgear/structure/subsystem_mgr.cxx
View File

@ -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

35
simgear/structure/subsystem_mgr.hxx
View File

@ -130,7 +130,8 @@ typedef void (*SGSubsystemTimingCb)(void* userData, const std::string& name, Sam
class SGSubsystem : public SGReferenced
{
public:
/**
using TimerStats = std::map<std::string, double>;
/**
* 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<SGSubsystem> SGSubsystemRef;
@ -355,7 +378,7 @@ typedef SGSharedPtr<SGSubsystem> 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