Improve subsystem manager's timing statistics

Option to print statistics at run-time.
Convenient filter parameters to show subsystems with jitter or excessive
execution time only.

diff --git a/simgear/structure/subsystem_mgr.cxx b/simgear/structure/subsystem_mgr.cxx
index 6e5b42411ff4de7acbf75a176a25b45ea93f049e..39598abeb8f3cb83768ca92309217bff382f9907 100644 (file)
--- a/simgear/structure/subsystem_mgr.cxx
+++ b/simgear/structure/subsystem_mgr.cxx
@@ -1,3 +1,22 @@
+// Written by David Megginson, started 2000-12
+//
+// Copyright (C) 2000  David Megginson, david@megginson.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., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+//
+// $Id$

 
 #include <simgear/debug/logstream.hxx>
 #include <simgear/timing/timestamp.hxx>
 
 #include <simgear/debug/logstream.hxx>
 #include <simgear/timing/timestamp.hxx>


@@ -117,10 +136,11 @@ SGSubsystemGroup::SGSubsystemGroup () :
 
 SGSubsystemGroup::~SGSubsystemGroup ()
 {
 
 SGSubsystemGroup::~SGSubsystemGroup ()
 {

+    printTimingStatistics();
+

     // reverse order to prevent order dependency problems
     for (unsigned int i = _members.size(); i > 0; i--)
     {
     // reverse order to prevent order dependency problems
     for (unsigned int i = _members.size(); i > 0; i--)
     {

-        _members[i-1]->printTimingStatistics();

         delete _members[i-1];
     }
 }
         delete _members[i-1];
     }
 }


@@ -188,7 +208,7 @@ SGSubsystemGroup::update (double delta_time_sec)
       {
            SGTimeStamp timeStamp = SGTimeStamp::now();
            _members[i]->update(delta_time_sec); // indirect call
       {
            SGTimeStamp timeStamp = SGTimeStamp::now();
            _members[i]->update(delta_time_sec); // indirect call

-           timeStamp = timeStamp - SGTimeStamp::now();
+           timeStamp = SGTimeStamp::now() - timeStamp;

            double b = timeStamp.toUSecs();
            _members[i]->updateExecutionTime(b);
            double threshold = _members[i]->getTimeWarningThreshold();
            double b = timeStamp.toUSecs();
            _members[i]->updateExecutionTime(b);
            double threshold = _members[i]->getTimeWarningThreshold();


@@ -208,6 +228,16 @@ SGSubsystemGroup::collectDebugTiming(bool 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]->timeStat.reset();
+    }
+}
+

 void
 SGSubsystemGroup::suspend ()
 {
 void
 SGSubsystemGroup::suspend ()
 {


@@ -267,8 +297,13 @@ SGSubsystemGroup::set_fixed_update_time(double dt)
   _fixedUpdateTime = dt;
 }
 
   _fixedUpdateTime = dt;
 }
 

+/**
+ * Print timing statistics.
+ * Only show data if jitter exceeds minJitter or
+ * maximum time exceeds minMaxTime. 
+ */

 void
 void

-SGSubsystemGroup::Member::printTimingStatistics ()
+SGSubsystemGroup::Member::printTimingStatistics(double minMaxTime,double minJitter)

 {
     if (collectTimeStats) {
         double minTime = timeStat.min()   / 1000;
 {
     if (collectTimeStats) {
         double minTime = timeStat.min()   / 1000;


@@ -276,13 +311,17 @@ SGSubsystemGroup::Member::printTimingStatistics ()
         double meanTime = timeStat.mean() / 1000;
         double stddev   = timeStat.stdDev()   / 1000;
 
         double meanTime = timeStat.mean() / 1000;
         double stddev   = timeStat.stdDev()   / 1000;
 

-        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);
+        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);
+        }

     }
 }
 
     }
 }
 


@@ -368,7 +407,7 @@ void
 SGSubsystemGroup::Member::printTimingInformation(double time)
 {
      if (collectTimeStats) {
 SGSubsystemGroup::Member::printTimingInformation(double time)
 {
      if (collectTimeStats) {

-         SG_LOG(SG_GENERAL, SG_ALERT, "Subsystem Timing Alert : " << time << " " << name);
+         SG_LOG(SG_GENERAL, SG_ALERT, "Subsystem Timing Alert, subsystem \"" << name << "\": " << time/1000.0 << "ms");

          subsystem->printTimingInformation();
      }
 }
          subsystem->printTimingInformation();
      }
 }


@@ -547,4 +586,12 @@ SGSubsystemMgr::get_subsystem (const string &name) const
         return s->second;
 }
 
         return s->second;
 }
 

-// end of fgfs.cxx
+void
+SGSubsystemMgr::printTimingStatistics(double minMaxTime,double minJitter)
+{
+    for (int i = 0; i < MAX_GROUPS; i++) {
+        _groups[i]->printTimingStatistics(minMaxTime, minJitter);
+    } // of groups iteration
+}
+
+// end of subsystem_mgr.cxx

diff --git a/simgear/structure/subsystem_mgr.hxx b/simgear/structure/subsystem_mgr.hxx
index 0de20ef8623f2559dccd3c5dc661ea04574c425e..60313fd4a3543a8f723f233dc66c660a0ecd2951 100644 (file)
--- a/simgear/structure/subsystem_mgr.hxx
+++ b/simgear/structure/subsystem_mgr.hxx
@@ -323,6 +323,7 @@ public:
     virtual bool has_subsystem (const std::string &name) const;
 
     void collectDebugTiming(bool collect);
     virtual bool has_subsystem (const std::string &name) const;
 
     void collectDebugTiming(bool collect);

+    void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0);

 
     /**
      * 
 
     /**
      * 


@@ -339,8 +340,8 @@ private:
         virtual ~Member ();
 
         virtual void update (double delta_time_sec);
         virtual ~Member ();
 
         virtual void update (double delta_time_sec);

-       void printTimingInformation(double time);
-        void printTimingStatistics();
+        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 updateExecutionTime(double time);
         double getTimeWarningThreshold();
         void collectDebugTiming (bool collect) { collectTimeStats = collect; };


@@ -427,6 +428,7 @@ public:
     virtual SGSubsystem * get_subsystem(const std::string &name) const;
 
    void collectDebugTiming(bool collect);
     virtual SGSubsystem * get_subsystem(const std::string &name) const;
 
    void collectDebugTiming(bool collect);

+   void printTimingStatistics(double minMaxTime=0.0,double minJitter=0.0);

 
 private:
 
 
 private: