DataLoggerのlogが時々(一回目だけ?)遅い

[garaemon]

優先度低めかもしれません。

DataLoggerのlog()が時々遅くなるようです

要因はm_log().push_back(m_data)とm_log.pop_from()の部分。

std::dequeが初期化のためにアロケーションしているのかも?

確認方法

以下のようなdiffを追加

diff --git a/rtc/DataLogger/DataLogger.cpp b/rtc/DataLogger/DataLogger.cpp
index 24b63c2..a5cc306 100644
--- a/rtc/DataLogger/DataLogger.cpp
+++ b/rtc/DataLogger/DataLogger.cpp
@@ -11,6 +11,29 @@
 #include "util/Hrpsys.h"
 #include "pointcloud.hh"

+class TimeAssert2
+{
+public:
+  TimeAssert2(const char* prefix_str): start_date(coil::gettimeofday()), prefix(prefix_str)
+  {
+  }
+  TimeAssert2(std::string& prefix_str): start_date(coil::gettimeofday()), prefix(prefix_str)
+  {
+  }
+  virtual ~TimeAssert2()
+  {
+    coil::TimeValue end_date(coil::gettimeofday());
+    coil::TimeValue diff_date = end_date - start_date;
+    double diff = diff_date;
+    if (diff > 0.005) {
+      std::cerr << "\x1b[31m" << prefix << ":: took " << diff << " sec" << "\x1b[39m" << std::endl;
+    }
+  }
+protected:
+  coil::TimeValue start_date;
+  std::string prefix;
+};
+

 typedef coil::Guard<coil::Mutex> Guard;

@@ -49,7 +72,7 @@ void printData(std::ostream& os, const RTC::Velocity2D& data)

 void printData(std::ostream& os, const RTC::Pose3D& data)
 {
-    os << data.position.x << " " << data.position.y << " " 
+    os << data.position.x << " " << data.position.y << " "
        << data.position.z << " " << data.orientation.r << " "
        << data.orientation.p << " " << data.orientation.y << " ";
 }
@@ -76,10 +99,10 @@ void printData(std::ostream& os, const PointCloudTypes::PointCloud& data)
   float *ptr = (float *)data.data.get_buffer();
   std::string type(data.type);
   if (type != "xyz" && type != "xyzrgb"){
-    std::cerr << "point cloud type(" << type << ") is not supported" 
+    std::cerr << "point cloud type(" << type << ") is not supported"
              << std::endl;
     return;
-  } 
+  }
   for (uint i=0; i<npoint ;i++){
     os << " " << *ptr++ << " " << *ptr++ << " " << *ptr++;
     if (type == "xyzrgb"){
@@ -88,7 +111,7 @@ void printData(std::ostream& os, const PointCloudTypes::PointCloud& data)
       ptr++;
     }
   }
-} 
+}

 template<class T>
 std::ostream& operator<<(std::ostream& os, const _CORBA_Unbounded_Sequence<T > & data)
