profiling unit implemented and working

CMakeLists.txt

@@ -120,6 +120,7 @@ SET(SRCS
   # common
   src/common/node_base.cpp
   src/common/node_state_blocks.cpp
+  src/common/profiling_unit.cpp
   src/common/time_stamp.cpp
   # composite
   src/composite/prior_composite.cpp

include/core/common/profiling_unit.h

@@ -20,123 +20,169 @@
 
 #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;
+#include <chrono>
+#include <cmath>
 
 namespace wolf
 {
 /**
- * \brief TimeStamp implements basic functionalities for time stamps
+ * @class ProfilingUnit
+ * @brief A class for profiling code execution time and statistics.
  *
- * TimeStamp implements basic functionalities for time stamps
+ * The ProfilingUnit class provides methods to start and stop profiling, and to
+ * print profiling results.
  */
 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_;
+    bool                      running_;         ///< True if profiling is running.
+    double                    desired_period_;  ///< Desired period in microseconds (< 0 for not specified)
+    unsigned int              n_callbacks_;     ///< Number of callbacks.
+    double                    average_period_;  ///< Average period in microseconds.
+    std::chrono::microseconds acc_duration_;    ///< Accumulated duration in microseconds.
+    std::chrono::microseconds max_duration_;    ///< Maximum duration in microseconds.
+    double                    var_duration_;    ///< Variance of the duration in microseconds squared.
+    std::chrono::time_point<std::chrono::high_resolution_clock> first_clock_;  ///< Time point of the first clock.
+    std::chrono::time_point<std::chrono::high_resolution_clock> start_clock_;  ///< Time point of the start clock.
 
   public:
-    /** \brief Constructor
-     *
-     * Constructor without arguments. Sets time stamp to now.
-     *
+    /**
+     * @brief Constructor
+     * @param desired_period_sec Desired period in seconds. Negative value means not specified. Default is -1.
      */
     ProfilingUnit(double desired_period_sec = -1);
 
+    /**
+     * @brief Start profiling.
+     */
     void startProfiling();
 
+    /**
+     * @brief Stop profiling.
+     */
     void stopProfiling();
 
-    void printProfiling(std::ostream& stream = std::cout) const;
+    /**
+     * @brief Print profiling results.
+     * @param _tabs Tabs to be used for indentation.
+     * @param stream Output stream to print the results. Default is std::cout.
+     */
+    void printProfiling(const std::string& _tabs, std::ostream& stream = std::cout) const;
+
+    /**
+     * @brief Print provided duration (in us) in the most appropiate units with specified precision.
+     * @param _duration_microsec Duration in microseconds.
+     * @param precision Precision for printing the duration. Default is 2.
+     * @return A string representing the duration.
+     */
+    std::string printDuration(double _duration_microsec, int precision = 2) const;
+
+    /**
+     * @brief Set the desired period.
+     * @param _desired_period_sec Desired period in seconds.
+     */
+    void setDesiredPeriod(double _desired_period_sec);
+
+    /**
+     * @brief Check if profiling is running.
+     * @return True if profiling is running, false otherwise.
+     */
+    bool isRunning() const;
+
+    /**
+     * @brief Get the number of callbacks.
+     * @return Number of callbacks.
+     */
+    unsigned int getNCallbacks() const;
+
+    /**
+     * @brief Get the desired period.
+     * @return Desired period in seconds.
+     */
+    double getDesiredPeriod() const;
+
+    /**
+     * @brief Get the average period.
+     * @return Average period in seconds.
+     */
+    double getAveragePeriod() const;
+
+    /**
+     * @brief Get the accumulated duration.
+     * @return Accumulated duration in seconds.
+     */
+    double getAccDuration() const;
+
+    /**
+     * @brief Get the average duration.
+     * @return Average duration in seconds.
+     */
+    double getAvgDuration() const;
+
+    /**
+     * @brief Get the maximum duration.
+     * @return Maximum duration in seconds.
+     */
+    double getMaxDuration() const;
+
+    /**
+     * @brief Get the variance of the duration.
+     * @return Variance of the duration in seconds squared.
+     */
+    double getVarDuration() const;
 
-    std::stringstream printDuration(double _duration_ms, int precision = 2) const;
+    /**
+     * @brief Get the standard deviation of the duration.
+     * @return Standard deviation of the duration in seconds.
+     */
+    double getStDevDuration() 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 bool ProfilingUnit::isRunning() const
+{
+    return running_;
+}
+
+inline unsigned int ProfilingUnit::getNCallbacks() const
+{
+    return n_callbacks_;
+}
+
+inline double ProfilingUnit::getDesiredPeriod() const
+{
+    return 1e-6 * desired_period_;
+}
+
+inline double ProfilingUnit::getAveragePeriod() const
+{
+    return 1e-6 * average_period_;
+}
+
+inline double ProfilingUnit::getAccDuration() const
 {
+    return 1e-6 * acc_duration_.count();
 }
 
-inline void ProfilingUnit::startCaptureProfiling()
+inline double ProfilingUnit::getAvgDuration() const
 {
-    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);
-    }
+    return 1e-6 * acc_duration_.count() / n_callbacks_;
 }
 
