From 27a1c0288b2bff81bbd71041d8b7dc10319e7bef Mon Sep 17 00:00:00 2001 From: ThorstenB Date: Sat, 19 Nov 2011 15:24:43 +0100 Subject: [PATCH] Separate module to monitor (subsystem-)performance. Move some code from the subsystem manager to a separate module. Add module to evaluate performance and expose statistics to properties. --- simgear/structure/CMakeLists.txt | 2 + simgear/structure/SGPerfMon.cxx | 130 +++++++++++++++++++++++++ simgear/structure/SGPerfMon.hxx | 64 +++++++++++++ simgear/structure/SGSmplstat.cxx | 1 + simgear/structure/SGSmplstat.hxx | 7 ++ simgear/structure/subsystem_mgr.cxx | 144 +++++----------------------- simgear/structure/subsystem_mgr.hxx | 43 +++------ 7 files changed, 243 insertions(+), 148 deletions(-) create mode 100644 simgear/structure/SGPerfMon.cxx create mode 100644 simgear/structure/SGPerfMon.hxx diff --git a/simgear/structure/CMakeLists.txt b/simgear/structure/CMakeLists.txt index 4bb969c7..e5ff687a 100644 --- a/simgear/structure/CMakeLists.txt +++ b/simgear/structure/CMakeLists.txt @@ -13,6 +13,7 @@ set(HEADERS SGSmplstat.hxx SGWeakPtr.hxx SGWeakReferenced.hxx + SGPerfMon.hxx Singleton.hxx StringTable.hxx callback.hxx @@ -29,6 +30,7 @@ set(SOURCES SGExpression.cxx SGSmplhist.cxx SGSmplstat.cxx + SGPerfMon.cxx StringTable.cxx commands.cxx event_mgr.cxx diff --git a/simgear/structure/SGPerfMon.cxx b/simgear/structure/SGPerfMon.cxx new file mode 100644 index 00000000..806ebe98 --- /dev/null +++ b/simgear/structure/SGPerfMon.cxx @@ -0,0 +1,130 @@ +// SGPerfMon.cxx -- Performance Monitoring +// +// Written by Thorsten Brehm, started November 2011. +// +// Copyright (C) 2011 Thorsten Brehm - brehmt (at) gmail com +// +// This program is free software; you can redistribute it and/or +// modify it under the terms of the GNU General Public License as +// published by the Free Software Foundation; either version 2 of the +// License, or (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program; if not, write to the Free Software +// Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. +// + +#ifdef HAVE_CONFIG_H +# include +#endif + +#include "SGPerfMon.hxx" +#include + +#include +#include +#include + +#include +#include +#include +#include +#include +#include + +using std::string; + +SGPerformanceMonitor::SGPerformanceMonitor(SGSubsystemMgr* subSysMgr, SGPropertyNode_ptr root) : + _isEnabled(false), + _count(0) +{ + _root = root; + _subSysMgr = subSysMgr; +} + +void +SGPerformanceMonitor::bind(void) +{ + _statiticsSubsystems = _root->getChild("subsystems", 0, true); + _statisticsFlag = _root->getChild("enabled", 0, true); + _statisticsInterval = _root->getChild("interval-s", 0, true); +// _statiticsMinJitter = _root->getChild("min-jitter-ms", 0, true); +// _statiticsMinTime = _root->getChild("min-time-ms", 0, true); +} + +void +SGPerformanceMonitor::unbind(void) +{ + _statiticsSubsystems = 0; + _statisticsFlag = 0; + _statisticsInterval = 0; +// _statiticsMinJitter = 0; +// _statiticsMinTime = 0; +} + +void +SGPerformanceMonitor::init(void) +{ + +} + +void +SGPerformanceMonitor::update(double dt) +{ + if (_isEnabled != _statisticsFlag->getBoolValue()) + { + // flag has changed, update subsystem manager + _isEnabled = _statisticsFlag->getBoolValue(); + if (_isEnabled) + _subSysMgr->setReportTimingCb(this,&subSystemMgrHook); + else + _subSysMgr->setReportTimingCb(this,0); + } + + if (!_isEnabled) + return; + + if (_lastUpdate.elapsedMSec() > 1000 * _statisticsInterval->getDoubleValue()) + { + _count = 0; + // grab timing statistics + _subSysMgr->reportTiming(); + _lastUpdate.stamp(); + } +} + +/** Callback hooked into the subsystem manager. */ +void +SGPerformanceMonitor::subSystemMgrHook(void* userData, const std::string& name, SampleStatistic* timeStat) +{ + ((SGPerformanceMonitor*) userData)->reportTiming(name, timeStat); +} + +/** Grabs and exposes timing information to properties */ +void +SGPerformanceMonitor::reportTiming(const string& name, SampleStatistic* timeStat) +{ + SGPropertyNode* node = _statiticsSubsystems->getChild("subsystem",_count++,true); + + double minMs = timeStat->min() / 1000; + double maxMs = timeStat->max() / 1000; + double meanMs = timeStat->mean() / 1000; + double stdDevMs = timeStat->stdDev() / 1000; + double totalMs = timeStat->total() / 1000; + int samples = timeStat->samples(); + + node->setStringValue("name", name); + node->setDoubleValue("min-ms", minMs); + node->setDoubleValue("max-ms", maxMs); + node->setDoubleValue("mean-ms", meanMs); + node->setDoubleValue("stddev-ms", stdDevMs); + node->setDoubleValue("total-ms", totalMs); + node->setDoubleValue("count",samples); + + timeStat->reset(); +} diff --git a/simgear/structure/SGPerfMon.hxx b/simgear/structure/SGPerfMon.hxx new file mode 100644 index 00000000..d3009702 --- /dev/null +++ b/simgear/structure/SGPerfMon.hxx @@ -0,0 +1,64 @@ +// SGPerfMon.hxx -- Performance Tracing +// +// Written by Thorsten Brehm, started November 2011. +// +// Copyright (C) 2011 Thorsten Brehm - brehmt (at) gmail com +// +// This program is free software; you can redistribute it and/or +// modify it under the terms of the GNU General Public License as +// published by the Free Software Foundation; either version 2 of the +// License, or (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +// General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program; if not, write to the Free Software +// Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. +// + +#ifndef __SGPERFMON_HXX +#define __SGPERFMON_HXX + +#include +#include +#include + +class SampleStatistic; + +/////////////////////////////////////////////////////////////////////////////// +// SG Performance Monitor //////////////////////////////////////////////////// +/////////////////////////////////////////////////////////////////////////////// + +class SGPerformanceMonitor : public SGSubsystem +{ + +public: + SGPerformanceMonitor(SGSubsystemMgr* subSysMgr, SGPropertyNode_ptr root); + + virtual void bind (void); + virtual void unbind (void); + virtual void init (void); + virtual void update (double dt); + +private: + static void subSystemMgrHook(void* userData, const std::string& name, SampleStatistic* timeStat); + + void reportTiming(const std::string& name, SampleStatistic* timeStat); + + SGTimeStamp _lastUpdate; + SGSubsystemMgr* _subSysMgr; + SGPropertyNode_ptr _root; + SGPropertyNode_ptr _statiticsSubsystems; + SGPropertyNode_ptr _statisticsFlag; + SGPropertyNode_ptr _statisticsInterval; +// SGPropertyNode_ptr _statiticsMinJitter; +// SGPropertyNode_ptr _statiticsMinTime; + + bool _isEnabled; + int _count; +}; + +#endif // __SGPERFMON_HXX diff --git a/simgear/structure/SGSmplstat.cxx b/simgear/structure/SGSmplstat.cxx index 6d071be9..3135cf0b 100644 --- a/simgear/structure/SGSmplstat.cxx +++ b/simgear/structure/SGSmplstat.cxx @@ -81,6 +81,7 @@ void SampleStatistic::operator += (double value) { n += 1; x += value; + allTimeTotal += value; x2 += (value * value); if (minValue > value) minValue = value; diff --git a/simgear/structure/SGSmplstat.hxx b/simgear/structure/SGSmplstat.hxx index d815f400..d8e29b3f 100644 --- a/simgear/structure/SGSmplstat.hxx +++ b/simgear/structure/SGSmplstat.hxx @@ -30,6 +30,7 @@ protected: double x; double x2; double minValue, maxValue; + double allTimeTotal; public: SampleStatistic (); inline virtual ~ SampleStatistic (); @@ -42,6 +43,7 @@ public: SampleStatistic (); double var () const; double min () const; double max () const; + double total () const; double confidence (int p_percentage) const; double confidence (double p_value) const; @@ -58,6 +60,7 @@ public: SampleStatistic (); inline SampleStatistic::SampleStatistic () { + allTimeTotal = 0; reset (); } inline int SampleStatistic::samples () const @@ -72,6 +75,10 @@ inline double SampleStatistic::max () const { return (maxValue); } +inline double SampleStatistic::total () const +{ + return (allTimeTotal); +} inline SampleStatistic::~SampleStatistic () { diff --git a/simgear/structure/subsystem_mgr.cxx b/simgear/structure/subsystem_mgr.cxx index 8265f9b3..6bd7b394 100644 --- a/simgear/structure/subsystem_mgr.cxx +++ b/simgear/structure/subsystem_mgr.cxx @@ -31,11 +31,14 @@ #include #include "SGSmplstat.hxx" -const int SG_MAX_SUBSYSTEM_EXCEPTIONS = 4; +const int SG_MAX_SUBSYSTEM_EXCEPTIONS = 4; + //////////////////////////////////////////////////////////////////////// // Implementation of SGSubsystem //////////////////////////////////////////////////////////////////////// +SGSubsystemTimingCb SGSubsystem::reportTimingCb = NULL; +void* SGSubsystem::reportTimingUserData = NULL; SGSubsystem::SGSubsystem () : _suspended(false) @@ -100,28 +103,6 @@ SGSubsystem::is_suspended () const return _suspended; } - -void -SGSubsystem::printTimingInformation () -{ - SGTimeStamp startTime; - for ( eventTimeVecIterator i = timingInfo.begin(); - i != timingInfo.end(); - ++i) { - if (i == timingInfo.begin()) { - startTime = i->getTime(); - } else { - SGTimeStamp endTime = i->getTime(); - SG_LOG(SG_GENERAL, SG_ALERT, "- Getting to timestamp : " - << i->getName() << " takes " << endTime - startTime - << " sec."); - startTime = endTime; - } - } -} - - - void SGSubsystem::stamp(const string& name) { timingInfo.push_back(TimingInfo(name, SGTimeStamp::now())); @@ -141,12 +122,10 @@ public: virtual ~Member (); virtual void update (double delta_time_sec); - void printTimingInformation(double time); - void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0); - void updateExecutionTime(double time); - double getTimeWarningThreshold(); - void collectDebugTiming (bool collect) { collectTimeStats = collect; }; - + + void reportTiming(void) { if (reportTimingCb) reportTimingCb(reportTimingUserData, name, &timeStat); } + void updateExecutionTime(double time) { timeStat += time;} + SampleStatistic timeStat; std::string name; SGSubsystem * subsystem; @@ -166,8 +145,6 @@ SGSubsystemGroup::SGSubsystemGroup () : SGSubsystemGroup::~SGSubsystemGroup () { - printTimingStatistics(); - // reverse order to prevent order dependency problems for (unsigned int i = _members.size(); i > 0; i--) { @@ -233,38 +210,31 @@ SGSubsystemGroup::update (double delta_time_sec) delta_time_sec = _fixedUpdateTime; } + SGTimeStamp timeStamp; while (loopCount-- > 0) { for (unsigned int i = 0; i < _members.size(); i++) { - SGTimeStamp timeStamp = SGTimeStamp::now(); - _members[i]->update(delta_time_sec); // indirect call - timeStamp = SGTimeStamp::now() - timeStamp; - double b = timeStamp.toUSecs(); - _members[i]->updateExecutionTime(b); - double threshold = _members[i]->getTimeWarningThreshold(); - if (( b > threshold ) && (b > 10000)) { - _members[i]->printTimingInformation(b); - } + bool recordTime = (reportTimingCb != NULL); + if (recordTime) + timeStamp = SGTimeStamp::now(); + + _members[i]->update(delta_time_sec); // indirect call + + if ((recordTime)&&(reportTimingCb)) + { + timeStamp = SGTimeStamp::now() - timeStamp; + _members[i]->updateExecutionTime(timeStamp.toUSecs()); + } } } // of multiple update loop } -void -SGSubsystemGroup::collectDebugTiming(bool collect) -{ - for (unsigned int i = 0; i < _members.size(); i++) - { - _members[i]->collectDebugTiming(collect); - } -} - -void -SGSubsystemGroup::printTimingStatistics(double minMaxTime,double minJitter) +void +SGSubsystemGroup::reportTiming(void) { for (unsigned int i = _members.size(); i > 0; i--) { - _members[i-1]->printTimingStatistics(minMaxTime, minJitter); - _members[i-1]->timeStat.reset(); + _members[i-1]->reportTiming(); } } @@ -327,35 +297,6 @@ SGSubsystemGroup::set_fixed_update_time(double dt) _fixedUpdateTime = dt; } -/** - * Print timing statistics. - * Only show data if jitter exceeds minJitter or - * maximum time exceeds minMaxTime. - */ -void -SGSubsystemGroup::Member::printTimingStatistics(double minMaxTime,double minJitter) -{ - if (collectTimeStats) { - double minTime = timeStat.min() / 1000; - double maxTime = timeStat.max() / 1000; - double meanTime = timeStat.mean() / 1000; - double stddev = timeStat.stdDev() / 1000; - - if ((maxTime - minTime >= minJitter)|| - (maxTime >= minMaxTime)) - { - char buffer[256]; - snprintf(buffer, 256, "Timing summary for %20s.\n" - "- mean time: %04.2f ms.\n" - "- min time : %04.2f ms.\n" - "- max time : %04.2f ms.\n" - "- stddev : %04.2f ms.\n", name.c_str(), meanTime, minTime, maxTime, stddev); - SG_LOG(SG_GENERAL, SG_ALERT, buffer); - } - } -} - - bool SGSubsystemGroup::has_subsystem (const string &name) const { @@ -390,7 +331,6 @@ SGSubsystemGroup::Member::Member () subsystem(0), min_step_sec(0), elapsed_sec(0), - collectTimeStats(false), exceptionCount(0) { } @@ -433,31 +373,6 @@ SGSubsystemGroup::Member::update (double delta_time_sec) } -void -SGSubsystemGroup::Member::printTimingInformation(double time) -{ - if (collectTimeStats) { - SG_LOG(SG_GENERAL, SG_ALERT, "Subsystem Timing Alert, subsystem \"" << name << "\": " << time/1000.0 << "ms"); - subsystem->printTimingInformation(); - } -} - -double SGSubsystemGroup::Member::getTimeWarningThreshold() -{ - return (timeStat.mean() + 3 * timeStat.stdDev()); -} - -void SGSubsystemGroup::Member::updateExecutionTime(double time) -{ - if (collectTimeStats) { - timeStat += time; - } -} - - - - - //////////////////////////////////////////////////////////////////////// // Implementation of SGSubsystemMgr. //////////////////////////////////////////////////////////////////////// @@ -534,14 +449,6 @@ SGSubsystemMgr::update (double delta_time_sec) } } -void -SGSubsystemMgr::collectDebugTiming(bool collect) -{ - for (int i = 0; i < MAX_GROUPS; i++) { - _groups[i]->collectDebugTiming(collect); - } -} - void SGSubsystemMgr::suspend () { @@ -616,11 +523,12 @@ SGSubsystemMgr::get_subsystem (const string &name) const return s->second; } +/** Trigger the timing callback to report data for all subsystems. */ void -SGSubsystemMgr::printTimingStatistics(double minMaxTime,double minJitter) +SGSubsystemMgr::reportTiming() { for (int i = 0; i < MAX_GROUPS; i++) { - _groups[i]->printTimingStatistics(minMaxTime, minJitter); + _groups[i]->reportTiming(); } // of groups iteration } diff --git a/simgear/structure/subsystem_mgr.hxx b/simgear/structure/subsystem_mgr.hxx index f1e2ad9a..f5f918f6 100644 --- a/simgear/structure/subsystem_mgr.hxx +++ b/simgear/structure/subsystem_mgr.hxx @@ -48,9 +48,12 @@ public: const SGTimeStamp& getTime() const { return time; } }; +class SampleStatistic; + typedef std::vector eventTimeVec; typedef std::vector::iterator eventTimeVecIterator; +typedef void (*SGSubsystemTimingCb)(void* userData, const std::string& name, SampleStatistic* pStatistic); /** @@ -227,7 +230,7 @@ public: /** - * Suspend or resum operation of this subsystem. + * Suspend or resume operation of this subsystem. * * @param suspended true if the subsystem should be suspended, false * otherwise. @@ -253,43 +256,25 @@ public: */ virtual bool is_suspended () const; - /** - * Keep track of execution time. - * - *

This method keeps track of timing statistics for each subsystem.

- * - * @param time execution time in ms of last call. + * Trigger the callback to report timing information for all subsystems. */ - void updateExecutionTime(double time); - - /** - * Print details of execution time. - * - *

For debugging purposes, developers can place stamp() calls - * at strategic points in the update() function of each subsystem, which - * record the time between the successive calls to stamp. This method, - * printExecutionTime() is called after exectution of the subsystem - * update function itself to conduct a post-hoc analysis of excecution - * time

- */ - void printTimingInformation(); + void reportTiming(void); /** * Place time stamps at strategic points in the execution of subsystems * update() member functions. Predominantly for debugging purposes. */ void stamp(const std::string& name); - - protected: bool _suspended; eventTimeVec timingInfo; - //int test; + static SGSubsystemTimingCb reportTimingCb; + static void* reportTimingUserData; }; @@ -322,11 +307,10 @@ public: virtual void remove_subsystem (const std::string &name); virtual bool has_subsystem (const std::string &name) const; - void collectDebugTiming(bool collect); - void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0); + void reportTiming(void); /** - * + * */ void set_fixed_update_time(double fixed_dt); private: @@ -404,16 +388,15 @@ public: virtual SGSubsystem * get_subsystem(const std::string &name) const; - void collectDebugTiming(bool collect); - void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0); + void reportTiming(); + void setReportTimingCb(void* userData,SGSubsystemTimingCb cb) {reportTimingCb = cb;reportTimingUserData = userData;} private: SGSubsystemGroup* _groups[MAX_GROUPS]; - + typedef std::map SubsystemDict; SubsystemDict _subsystem_map; - };