[skip ci] implementing profiling_unit

include/core/common/profiling_unit.h

+// WOLF - Copyright (C) 2020,2021,2022,2023,2024,2025
+// Institut de Robòtica i Informàtica Industrial, CSIC-UPC.
+// Authors: Joan Solà Ortega (jsola@iri.upc.edu) and
+// Joan Vallvé Navarro (jvallve@iri.upc.edu)
+// All rights reserved.
+//
+// This file is part of WOLF: http://www.iri.upc.edu/wolf
+// WOLF is free software: you can redistribute it and/or modify
+// it under the terms of the GNU Lesser General Public License as published by
+// the Free Software Foundation, either version 3 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 Lesser General Public License for more details.
+//
+// You should have received a copy of the GNU Lesser General Public License
+// along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+#pragma once
+
+// wolf includes
+#include "core/common/wolf.h"
+
+// C, std
+#include <sys/time.h>
+#include <iostream>
+#include <iomanip>
+
+static const unsigned int NANOSECS = 1000000000;
+
+namespace wolf
+{
+/**
+ * \brief TimeStamp implements basic functionalities for time stamps
+ *
+ * TimeStamp implements basic functionalities for time stamps
+ */
+class ProfilingUnit
+{
+  protected:
+    double                                                      desired_period_;
+    unsigned int                                                n_callbacks_;
+    double                                                      average_period_;
+    std::chrono::microseconds                                   acc_duration_;
+    std::chrono::microseconds                                   max_duration_;
+    double                                                      var_duration_;
+    std::chrono::time_point<std::chrono::high_resolution_clock> first_clock_;
+    std::chrono::time_point<std::chrono::high_resolution_clock> start_clock_;
+
+  public:
+    /** \brief Constructor
+     *
+     * Constructor without arguments. Sets time stamp to now.
+     *
+     */
+    ProfilingUnit(double desired_period_sec = -1);
+
+    void startProfiling();
+
+    void stopProfiling();
+
+    void printProfiling(std::ostream& stream = std::cout) const;
+
+    std::stringstream printDuration(double _duration_ms, int precision = 2) const;
+};
+
+ProfilingUnit::ProfilingUnit(desired_period_sec)
+    : desired_period_(1e6 * desired_period_sec),
+      n_callbacks_(0),
+      average_period_(0),
+      acc_duration_(0),
+      max_duration_(0),
+      var_duration_(0)
+{
+}
+
+inline void ProfilingUnit::startCaptureProfiling()
+{
+    start_ = std::chrono::high_resolution_clock::now();
+    n_callback_++;
+    if (n_callback_ == 1)
+        first_clock_ = start_;
+    else
+    {
+        auto duration   = std::chrono::duration_cast<std::chrono::microseconds>(start_ - first_clock_);
+        average_period_ = duration.count() / (n_callback_ - 1);
+    }
+}
+
+inline void ProfilingUnit::stopCaptureProfiling()
+{
+    auto prev_mean_duration = n_callback_ < 2 ? 0 : acc_duration_.count() / (n_callback_ - 1);
+
+    auto duration =
+        std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start_);
+
+    max_duration_ = std::max(max_duration_, duration);
+    acc_duration_ += duration;
+    var_duration_ =
+        n_callback_ < 2
+            ? 0
+            : ((n_callback_ - 2) * var_duration_ +
+               (duration.count() - prev_mean_duration) * (duration.count() - acc_duration_.count() / n_callback_)) /
+                  (n_callback_ - 1);
+}
+
+inline std::stringstream ProfilingUnit::printDuration(double _duration_microsec, int precision) const
+{
+    std::stringstream stream;
+    if (_duration_microsec > 1e6)
+        stream << std::fixed << std::setprecision(precision) << 1e-6 * _duration_microsec << " s";
+    else if (_duration_microsec > 1e3)
+        stream << std::fixed << std::setprecision(precision) << 1e-3 * _duration_microsec << " ms";
+    else
+        stream << std::fixed << std::setprecision(precision) << _duration_microsec << " us";
+
+    return stream;
+}
+
+inline void ProcessorBase::printProfiling(std::ostream& _stream) const
+{
+    auto ref_period = desired_period_ > 0 ? desired_period_ : average_period_;
+
+    unsigned int average_percent =
+        (n_callbacks_ > 0) ? std::round(100 * acc_duration_.count() / n_callbacks_ / ref_period) : 0;
+    unsigned int max_percent   = (n_callbacks_ > 0) ? std::round(100 * max_duration_.count() / ref_period) : 0;
+    unsigned int stdev_percent = (n_callbacks_ > 0) ? std::round(100 * sqrt(var_duration_) / ref_period) : 0;
+
+    _stream << "\n\t\tinstances: " << n_callbacks_                                        //
+            << "\n\t\taverage period:     " << printDuration(average_period_)             //
+            << "\n\t\ttotal time:   " << printDuration(acc_duration_.count())             //
+            << "\n\t\tavg time: " << printDuration(acc_duration_.count() / n_callbacks_)  //
+            << " (" << average_percent << "%)"                                            //
+            << "\n\t\tstdev time: " << printDuration(sqrt(var_duration_))                 //
+            << " (" << stdev_percent << "%)"                                              //
+            << "\n\t\tmax time:     " << printDuration(max_duration_.count())             //
+            << " (" << max_percent << "%)"                                                //
+}
+
+}  // namespace wolf

