X-Git-Url: https://git.mxchange.org/?a=blobdiff_plain;f=simgear%2Fstructure%2Fsubsystem_mgr.cxx;h=9488faea51a06c1b2c58d624adc4f11f6a5c60c7;hb=1f6555c9ad3fb75cb474fbf99b46333830285514;hp=3be9096233ac67f9258c19a9e5b594e2c7398c8b;hpb=a75b4af3744039072c7a03ef4ed6fcb536763937;p=simgear.git

diff --git a/simgear/structure/subsystem_mgr.cxx b/simgear/structure/subsystem_mgr.cxx
index 3be90962..9488faea 100644
--- a/simgear/structure/subsystem_mgr.cxx
+++ b/simgear/structure/subsystem_mgr.cxx
@@ -1,11 +1,14 @@
 
 #include <simgear/debug/logstream.hxx>
+#include <simgear/timing/timestamp.hxx>
 
 #include "exception.hxx"
 #include "subsystem_mgr.hxx"
 
+#include <simgear/math/SGMath.hxx>
 
-
+
+const int SG_MAX_SUBSYSTEM_EXCEPTIONS = 4;
 ////////////////////////////////////////////////////////////////////////
 // Implementation of SGSubsystem
 ////////////////////////////////////////////////////////////////////////
@@ -70,19 +73,51 @@ SGSubsystem::is_suspended () const
 }
 
 
+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()));
+}
+
 
 ////////////////////////////////////////////////////////////////////////
 // Implementation of SGSubsystemGroup.
 ////////////////////////////////////////////////////////////////////////
 
-SGSubsystemGroup::SGSubsystemGroup ()
+SGSubsystemGroup::SGSubsystemGroup () :
+  _fixedUpdateTime(-1.0),
+  _updateTimeRemainder(0.0)
 {
 }
 
 SGSubsystemGroup::~SGSubsystemGroup ()
 {
-    for (unsigned int i = 0; i < _members.size(); i++)
-        delete _members[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];
+    }
 }
 
 void
@@ -116,15 +151,48 @@ SGSubsystemGroup::bind ()
 void
 SGSubsystemGroup::unbind ()
 {
-    for (unsigned int i = 0; i < _members.size(); i++)
-        _members[i]->subsystem->unbind();
+    // reverse order to prevent order dependency problems
+    for (unsigned int i = _members.size(); i > 0; i--)
+       _members[i-1]->subsystem->unbind();
 }
 
 void
 SGSubsystemGroup::update (double delta_time_sec)
+{
+    int loopCount = 1;
+    // if dt == 0.0, we are paused, so we need to run one iteration
+    // of our members; if we have a fixed update time, we compute a
+    // loop count, and locally adjust dt
+    if ((delta_time_sec > 0.0) && (_fixedUpdateTime > 0.0)) {
+      double localDelta = delta_time_sec + _updateTimeRemainder;
+      loopCount = SGMiscd::roundToInt(localDelta / _fixedUpdateTime);
+      _updateTimeRemainder = delta_time_sec - (loopCount * _fixedUpdateTime);
+      delta_time_sec = _fixedUpdateTime;
+    }
+
+    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 = timeStamp - SGTimeStamp::now();
+           double b = timeStamp.toUSecs();
+           _members[i]->updateExecutionTime(b);
+           double threshold = _members[i]->getTimeWarningThreshold();
+           if (( b > threshold ) && (b > 10000)) {
+               _members[i]->printTimingInformation(b);
+           }
+      }
+    } // of multiple update loop
+}
+
+void 
+SGSubsystemGroup::collectDebugTiming(bool collect)
 {
     for (unsigned int i = 0; i < _members.size(); i++)
-        _members[i]->update(delta_time_sec); // indirect call
+    {
+        _members[i]->collectDebugTiming(collect);
+    }
 }
 
 void
@@ -180,6 +248,32 @@ SGSubsystemGroup::remove_subsystem (const string &name)
     }
 }
 
+void
+SGSubsystemGroup::set_fixed_update_time(double dt)
+{
+  _fixedUpdateTime = dt;
+}
+
+void
+SGSubsystemGroup::Member::printTimingStatistics ()
+{
+    if (collectTimeStats) {
+        double minTime = timeStat.min()   / 1000;
+        double maxTime = timeStat.max()   / 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);
+    }
+}
+
+
 bool
 SGSubsystemGroup::has_subsystem (const string &name) const
 {
@@ -213,13 +307,15 @@ SGSubsystemGroup::Member::Member ()
     : name(""),
       subsystem(0),
       min_step_sec(0),
-      elapsed_sec(0)
+      elapsed_sec(0),
+      collectTimeStats(false),
+      exceptionCount(0)
 {
 }
 
+// This shouldn't be called due to subsystem pointer ownership issues.
 SGSubsystemGroup::Member::Member (const Member &)
 {
-    Member();
 }
 
 SGSubsystemGroup::Member::~Member ()
@@ -231,15 +327,54 @@ void
 SGSubsystemGroup::Member::update (double delta_time_sec)
 {
     elapsed_sec += delta_time_sec;
-    if (elapsed_sec >= min_step_sec) {
-        if (!subsystem->is_suspended()) {
-            subsystem->update(elapsed_sec);
-            elapsed_sec = 0;
-        }
+    if (elapsed_sec < min_step_sec) {
+        return;
+    }
+    
+    if (subsystem->is_suspended()) {
+        return;
+    }
+    
+    try {
+      subsystem->update(elapsed_sec);
+      elapsed_sec = 0;
+    } catch (sg_exception& e) {
+      SG_LOG(SG_GENERAL, SG_ALERT, "caught exception processing subsystem:" << name
+        << "\nmessage:" << e.getMessage());
+      
+      if (++exceptionCount > SG_MAX_SUBSYSTEM_EXCEPTIONS) {
+        SG_LOG(SG_GENERAL, SG_ALERT, "(exceptionCount=" << exceptionCount <<
+          ", suspending)");
+        subsystem->suspend();
+      }
+    }
+}
+
+
+void 
+SGSubsystemGroup::Member::printTimingInformation(double time)
+{
+     if (collectTimeStats) {
+         SG_LOG(SG_GENERAL, SG_ALERT, "Subsystem Timing Alert : " << time << " " << name);
+         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.
@@ -285,7 +420,8 @@ SGSubsystemMgr::bind ()
 void
 SGSubsystemMgr::unbind ()
 {
-    for (int i = 0; i < MAX_GROUPS; i++)
+    // reverse order to prevent order dependency problems
+    for (int i = MAX_GROUPS-1; i >= 0; i--)
         _groups[i].unbind();
 }
 
@@ -297,6 +433,14 @@ 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 ()
 {