diff --git a/include/core/common/profiling_unit.h b/include/core/common/profiling_unit.h
new file mode 100644
index 0000000000000000000000000000000000000000..b25b5800079d4ac7c6abff0b94ff2314308fb998
--- /dev/null
+++ b/include/core/common/profiling_unit.h
@@ -0,0 +1,142 @@
+// 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
diff --git a/include/core/processor/processor_base.h b/include/core/processor/processor_base.h
index 5be34172c99b14e732fe4c3272f1adc58eea2190..6ce77b5f747cd557a8a6beb446ad95f7d01c91e6 100644
--- a/include/core/processor/processor_base.h
+++ b/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
diff --git a/src/processor/processor_base.cpp b/src/processor/processor_base.cpp
index 72b5bbb2c610e3905c154108df1673025e29fd7e..52864d47e55d5537ff289cbc272ddb2715f5c7cb 100644
--- a/src/processor/processor_base.cpp
+++ b/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;
}