-inline void ProfilingUnit::stopCaptureProfiling()
+inline double ProfilingUnit::getMaxDuration() const
 {
-    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);
+    return 1e-6 * max_duration_.count();
 }
 
-inline std::stringstream ProfilingUnit::printDuration(double _duration_microsec, int precision) const
+inline double ProfilingUnit::getVarDuration() 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;
+    return 1e-12 * var_duration_;
 }
 
-inline void ProcessorBase::printProfiling(std::ostream& _stream) const
+inline double ProfilingUnit::getStDevDuration() 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 << "%)"                                                //
+    return 1e-6 * sqrt(var_duration_);
 }
 
 }  // namespace wolf

include/core/processor/processor_base.h

@@ -29,6 +29,7 @@
 #include "core/frame/frame_base.h"
 #include "core/common/time_stamp.h"
 #include "core/processor/buffer.h"
+#include "core/common/profiling_unit.h"
 
 // std
 #include <memory>
@@ -127,26 +128,18 @@ class ProcessorBase : public NodeBase, public std::enable_shared_from_this<Proce
     static unsigned int processor_id_count_;
 
     // CHECKING captures period and time_tolerance
-    double    capture_period_max_, capture_period_min_, capture_period_mean_;
+    double    capture_period_mean_;
     TimeStamp prev_capture_stamp_;
 
-  public:
     // PROFILING