include/core/processor/processor_base.h

@@ -138,6 +138,8 @@ class ProcessorBase : public NodeBase, public std::enable_shared_from_this<Proce
     std::chrono::microseconds                                   acc_duration_kf_;
     std::chrono::microseconds                                   max_duration_capture_;
     std::chrono::microseconds                                   max_duration_kf_;
+    double                                                      var_duration_capture_;
+    double                                                      var_duration_kf_;
     std::chrono::time_point<std::chrono::high_resolution_clock> start_capture_;
     std::chrono::time_point<std::chrono::high_resolution_clock> start_kf_;
     void                                                        startCaptureProfiling();
@@ -289,11 +291,17 @@ inline void ProcessorBase::startCaptureProfiling()
 
 inline void ProcessorBase::stopCaptureProfiling()
 {
+    //auto prev_mean_duration_capture = n_capture_callback_ < 2 ? 0 : acc_duration_capture_.count() / (n_capture_callback_ - 1);
+
     auto duration_capture = std::chrono::duration_cast<std::chrono::microseconds>(
         std::chrono::high_resolution_clock::now() - start_capture_);
 
     max_duration_capture_ = std::max(max_duration_capture_, duration_capture);
     acc_duration_capture_ += duration_capture;
+    // var_duration_capture_ = n_capture_callback_ < 2 ? 0 : ((n_capture_callback_ - 2) * var_duration_capture_ +
+    //                          (duration_capture.count() - prev_mean_duration_capture) *
+    //                              (duration_capture.count() - acc_duration_capture_.count() / n_capture_callback_)) /
+    //                         (n_capture_callback_ - 1);
 }
 
 inline void ProcessorBase::startKFProfiling()
@@ -303,11 +311,17 @@ inline void ProcessorBase::startKFProfiling()
 
 inline void ProcessorBase::stopKFProfiling()
 {
+    //auto prev_mean_duration_kf = n_kf_callback_ < 2 ? 0 : acc_duration_kf_.count() / (n_kf_callback_ - 1) ;
+
     auto duration_kf =
         std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - start_kf_);
 
     max_duration_kf_ = std::max(max_duration_kf_, duration_kf);
     acc_duration_kf_ += duration_kf;
+    // var_duration_kf_ = n_kf_callback_ < 2 ? 0 : ((n_kf_callback_ - 2) * var_duration_kf_ +
+    //                     (duration_kf.count() - prev_mean_duration_kf) *
+    //                         (duration_kf.count() - acc_duration_kf_.count() / n_kf_callback_)) /
+    //                    (n_kf_callback_ - 1);
 }
 
 inline YAML::Node ProcessorBase::getParams() const

src/processor/processor_base.cpp

