From 2125c7e93c286d05bd306826118cfc8b8d5a434f Mon Sep 17 00:00:00 2001 From: Yifei Wu Date: Wed, 13 Aug 2025 12:01:25 -0700 Subject: [PATCH] add hierarachical time breakdown feature --- src/oops/util/Timer.cc | 30 +++++++++++----- src/oops/util/Timer.h | 3 ++ src/oops/util/TimerHelper.cc | 32 +++++++++++++++++ src/oops/util/TimerHelper.h | 5 +++ src/oops/util/TimerTree.h | 68 ++++++++++++++++++++++++++++++++++++ 5 files changed, 130 insertions(+), 8 deletions(-) create mode 100644 src/oops/util/TimerTree.h diff --git a/src/oops/util/Timer.cc b/src/oops/util/Timer.cc index e8b671568..81ebef500 100644 --- a/src/oops/util/Timer.cc +++ b/src/oops/util/Timer.cc @@ -25,22 +25,36 @@ static int nested_timers = 0; // Only non-nested timers count towards measured // ----------------------------------------------------------------------------- Timer::Timer(const std::string & class_name, const std::string & method_name) - : name_(class_name + "::" + method_name), start_() + : name_(class_name + "::" + method_name), start_(), stopped_(false) { ++nested_timers; start_ = ClockT::now(); + // create a new node in timer tree + TimerHelper::setCurrentTree(TimerHelper::getCurrentTree()->goDown(name_)); +} + +void Timer::stop() { + if (!stopped_) { + stopped_ = true; + std::chrono::duration dt = ClockT::now() - start_; // elapsed millisecs + --nested_timers; + // A top-level timer is created (when nested_timers == 0) in TimerHelper::start() for total time. + // To count measured time (and establish timer coverage), we sum times from the timers 1 level + // below this top-level timer. More-deeply nested timers would duplicate time if included. + const bool include_timer_in_sum = (nested_timers == 1); + TimerHelper::add(name_, dt.count(), include_timer_in_sum); + // time will be added in tree strcture anyway + TimerHelper::getCurrentTree()->addTime(dt.count()); + TimerHelper::setCurrentTree(TimerHelper::getCurrentTree()->goUp()); + } } // ----------------------------------------------------------------------------- Timer::~Timer() { - std::chrono::duration dt = ClockT::now() - start_; // elapsed millisecs - --nested_timers; - // A top-level timer is created (when nested_timers == 0) in TimerHelper::start() for total time. - // To count measured time (and establish timer coverage), we sum times from the timers 1 level - // below this top-level timer. More-deeply nested timers would duplicate time if included. - const bool include_timer_in_sum = (nested_timers == 1); - TimerHelper::add(name_, dt.count(), include_timer_in_sum); + if (!stopped_) { + stop(); + } } // ----------------------------------------------------------------------------- diff --git a/src/oops/util/Timer.h b/src/oops/util/Timer.h index 8b82614c2..e40152ef8 100644 --- a/src/oops/util/Timer.h +++ b/src/oops/util/Timer.h @@ -28,9 +28,12 @@ class Timer { Timer(const Timer&) = delete; // Non-copyable + void stop(); + private: std::string name_; TimeT start_; + bool stopped_; }; // ----------------------------------------------------------------------------- diff --git a/src/oops/util/TimerHelper.cc b/src/oops/util/TimerHelper.cc index d6a522854..aa5b1802d 100644 --- a/src/oops/util/TimerHelper.cc +++ b/src/oops/util/TimerHelper.cc @@ -24,6 +24,9 @@ namespace util { +TimerTree* TimerHelper::ttree_ptr_root_ = nullptr; +TimerTree* TimerHelper::ttree_ptr_current_ = nullptr; + // ----------------------------------------------------------------------------- TimerHelper & TimerHelper::getHelper() { @@ -35,6 +38,8 @@ TimerHelper & TimerHelper::getHelper() { void TimerHelper::start() { getHelper().on_ = true; + getHelper().ttree_ptr_root_ = new TimerTree("root"); + getHelper().ttree_ptr_current_ = getHelper().ttree_ptr_root_; getHelper().total_.reset(new Timer("util::Timers", "Total")); getHelper().timers_["util::Timers::measured"] = 0.0; getHelper().counts_["util::Timers::measured"] = 1; @@ -48,6 +53,9 @@ void TimerHelper::stop() { getHelper().timers_.clear(); getHelper().counts_.clear(); getHelper().on_ = false; + delete getHelper().ttree_ptr_root_; + getHelper().ttree_ptr_root_ = nullptr; + getHelper().ttree_ptr_current_ = nullptr; } // ----------------------------------------------------------------------------- @@ -185,8 +193,32 @@ void TimerHelper::print(std::ostream & os) const { os << std::string(std::floor(title_half_width), '-') << title << std::string(std::ceil(title_half_width), '-') << std::endl; } + + // Print hierarchical timer tree structure + if (ttree_ptr_root_ != nullptr) { + os << std::endl; + os << std::string(table_width, '-') << std::endl; + std::string tree_title = " Hierarchical Timer Tree"; + float tree_title_half_width = (table_width - tree_title.size()) / 2.; + os << std::string(std::floor(tree_title_half_width), '-') + << tree_title << std::string(std::ceil(tree_title_half_width), '-') << std::endl; + os << std::string(table_width, '-') << std::endl; + + // Print the tree structure starting from root + ttree_ptr_root_->printTree(os); + + os << std::string(table_width, '-') << std::endl; + } + } +TimerTree* TimerHelper::getCurrentTree() { + return ttree_ptr_current_; +} + +void TimerHelper::setCurrentTree(TimerTree* ttree) { + ttree_ptr_current_ = ttree; +} // ----------------------------------------------------------------------------- } // namespace util diff --git a/src/oops/util/TimerHelper.h b/src/oops/util/TimerHelper.h index 38dc0982c..f8ccbae5b 100644 --- a/src/oops/util/TimerHelper.h +++ b/src/oops/util/TimerHelper.h @@ -21,6 +21,7 @@ #include "eckit/mpi/Comm.h" #include "oops/mpi/mpi.h" #include "oops/util/Printable.h" +#include "oops/util/TimerTree.h" namespace util { class Timer; @@ -35,10 +36,14 @@ class TimerHelper : public util::Printable, static void add(const std::string &, const double, const bool); // const std::chrono::duration &); static void setComm(const eckit::mpi::Comm & comm); + static TimerTree* getCurrentTree(); + static void setCurrentTree(TimerTree* ttree); ~TimerHelper(); private: static TimerHelper & getHelper(); + static TimerTree* ttree_ptr_root_; + static TimerTree* ttree_ptr_current_; TimerHelper(); void print(std::ostream &) const; diff --git a/src/oops/util/TimerTree.h b/src/oops/util/TimerTree.h new file mode 100644 index 000000000..f56ce9773 --- /dev/null +++ b/src/oops/util/TimerTree.h @@ -0,0 +1,68 @@ +#ifndef OOPS_UTIL_TIMER_TREE_H_ +#define OOPS_UTIL_TIMER_TREE_H_ + +#include +#include +#include +#include +#include + +#include "oops/util/Timer.h" + +namespace util { + +class TimerTree { + public: + TimerTree(const std::string & name): name_(name), time_count_(0), called_count_(0), parent_(nullptr) {} + ~TimerTree() { + for (std::map::iterator it = children_.begin(); it != children_.end(); ++it) { + delete it->second; + } + } + TimerTree* goDown(const std::string & name) { + if (children_.find(name) == children_.end()) { + children_[name] = new TimerTree(name); + children_[name]->parent_ = this; + } + return children_[name]; + } + TimerTree* goUp() { + return parent_; + } + void addTime(const int time) { + time_count_ += time; + ++called_count_; + } + + // Print hierarchical tree structure like Unix 'tree' command + void printTree(std::ostream& os, const std::string& prefix = "", bool isLast = true) const { + // Print current node + os << prefix; + os << (isLast ? "└── " : "├── "); + os << name_ << " (" << std::fixed << std::setprecision(2) << time_count_ << " ms, " + << called_count_ << " calls)" << std::endl; + + // Print children + if (!children_.empty()) { + auto it = children_.begin(); + for (size_t i = 0; i < children_.size(); ++i, ++it) { + bool childIsLast = (i == children_.size() - 1); + std::string childPrefix = prefix + (isLast ? " " : "│ "); + it->second->printTree(os, childPrefix, childIsLast); + } + } + } + + private: + std::string name_; + int time_count_, called_count_; + TimerTree* parent_; + std::map children_; +}; +} + + + + + +#endif // OOPS_UTIL_TIMER_TREE_H_ \ No newline at end of file