-    unsigned int                                                n_capture_callback_;
-    unsigned int                                                n_kf_callback_;
-    std::chrono::microseconds                                   acc_duration_capture_;
-    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();
-    void                                                        stopCaptureProfiling();
-    void                                                        startKFProfiling();
-    void                                                        stopKFProfiling();
-    void                                                        printProfiling(std::ostream& stream = std::cout) const;
+    ProfilingUnit profiling_capture_, profiling_kf_;
+
+  public:
+    void startCaptureProfiling();
+    void stopCaptureProfiling();
+    void startKFProfiling();
+    void stopKFProfiling();
+    void printProfiling(std::ostream& stream = std::cout) const;
 
     /** \brief constructor
      *
@@ -286,42 +279,12 @@ inline bool ProcessorBase::hasChildren() const
 
 inline void ProcessorBase::startCaptureProfiling()
 {
-    start_capture_ = std::chrono::high_resolution_clock::now();
-}
-
-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);
+    profiling_capture_.startProfiling();
 }
 
 inline void ProcessorBase::startKFProfiling()
 {
-    start_kf_ = std::chrono::high_resolution_clock::now();
-}
-
-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);
+    profiling_kf_.startProfiling();
 }
 
 inline YAML::Node ProcessorBase::getParams() const

src/common/profiling_unit.cpp

+// 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/>.
+
+#include "core/common/profiling_unit.h"
+#include <cassert>
+
+namespace wolf
+{
+
+ProfilingUnit::ProfilingUnit(double desired_period_sec)
+    : running_(false),
+      desired_period_(1e6 * desired_period_sec),
+      n_callbacks_(0),
+      average_period_(0),
+      acc_duration_(0),
+      max_duration_(0),
+      var_duration_(0)
+{
+}
+
+void ProfilingUnit::startProfiling()
+{
+    if (running_) throw std::runtime_error("ProfilingUnit::startProfiling: profiling already running");
+
+    n_callbacks_++;
+    running_     = true;
+    start_clock_ = std::chrono::high_resolution_clock::now();
+}
+
+void ProfilingUnit::stopProfiling()
+{
+    if (not running_) return;
+
+    assert(n_callbacks_ > 0);
+
+    // compute duration first of all
+    auto duration = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() -
+                                                                          start_clock_);
+
+    // average period
+    if (n_callbacks_ == 1)
+        first_clock_ = start_clock_;
+    else
+    {
+        auto duration_from_start = std::chrono::duration_cast<std::chrono::microseconds>(start_clock_ - first_clock_);
+        average_period_          = duration_from_start.count() / (n_callbacks_ - 1);
+    }
+
+    // recursive formula for variance: https://math.stackexchange.com/a/2746016
+    if (n_callbacks_ == 1)
+        var_duration_ = 0;
+    else  // n_callbacks_ > 1
+    {
+        double n_callbacks_d      = n_callbacks_;
+        auto   prev_mean_duration = acc_duration_.count() / (n_callbacks_d - 1);
+        var_duration_             = ((n_callbacks_d - 1) / n_callbacks_d) *
+                        (var_duration_ + std::pow(prev_mean_duration - duration.count(), 2) / n_callbacks_d);
+    }
+    // max and accumulated duration
+    max_duration_ = std::max(max_duration_, duration);
+    acc_duration_ += duration;
+
+    running_ = false;
+}
+
+std::string ProfilingUnit::printDuration(double _duration_microsec, int precision) const
+{
+    std::stringstream stream;
+    if (_duration_microsec >= 3600 * 1e6)
+    {
+        auto hours   = static_cast<int>(_duration_microsec / (3600 * 1e6));
+        auto minutes = static_cast<int>((_duration_microsec - hours * 3600 * 1e6) / (60 * 1e6));
+        auto seconds = (_duration_microsec - hours * 3600 * 1e6 - minutes * 60 * 1e6) * 1e-6;
+        stream << hours << " h " << minutes << " min " << std::fixed << std::setprecision(precision) << seconds
+               << " s";
+    }
+    else if (_duration_microsec >= 60 * 1e6)
+    {
+        auto minutes = static_cast<int>(_duration_microsec / (60 * 1e6));
+        auto seconds = (_duration_microsec - minutes * 60 * 1e6) * 1e-6;
+        stream << minutes << " min " << std::fixed << std::setprecision(precision) << seconds << " s";
+    }
+    else 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.str();
+}
+
+void ProfilingUnit::printProfiling(const std::string& _tabs, 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"
+            << _tabs << "instances:      " << n_callbacks_  //
+            << "\n"
+            << _tabs << "total time:     " << printDuration(acc_duration_.count())  //
+            << "\n";
+    if (desired_period_ > 0)
+        _stream << _tabs << "desired period: " << printDuration(desired_period_)  //
+                << " (reference)\n";
+    _stream << _tabs << "avg period:     " << printDuration(average_period_)  //
+            << (desired_period_ > 0 ? "\n" : " (reference)\n")
+            << _tabs << "avg time:       " << printDuration(acc_duration_.count() / n_callbacks_)  //
+            << " (" << average_percent << "%)"
+            << "\n"
+            << _tabs << "stdev time:     " << printDuration(sqrt(var_duration_))  //
+            << " (" << stdev_percent << "%)"
+            << "\n"
+            << _tabs << "max time:       " << printDuration(max_duration_.count())  //
+            << " (" << max_percent << "%)";
+}
+
+}  // namespace wolf

src/problem/problem.cpp

@@ -868,6 +868,7 @@ void Problem::keyFrameCallback(FrameBasePtr _keyframe_ptr, ProcessorBasePtr _pro
     // pause processor profiling
     if (_processor_ptr) _processor_ptr->stopCaptureProfiling();
 
+    // notify other processors
     for (auto sensor : hardware_ptr_->getSensorList())
         for (auto processor : sensor->getProcessorList())
             if (processor && (processor != _processor_ptr)) processor->keyFrameCallback(_keyframe_ptr);

src/processor/processor_base.cpp

@@ -33,18 +33,8 @@ ProcessorBase::ProcessorBase(const std::string& _type, unsigned int _dim_compati
       params_(Clone(_params)),
       dim_compatible_(_dim_compatible),
       sensor_ptr_(),
-      capture_period_max_(0),
-      capture_period_min_(1e12),
       capture_period_mean_(0),
-      prev_capture_stamp_(TimeStamp::Invalid()),
-      n_capture_callback_(0),
-      n_kf_callback_(0),
-      acc_duration_capture_(0),
-      acc_duration_kf_(0),
-      max_duration_capture_(0),
-      max_duration_kf_(0),
-      var_duration_capture_(0),
-      var_duration_kf_(0)
+      prev_capture_stamp_(TimeStamp::Invalid())
 {
     assert(dim_compatible_ == 0 or dim_compatible_ == 2 or dim_compatible_ == 3);
     WOLF_DEBUG("Constructed ProcessorBase - ", getType(), " id: ", id(), " name: ", getName());
@@ -69,7 +59,6 @@ void ProcessorBase::keyFrameCallback(FrameBasePtr _keyframe)
                _keyframe->getTimeStamp());
 
     // profiling
-    n_kf_callback_++;
     startKFProfiling();
 
     // asking if frame should be stored
@@ -94,18 +83,16 @@ void ProcessorBase::captureCallback(CaptureBasePtr _capture)
                _capture->getTimeStamp());
 
     // profiling
-    n_capture_callback_++;
     startCaptureProfiling();
 
     // CHECKING captures period and time_tolerance
-    if (n_capture_callback_ > 1)
+    if (profiling_capture_.getNCallbacks() > 1)
     {
         assert(prev_capture_stamp_.ok());
 
         double dt            = _capture->getTimeStamp() - prev_capture_stamp_;
-        capture_period_mean_ = ((n_capture_callback_ - 2) * capture_period_mean_ + dt) / (n_capture_callback_ - 1);
-        capture_period_min_  = std::min(dt, capture_period_min_);
-        capture_period_max_  = std::max(dt, capture_period_max_);
+        double n_captures    = profiling_capture_.getNCallbacks();
+        capture_period_mean_ = ((n_captures - 2) * capture_period_mean_ + dt) / (n_captures - 1);
 
         WOLF_ERROR_COND(capture_period_mean_ < getTimeTolerance() * 2,
                         getType(),
@@ -240,50 +227,28 @@ bool ProcessorBase::check(CheckLog& _log, bool _verbose, std::ostream& _stream,
     return _log.is_consistent_;
 }
 
-void ProcessorBase::printProfiling(std::ostream& _stream) const
+void ProcessorBase::stopCaptureProfiling()
 {
-    unsigned int kf_average_period =
-        (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 * 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 * 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 * 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 * 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;
+    profiling_capture_.stopProfiling();
+}
 
+void ProcessorBase::stopKFProfiling()
+{
+    profiling_kf_.stopProfiling();
+}
+
+void ProcessorBase::printProfiling(std::ostream& _stream) const
+{
     _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:     " << 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:     " << 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;
+            << "\n\ttotal time:             "
+            << profiling_capture_.printDuration(1e6 *
+                                                (profiling_capture_.getAccDuration() + profiling_kf_.getAccDuration()))
+            << "\n\tProcessing captures:";
+    profiling_capture_.printProfiling("\t\t", _stream);
+    _stream << "\n\tProcessing keyframes:";
+    profiling_kf_.printProfiling("\t\t", _stream);
+    _stream << std::endl;
 }
 
 bool ProcessorBase::checkTimeTolerance(const TimeStamp& _ts1, const TimeStamp& _ts2) const

test/CMakeLists.txt

@@ -50,6 +50,10 @@ wolf_add_gtest(gtest_capture_base gtest_capture_base.cpp)
 # Composite class test
 wolf_add_gtest(gtest_composite gtest_composite.cpp)
 
+# Emplace test
+wolf_add_gtest(gtest_emplace gtest_emplace.cpp)
+target_link_libraries(gtest_emplace PUBLIC wolfcore_dummy)
+
 # FactorBase class test
 wolf_add_gtest(gtest_factor_base gtest_factor_base.cpp)
 
@@ -66,10 +70,6 @@ target_link_libraries(gtest_factory PUBLIC wolfcore_dummy)
 # FactoryStateBlock factory test
 wolf_add_gtest(gtest_factory_state_block gtest_factory_state_block.cpp)
 
-# Node Emplace test
-wolf_add_gtest(gtest_emplace gtest_emplace.cpp)
-target_link_libraries(gtest_emplace PUBLIC wolfcore_dummy)
-
 # FeatureBase classes test
 wolf_add_gtest(gtest_feature_base gtest_feature_base.cpp)
 
@@ -79,9 +79,6 @@ wolf_add_gtest(gtest_frame_base gtest_frame_base.cpp)
 # GraphSearch class test
 wolf_add_gtest(gtest_graph_search gtest_graph_search.cpp)
 
-# MotionProvider classes test
-wolf_add_gtest(gtest_motion_provider gtest_motion_provider.cpp)
-target_link_libraries(gtest_motion_provider PUBLIC wolfcore_dummy)
 
 # LocalParametrizationXxx classes test
 wolf_add_gtest(gtest_loader gtest_loader.cpp)
@@ -92,6 +89,10 @@ wolf_add_gtest(gtest_local_param gtest_local_param.cpp)
 # Logging test
 wolf_add_gtest(gtest_logging gtest_logging.cpp)
 
+# MotionProvider classes test
+wolf_add_gtest(gtest_motion_provider gtest_motion_provider.cpp)
+target_link_libraries(gtest_motion_provider PUBLIC wolfcore_dummy)
+
 # MotionBuffer class test
 wolf_add_gtest(gtest_motion_buffer gtest_motion_buffer.cpp)
 
@@ -109,6 +110,9 @@ target_link_libraries(gtest_processor_base PUBLIC wolfcore_dummy)
 # ProcessorMotion class test
 wolf_add_gtest(gtest_processor_motion gtest_processor_motion.cpp)
   
+# ProfilingUnit class test
+wolf_add_gtest(gtest_profiling_unit gtest_profiling_unit.cpp)
+
 # Rotation test
 wolf_add_gtest(gtest_rotation gtest_rotation.cpp)
 

test/gtest_profiling_unit.cpp

+// 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/>.
+
+#include "core/utils/utils_gtest.h"
+#include "core/common/profiling_unit.h"
+#include <thread>
+#include <list>
+
+using namespace wolf;
+
+TEST(ProfilingUnitTest, ConstructorInitializesCorrectly)
+{
+    ProfilingUnit prof_unit(1.0);
+
+    EXPECT_EQ(prof_unit.getDesiredPeriod(), 1);
+    EXPECT_EQ(prof_unit.getNCallbacks(), 0);
+    EXPECT_EQ(prof_unit.getAveragePeriod(), 0);
+    EXPECT_EQ(prof_unit.getAccDuration(), 0);
+    EXPECT_EQ(prof_unit.getMaxDuration(), 0);
+    EXPECT_EQ(prof_unit.getVarDuration(), 0);
+}
+
+TEST(ProfilingUnitTest, StartProfilingUpdatesCorrectly)
+{
+    ProfilingUnit prof_unit(1.0);
+
+    prof_unit.startProfiling();
+    EXPECT_EQ(prof_unit.getNCallbacks(), 1);
+
+    EXPECT_THROW(prof_unit.startProfiling(), std::runtime_error);
+    std::this_thread::sleep_for(std::chrono::milliseconds(10));
+
+    prof_unit.stopProfiling();
+    prof_unit.startProfiling();
+    EXPECT_EQ(prof_unit.getNCallbacks(), 2);
+    EXPECT_GT(prof_unit.getAccDuration(), 0);
+    EXPECT_GT(prof_unit.getAvgDuration(), 0);
+    EXPECT_GT(prof_unit.getMaxDuration(), 0);
+}
+
+TEST(ProfilingUnitTest, StopProfilingUpdatesCorrectly)
+{
+    ProfilingUnit prof_unit(1.0);
+
+    prof_unit.startProfiling();
+    std::this_thread::sleep_for(std::chrono::milliseconds(100));
+    prof_unit.stopProfiling();
+
+    EXPECT_NEAR(prof_unit.getAccDuration(), 0.1, 1e-2);
+    EXPECT_NEAR(prof_unit.getAvgDuration(), 0.1, 1e-2);
+    EXPECT_NEAR(prof_unit.getMaxDuration(), 0.1, 1e-2);
+    EXPECT_NEAR(prof_unit.getVarDuration(), 0, 1e-12);
+
+    prof_unit.startProfiling();
+    std::this_thread::sleep_for(std::chrono::milliseconds(200));
+    prof_unit.stopProfiling();
+
+    EXPECT_GT(prof_unit.getAveragePeriod(), 0);
+
+    EXPECT_NEAR(prof_unit.getAccDuration(), 0.3, 1e-2);
+    EXPECT_NEAR(prof_unit.getAvgDuration(), 0.15, 1e-2);
+    EXPECT_NEAR(prof_unit.getMaxDuration(), 0.2, 1e-2);
+}
+
+TEST(ProfilingUnitTest, ProfilingUnitTest_statistics_Test)
+{
+    ProfilingUnit prof_unit;
+
+    std::list<double> durations;
+    double            acc_duration = 0;
+    double            max_duration = 0;
+    double            avg_duration = 0;
+    double            var_duration = 0;
+    int               n_samples    = 10;
+
+    std::chrono::high_resolution_clock::time_point start, stop;
+
+    for (auto i = 0; i < n_samples; i++)
+    {
+        int    random_ms     = rand() % 100;
+        double prev_duration = prof_unit.getAccDuration();
+        prof_unit.startProfiling();
+        start = std::chrono::high_resolution_clock::now();
+        std::this_thread::sleep_for(std::chrono::milliseconds(random_ms));
+        stop = std::chrono::high_resolution_clock::now();
+        prof_unit.stopProfiling();
+
+        // Check measured duration
+        auto meas_duration_us = std::chrono::duration_cast<std::chrono::microseconds>(stop - start);
+        auto duration         = prof_unit.getAccDuration() - prev_duration;
+
+        EXPECT_NEAR(1e-6 * meas_duration_us.count(), 1e-3 * random_ms, 1e-2);
+        EXPECT_NEAR(1e-6 * meas_duration_us.count(), duration, 1e-5);
+
+        durations.push_back(duration);
+        acc_duration += duration;
+
+        if (durations.back() > max_duration)
+        {
+            max_duration = durations.back();
+        }
+    }
+    avg_duration = acc_duration / n_samples;
+
+    for (auto duration : durations)
+    {
+        var_duration += std::pow(duration - avg_duration, 2);
+    }
+    var_duration /= n_samples;
+
+    EXPECT_NEAR(prof_unit.getAccDuration(), acc_duration, 1e-9);
+    EXPECT_NEAR(prof_unit.getAvgDuration(), avg_duration, 1e-9);
+    EXPECT_NEAR(prof_unit.getMaxDuration(), max_duration, 1e-9);
+    EXPECT_NEAR(prof_unit.getVarDuration(), var_duration, 1e-9);
+    EXPECT_NEAR(prof_unit.getStDevDuration(), std::sqrt(var_duration), 1e-9);
+}
+
+TEST(ProfilingUnitTest, PrintDurationFormatsCorrectly)
+{
+    ProfilingUnit prof_unit(1.0);
+
+    EXPECT_EQ(prof_unit.printDuration(3600 * 1e6), "1 h 0 min 0.00 s");
+    EXPECT_EQ(prof_unit.printDuration(60 * 1e6), "1 min 0.00 s");
+    EXPECT_EQ(prof_unit.printDuration(1e6), "1.00 s");
+    EXPECT_EQ(prof_unit.printDuration(1e3), "1.00 ms");
+    EXPECT_EQ(prof_unit.printDuration(1), "1.00 us");
+}
+
+TEST(ProfilingUnitTest, PrintProfilingOutputsWithDesiredPeriod)
+{
+    ProfilingUnit prof_unit(1.0);
+
+    prof_unit.startProfiling();
+    std::this_thread::sleep_for(std::chrono::milliseconds(10));
+    prof_unit.stopProfiling();
+
+    std::stringstream ss;
+    prof_unit.printProfiling("", ss);
+
+    std::cout << ss.str() << std::endl;
+
+    std::string output = ss.str();
+    EXPECT_NE(output.find("instances:      1"), std::string::npos);
+    EXPECT_NE(output.find(std::string("desired period: ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getDesiredPeriod())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("avg period:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAveragePeriod())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("total time:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAccDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("avg time:       ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAvgDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("stdev time:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getStDevDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("max time:       ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getMaxDuration())),
+              std::string::npos);
+}
+
+TEST(ProfilingUnitTest, PrintProfilingOutputs)
+{
+    ProfilingUnit prof_unit;
+
+    prof_unit.startProfiling();
+    std::this_thread::sleep_for(std::chrono::milliseconds(10));
+    prof_unit.stopProfiling();
+
+    std::stringstream ss;
+    prof_unit.printProfiling("", ss);
+
+    std::cout << ss.str() << std::endl;
+
+    std::string output = ss.str();
+    EXPECT_NE(output.find("instances:      1"), std::string::npos);
+    EXPECT_EQ(output.find(std::string("desired period: ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getDesiredPeriod())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("avg period:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAveragePeriod())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("total time:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAccDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("avg time:       ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getAvgDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("stdev time:     ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getStDevDuration())),
+              std::string::npos);
+    EXPECT_NE(output.find(std::string("max time:       ") +  //
+                          prof_unit.printDuration(1e6 * prof_unit.getMaxDuration())),
+              std::string::npos);
+}
+
+int main(int argc, char **argv)
+{
+    ::testing::InitGoogleTest(&argc, argv);
+    return RUN_ALL_TESTS();
+}
\ No newline at end of file