@@ -42,7 +42,9 @@ ProcessorBase::ProcessorBase(const std::string& _type, unsigned int _dim_compati
       acc_duration_capture_(0),
       acc_duration_kf_(0),
       max_duration_capture_(0),
-      max_duration_kf_(0)
+      max_duration_kf_(0),
+      var_duration_capture_(0),
+      var_duration_kf_(0)
 {
     assert(dim_compatible_ == 0 or dim_compatible_ == 2 or dim_compatible_ == 3);
     WOLF_DEBUG("Constructed ProcessorBase - ", getType(), " id: ", id(), " name: ", getName());
@@ -244,32 +246,42 @@ void ProcessorBase::printProfiling(std::ostream& _stream) const
         (n_kf_callback_ > 0) ? std::round(100 * capture_period_mean_ * n_capture_callback_ / n_kf_callback_) : 0;
     unsigned int average_proc_cap_percent =
         (n_capture_callback_ > 0)
-            ? std::round(100 * acc_duration_capture_.count() / n_capture_callback_ / capture_period_mean_)
+            ? std::round(100 * 1e-6 * acc_duration_capture_.count() / n_capture_callback_ / capture_period_mean_)
             : 0;
     unsigned int max_proc_cap_percent =
-        (n_capture_callback_ > 0) ? std::round(100 * max_duration_capture_.count() / capture_period_min_) : 0;
+        (n_capture_callback_ > 0) ? std::round(100 * 1e-6 * max_duration_capture_.count() / capture_period_min_) : 0;
+    unsigned int stdev_proc_cap_percent =
+        (n_capture_callback_ > 0) ? std::round(100 * 1e-6 * sqrt(var_duration_capture_) / capture_period_mean_)
+                                  : 0;
     unsigned int average_proc_kf_percent =
-        (n_kf_callback_ > 0) ? std::round(100 * acc_duration_kf_.count() / n_kf_callback_ / kf_average_period) : 0;
+        (n_kf_callback_ > 0) ? std::round(100 * 1e-6 * acc_duration_kf_.count() / n_kf_callback_ / kf_average_period)
+                             : 0;
     unsigned int max_proc_kf_percent =
-        (n_kf_callback_ > 0) ? std::round(100 * max_duration_kf_.count() / kf_average_period) : 0;
+        (n_kf_callback_ > 0) ? std::round(100 * 1e-6 * max_duration_kf_.count() / kf_average_period) : 0;
+    unsigned int std_dev_proc_kf_percent =
+        (n_kf_callback_ > 0) ? std::round(100 * 1e-6 * sqrt(var_duration_kf_) / kf_average_period) : 0;
 
     _stream << "\n"
             << getType() << " - " << getName() << ":"
             << "\n\ttotal proc. time:           " << 1e-6 * (acc_duration_capture_ + acc_duration_kf_).count() << " s"
             << "\n\tProcessing captures:"
             << "\n\t\tcaptures processed: " << n_capture_callback_
-            << "\n\t\taverage period:     " << 1e-3 * capture_period_mean_ << " ms"
+            << "\n\t\taverage period:     " << 1e3 * capture_period_mean_ << " ms"
             << "\n\t\ttotal proc. time:   " << 1e-6 * acc_duration_capture_.count() << " s"
             << "\n\t\taverage proc. time: " << 1e-3 * acc_duration_capture_.count() / n_capture_callback_ << " ms"
             << " (" << average_proc_cap_percent << "%)"
+            << "\n\t\tstd dev proc. time: " << 1e-3 * sqrt(var_duration_capture_) << " ms"
+            << " (" << stdev_proc_cap_percent << "%)"
             << "\n\t\tmax proc. time:     " << 1e-3 * max_duration_capture_.count() << " ms"
             << " (" << max_proc_cap_percent << "%)"
             << "\n\tProcessing keyframes:"
             << "\n\t\tkf processed:       " << n_kf_callback_
-            << "\n\t\taverage period:     " << 1e-3 * kf_average_period << " ms"
+            << "\n\t\taverage period:     " << kf_average_period << " s"
             << "\n\t\ttotal proc. time:   " << 1e-6 * acc_duration_kf_.count() << " s"
             << "\n\t\taverage proc. time: " << 1e-3 * acc_duration_kf_.count() / n_kf_callback_ << " ms"
             << " (" << average_proc_kf_percent << "%)"
+            << "\n\t\tstd dev proc. time: " << 1e-3 * sqrt(var_duration_kf_) << " ms"
+            << " (" << std_dev_proc_kf_percent << "%)"
             << "\n\t\tmax proc. time:     " << 1e-3 * max_duration_kf_.count() << " ms"
             << " (" << max_proc_kf_percent << "%)" << std::endl;
 }