@@ -129,13 +152,29 @@ public:
             return m_port;
     }
     void log(){
-        if (m_port.isNew()){
-            m_port.read();
-            m_log.push_back(m_data);
-            while (m_log.size() > m_maxLength){
-                m_log.pop_front();
-            }
+      TimeAssert2 tm_all("log()");
+      bool is_new_p;
+      {
+        TimeAssert2 tm_is_new("m_port.isNew()");
+        is_new_p = m_port.isNew();
+      }
+      if (is_new_p){
+        {
+          TimeAssert2 tm("m_port.read()");
+          m_port.read();
         }
+        {
+          std::string n = std::string("m_log.push_back(m_data)") + std::string(name());
+          TimeAssert2 tm(n);
+          m_log.push_back(m_data);
+        }
+        {
+          TimeAssert2 tm("while");
+          while (m_log.size() > m_maxLength){
+            m_log.pop_front();
+          }
+        }
+      }
     }
     void clear(){
         m_log.clear();
@@ -190,19 +229,19 @@ RTC::ReturnCode_t DataLogger::onInitialize()
   addInPort("emergencySignal", m_emergencySignalIn);

   // Set OutPort buffer
-  
+
   // Set service provider to Ports
   m_DataLoggerServicePort.registerProvider("service0", "DataLoggerService", m_service0);
-  
+
   // Set service consumers to Ports
-  
+
   // Set CORBA Service Ports
   addPort(m_DataLoggerServicePort);
-  
+
   // </rtc-template>
   // <rtc-template block="bind_config">
   // Bind variables and configuration variable
-  
+
   // </rtc-template>

   return RTC::RTC_OK;
@@ -243,32 +282,47 @@ RTC::ReturnCode_t DataLogger::onDeactivated(RTC::UniqueId ec_id)

 RTC::ReturnCode_t DataLogger::onExecute(RTC::UniqueId ec_id)
 {
-  if (ec_id == 0){
-    if (m_emergencySignalIn.isNew()){
-        m_emergencySignalIn.read();
-        time_t sec = time(NULL);
-        struct tm *tm_ = localtime(&sec);
-        char date[20];
-        strftime(date,20, "%Y-%m-%d", tm_);
-        char basename[30];
-        sprintf(basename, "emglog-%s-%02d%02d",
-                date, tm_->tm_hour, tm_->tm_min);
-        std::cout << "received emergency signal. saving log files("
-                  << basename << ")" << std::endl;
-        save(basename);
-        while (m_emergencySignalIn.isNew()){
-            m_emergencySignalIn.read();
-        }
-    }
-  }else{
-    Guard guard(m_suspendFlagMutex);
-    
-    if (m_suspendFlag) return RTC::RTC_OK;
-    
+  TimeAssert2 all_tm("DataLogger::onExecute");
+  {
     for (unsigned int i=0; i<m_ports.size(); i++){
-      m_ports[i]->log();
+      {
+        TimeAssert2 tm("m_ports[i]->log()");
+        m_ports[i]->log();
+      }
     }
   }
+//   if (ec_id == 0){
+//     if (m_emergencySignalIn.isNew()){
+//       {
+//         TimeAssert2 tm("m_emergencySignalIn.read()");
+//         m_emergencySignalIn.read();
+//       }
+//         time_t sec = time(NULL);
+//         struct tm *tm_ = localtime(&sec);
+//         char date[20];
+//         strftime(date,20, "%Y-%m-%d", tm_);
+//         char basename[30];
+//         sprintf(basename, "emglog-%s-%02d%02d",
+//                 date, tm_->tm_hour, tm_->tm_min);
+//         std::cout << "received emergency signal. saving log files("
+//                   << basename << ")" << std::endl;
+//         save(basename);
+//         while (m_emergencySignalIn.isNew()){
+//             m_emergencySignalIn.read();
+//         }
+//     }
+//   }else{
+//     Guard guard(m_suspendFlagMutex);
+
+//     if (m_suspendFlag) return RTC::RTC_OK;
+
+//     for (unsigned int i=0; i<m_ports.size(); i++){
+//       {
+//         TimeAssert2 tm("m_ports[i]->log()");
+//         m_ports[i]->log();
+//       }
+//     }
+//   }
   return RTC::RTC_OK;
 }

@@ -317,7 +371,7 @@ bool DataLogger::add(const char *i_type, const char *i_name)
           resumeLogging();
           return false;
       }
-  }  
+  }

   LoggerPortBase *new_port=NULL;
   if (strcmp(i_type, "TimedDoubleSeq")==0){

以下のような出力が得られた

[garaemon]

ログの長さについてですが、

self.log_svc.maxLength(6000)

してます

[fkanehiro]

スナップショットを見る限りは pop_front() が時間を食っているようですね。 STLの中身を読む気がしないんですが、どなたか何かご存知ないですか。

On Sat, Dec 6, 2014 at 2:09 PM, Ryohei Ueda notifications@github.com wrote:

ログの長さについてですが、

self.log_svc.maxLength(6000)

してます

— Reply to this email directly or view it on GitHub https://github.com/fkanehiro/hrpsys-base/issues/416#issuecomment-65885996 .