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

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

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 <simgear_config.h>
+#endif
+
+#include "SGPerfMon.hxx"
+#include <simgear/structure/SGSmplstat.hxx>
+
+#include <stdio.h>
+#include <string.h>
+#include <string>
+
+#include <simgear/constants.h>
+#include <simgear/sg_inlines.h>
+#include <simgear/debug/logstream.hxx>
+#include <simgear/math/sg_geodesy.hxx>
+#include <simgear/sound/soundmgr_openal.hxx>
+#include <simgear/structure/exception.hxx>
+
+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();
+}

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 <simgear/props/props.hxx>
+#include <simgear/structure/subsystem_mgr.hxx>
+#include <simgear/timing/timestamp.hxx>
+
+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

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;

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 ()
 {

simgear/structure/subsystem_mgr.cxx

@@ -31,11 +31,14 @@
 #include <simgear/math/SGMath.hxx>
 #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,11 +122,9 @@ 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 reportTiming(void) { if (reportTimingCb) reportTimingCb(reportTimingUserData, name, &timeStat); }
-    void updateExecutionTime(double time);
+    void updateExecutionTime(double time) { timeStat += time;}
-    double getTimeWarningThreshold();
-    void collectDebugTiming (bool collect) { collectTimeStats = collect; };
 
     SampleStatistic timeStat;
     std::string name;
@@ -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();
+          bool recordTime = (reportTimingCb != NULL);
-           _members[i]->update(delta_time_sec); // indirect call
+          if (recordTime)
-           timeStamp = SGTimeStamp::now() - timeStamp;
+              timeStamp = SGTimeStamp::now();
-           double b = timeStamp.toUSecs();
+
-           _members[i]->updateExecutionTime(b);
+          _members[i]->update(delta_time_sec); // indirect call
-           double threshold = _members[i]->getTimeWarningThreshold();
+
-           if (( b > threshold ) && (b > 10000)) {
+          if ((recordTime)&&(reportTimingCb))
-               _members[i]->printTimingInformation(b);
+          {
-           }
+              timeStamp = SGTimeStamp::now() - timeStamp;
+              _members[i]->updateExecutionTime(timeStamp.toUSecs());
+          }
       }
     } // of multiple update loop
 }
 
 void
-SGSubsystemGroup::collectDebugTiming(bool collect)
+SGSubsystemGroup::reportTiming(void)
-{
-    for (unsigned int i = 0; i < _members.size(); i++)
-    {
-        _members[i]->collectDebugTiming(collect);
-    }
-}
-
-void 
-SGSubsystemGroup::printTimingStatistics(double minMaxTime,double minJitter)
 {
     for (unsigned int i = _members.size(); i > 0; i--)
     {
-        _members[i-1]->printTimingStatistics(minMaxTime, minJitter);
+        _members[i-1]->reportTiming();
-        _members[i-1]->timeStat.reset();
     }
 }
 
@@ -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
 }
 

simgear/structure/subsystem_mgr.hxx

@@ -48,9 +48,12 @@ public:
     const SGTimeStamp& getTime() const { return time; }
 };
 
+class SampleStatistic;
+
 typedef std::vector<TimingInfo> eventTimeVec;
 typedef std::vector<TimingInfo>::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,27 +256,10 @@ public:
    */
   virtual bool is_suspended () const;
 
-
   /**
-   * Keep track of execution time.
+   * Trigger the callback to report timing information for all subsystems.
-   *
-   * <p>This method keeps track of timing statistics for each subsystem.</p>
-   * 
-   * @param time execution time in ms of last call.
    */
-  void updateExecutionTime(double time);
+  void reportTiming(void);
-
-  /**
-   * Print details of execution time.
-   *
-   * <p>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</p>
-   */ 
-  void printTimingInformation();
 
   /**
    * Place time stamps at strategic points in the execution of subsystems 
@@ -281,15 +267,14 @@ public:
    */
   void stamp(const std::string& name);
 
-
-
 protected:
 
   bool _suspended;
 
   eventTimeVec timingInfo;
-  //int test;
 
+  static SGSubsystemTimingCb reportTimingCb;
+  static void* reportTimingUserData;
 };
 
 
@@ -322,8 +307,7 @@ public:
     virtual void remove_subsystem (const std::string &name);
     virtual bool has_subsystem (const std::string &name) const;
 
-    void collectDebugTiming(bool collect);
+    void reportTiming(void);
-    void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0);
 
     /**
      *
@@ -404,8 +388,8 @@ public:
 
     virtual SGSubsystem * get_subsystem(const std::string &name) const;
 
-   void collectDebugTiming(bool collect);
+    void reportTiming();
-   void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0);
+    void setReportTimingCb(void* userData,SGSubsystemTimingCb cb) {reportTimingCb = cb;reportTimingUserData = userData;}
 
 private:
 
@@ -413,7 +397,6 @@ private:
 
     typedef std::map<std::string, SGSubsystem*> SubsystemDict;
     SubsystemDict _subsystem_map;
-
 };