From 45c1559023a422016965d10d6b02b9bbbb20f3a1 Mon Sep 17 00:00:00 2001
From: joanvallve <jvallve@iri.upc.edu>
Date: Tue, 14 Jan 2025 16:21:13 +0100
Subject: [PATCH] profiling unit implemented and working
---
CMakeLists.txt | 1 +
include/core/common/profiling_unit.h | 208 +++++++++++++---------
include/core/processor/processor_base.h | 61 ++-----
src/common/profiling_unit.cpp | 139 +++++++++++++++
src/problem/problem.cpp | 1 +
src/processor/processor_base.cpp | 79 +++------
test/CMakeLists.txt | 18 +-
test/gtest_profiling_unit.cpp | 220 ++++++++++++++++++++++++
8 files changed, 533 insertions(+), 194 deletions(-)
create mode 100644 src/common/profiling_unit.cpp
create mode 100644 test/gtest_profiling_unit.cpp
diff --git a/CMakeLists.txt b/CMakeLists.txt
index ed049c6c3..dab498ba7 100644
--- a/CMakeLists.txt
+++ b/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
diff --git a/include/core/common/profiling_unit.h b/include/core/common/profiling_unit.h
index b25b58000..90a3fc160 100644
--- a/include/core/common/profiling_unit.h
+++ b/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
diff --git a/include/core/processor/processor_base.h b/include/core/processor/processor_base.h
index 6ce77b5f7..305db223a 100644
--- a/include/core/processor/processor_base.h
+++ b/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
diff --git a/src/common/profiling_unit.cpp b/src/common/profiling_unit.cpp
new file mode 100644
index 000000000..19fdab32c
--- /dev/null
+++ b/src/common/profiling_unit.cpp
@@ -0,0 +1,139 @@
+// 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
diff --git a/src/problem/problem.cpp b/src/problem/problem.cpp
index 4055a51c4..6d4bbe712 100644
--- a/src/problem/problem.cpp
+++ b/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);
diff --git a/src/processor/processor_base.cpp b/src/processor/processor_base.cpp
index 52864d47e..78d716785 100644
--- a/src/processor/processor_base.cpp
+++ b/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
diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt
index e924582eb..31836743b 100644
--- a/test/CMakeLists.txt
+++ b/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)
diff --git a/test/gtest_profiling_unit.cpp b/test/gtest_profiling_unit.cpp
new file mode 100644
index 000000000..ec35836b2
--- /dev/null
+++ b/test/gtest_profiling_unit.cpp
@@ -0,0 +1,220 @@
+// 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
--
GitLab