Teuchos_StackedTimer.hpp

// @HEADER BEGIN
// @HEADER END
 
#ifndef TEUCHOS_STACKED_TIMER_HPP
#define TEUCHOS_STACKED_TIMER_HPP
 
#include "Teuchos_ConfigDefs.hpp"
#include "Teuchos_Comm.hpp"
#include "Teuchos_DefaultComm.hpp"
#include "Teuchos_CommHelpers.hpp"
#include "Teuchos_RCP.hpp"
#include "Teuchos_Array.hpp"
#include "Teuchos_PerformanceMonitorBase.hpp"
#include <string>
#include <vector>
#include <cassert>
#include <chrono>
#include <climits>
#include <cstdlib> // for std::getenv
#include <iostream>
 
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
namespace Kokkos {
namespace Profiling {
extern void pushRegion (const std::string&);
extern void popRegion ();
} // namespace Profiling
} // namespace Kokkos
#endif
 
 
namespace Teuchos {
 
void error_out(const std::string& msg, const bool fail_all = false);
 
class BaseTimer {
 
public:
 
  using Clock = std::chrono::high_resolution_clock;
 
  BaseTimer() : accumulation_(0.0), count_started_(0), count_updates_(0), running_(false) {}
 
  void start(){
    if (running_)
      error_out("Base_Timer:start Failed timer already running");
    start_time_ = Clock::now();
 
    count_started_++;
    running_ = true;
  }
 
  void stop(){
    if (!running_)
      error_out("Base_Timer:stop Failed timer not running");
    accumulation_ += std::chrono::duration_cast<std::chrono::duration<double>>(Clock::now() - start_time_).count();
    running_ = false;
  }
 
  unsigned long long incrementUpdates(unsigned long long count=1) {count_updates_ += count; return count_updates_;}
 
  double accumulatedTime() const {return accumulation_;}
 
  void setAccumulatedTime(double accum=0)  {accumulation_=accum;}
  double accumulatedTimePerUpdate() const {
    if (count_updates_ > 0) {
      return accumulation_/count_updates_;
    } else {
      return 0;
    }
  }
 
 
  double accumulatedTimePerTimerCall() const {
    if (count_started_> 0) {
      return accumulation_/count_started_;
    } else {
      return 0;
    }
  }
 
  double difference(const BaseTimer &from) const {
    return accumulation_ - from.accumulation_;
  }
 
  void reset() {
    if (running_)
       error_out("BaseTimer, cannot reset a running timer");
    accumulation_ = 0.0;
    count_started_ = count_updates_ = 0;
  }
 
  bool running() const { return running_;}
 
  unsigned long numCalls() const { return count_started_; }
 
  unsigned long long numUpdates() const { return count_updates_; }
 
  void overrideNumCallsForUnitTesting(const unsigned long num_calls)
  { count_started_ = num_calls; }
 
  void overrideNumUpdatesForUnitTesting(const unsigned long long num_updates)
  { count_updates_ = num_updates; }
 
  struct TimeInfo {
    TimeInfo():time(0.0), count(0), updates(0), running(false){}
    TimeInfo(BaseTimer* t): time(t->accumulation_), count(t->count_started_), updates(t->count_updates_), running(t->running()) {}
    double time;
    unsigned long count;
    unsigned long long updates;
    bool running;
  };
 
protected:
  double accumulation_;       // total time
  unsigned long count_started_; // Number of times this timer has been started
  unsigned long long count_updates_; // Total count of items updated during this timer
  Clock::time_point start_time_;
  bool running_;
 
  friend struct TimeInfo;
};
 
class StackedTimer
{
protected:
 
  class LevelTimer : public BaseTimer {
  protected:
 
    // TODO: implement operator=
 
    unsigned level_;
    std::string name_;
    LevelTimer *parent_;
    std::vector<LevelTimer> sub_timers_;
  public:
    LevelTimer();
 
    LevelTimer(int level,
        const char* name = "RootTimer",
        LevelTimer *parent=nullptr,
        bool start_timer=true) :
          BaseTimer(),
          level_(level),
          name_(name),
          parent_(parent)
    {
      if ( start_timer )
        BaseTimer::start();
 
    }
 
    LevelTimer(const LevelTimer &src) :
      BaseTimer(src), level_(src.level_), name_(src.name_),parent_(src.parent_), sub_timers_(src.sub_timers_)
    {
      for (unsigned i=0;i<sub_timers_.size();++i)
        sub_timers_[i].parent_ = this;
    }
 
    LevelTimer* start(const char* sub_name) {
      for (unsigned i=0;i<sub_timers_.size();i++ )
        if (sub_name == sub_timers_[i].name_ ) {
          sub_timers_[i].BaseTimer::start();
          return &sub_timers_[i];
        }
      sub_timers_.push_back(LevelTimer(level_+1,sub_name,this,true));
      return &sub_timers_[sub_timers_.size()-1];
    }
 
    LevelTimer* stop(const std::string &name = "RootTimer") {
      if (name != name_)
        error_out("Stopping timer "+name+" But top level running timer is "+name_);
      BaseTimer::stop();
      return parent_;
    }
 
 
    std::string get_full_name() const {
      std::string parent_name("");
      if ((parent_ != nullptr))
        parent_name = parent_->get_full_name() + "@";
 
      std::string my_name(name_);
 
      std::string full_name = parent_name + my_name;
      return full_name;
    }
 
    int countTimers() {
      int count=1;
      for (unsigned i=0;i<sub_timers_.size(); ++i)
        count += sub_timers_[i].countTimers();
      return count;
    }
 
    void addTimerNames(Array<std::string> &names, unsigned &pos) {
      names[pos++] = get_full_name();
      for (unsigned i=0;i<sub_timers_.size(); ++i)
        sub_timers_[i].addTimerNames(names, pos);
    }
 
    double accumulatedTime(const std::string &locate_name="") {
 
      if (locate_name == "")
        return BaseTimer::accumulatedTime();
 
      std::string first_name,second_name;
 
      size_t i = locate_name.find_first_of('@');
      if ( i >= locate_name.size() ) {
        first_name = locate_name;
        second_name = "";
      } else {
        first_name.assign(locate_name,0,i);
        second_name.assign(locate_name,i+1,locate_name.size()-i-1);
      }
      for (unsigned j=0;j<sub_timers_.size();++j)
        if ( first_name == sub_timers_[j].name_)
          return sub_timers_[j].accumulatedTime(second_name);
      return 0;
    }
 
  protected:
    void splitString(const std::string &locate_name, std::string &first_name, std::string &second_name) {
      size_t i = locate_name.find_first_of('@');
      if ( i >= locate_name.size() ) {
        first_name = locate_name;
        second_name = "";
      } else {
        first_name.assign(locate_name,0,i);
        second_name.assign(locate_name,i+1,locate_name.size()-i-1);
      }
    }
 
  public:
    double accumulatedTimePerUpdate(const std::string &locate_name="") {
 
       if (locate_name == "")
         return BaseTimer::accumulatedTimePerUpdate();
 
       std::string first_name,second_name;
       splitString(locate_name, first_name, second_name);
 
       for (unsigned j=0;j<sub_timers_.size();j++)
         if ( first_name == sub_timers_[j].name_)
           return sub_timers_[j].accumulatedTimePerUpdate(second_name);
       return 0;
     }
 
     double accumulatedTimePerTimerCall(const std::string &locate_name="") {
 
       if (locate_name == "")
         return BaseTimer::accumulatedTimePerTimerCall();
 
       std::string first_name,second_name;
       splitString(locate_name, first_name, second_name);
 
       for (unsigned j=0;j<sub_timers_.size();j++)
         if ( first_name == sub_timers_[j].name_)
           return sub_timers_[j].accumulatedTimePerTimerCall(second_name);
       return 0;
     }
 
     void pack();
 
     LevelTimer* unpack(unsigned from);
 
     void report(std::ostream &os);
 
    const BaseTimer* findBaseTimer(const std::string &name) const;
    
    BaseTimer::TimeInfo findTimer(const std::string &name,bool& found);
 
  protected:
 
 
  }; // LevelTimer
 
 
 
 
public:
  explicit StackedTimer(const char *name, const bool start_base_timer = true)
    : timer_(0,name,nullptr,false),
      enable_verbose_(false),
      verbose_ostream_(Teuchos::rcpFromRef(std::cout))
  {
    top_ = &timer_;
    if (start_base_timer)
      this->startBaseTimer();
 
    auto check_verbose = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMERS");
    if (check_verbose != nullptr)
      enable_verbose_ = true;
  }
 
  void startBaseTimer() {
    timer_.BaseTimer::start();
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
    ::Kokkos::Profiling::pushRegion(timer_.get_full_name());
#endif
  }
 
  void stopBaseTimer() {
    timer_.BaseTimer::stop();
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
    ::Kokkos::Profiling::popRegion();
#endif
  }
 
  void start(const std::string name,
             const bool push_kokkos_profiling_region = true) {
    if (top_ == nullptr)
      top_ = timer_.start(name.c_str());
    else
      top_ = top_->start(name.c_str());
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
    if (push_kokkos_profiling_region) {
      ::Kokkos::Profiling::pushRegion(name);
    }
#endif
    if (enable_verbose_)
      *verbose_ostream_ << "STARTING: " << name << std::endl;
  }
 
  void stop(const std::string &name,
            const bool pop_kokkos_profiling_region = true) {
    if (top_)
      top_ = top_->stop(name);
    else
      timer_.BaseTimer::stop();
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOSCORE)
    if (pop_kokkos_profiling_region) {
      ::Kokkos::Profiling::popRegion();
    }
#endif
    if (enable_verbose_)
      *verbose_ostream_ << "STOPPING: " << name << std::endl;
  }
 
  void incrementUpdates(const long long i = 1) {
    top_->incrementUpdates(i);
  }
 
  double accumulatedTime(const std::string &name="") {
    if (top_) // Top is null for the head node when nothing is running
      return top_->accumulatedTime(name);
    else
      return timer_.accumulatedTime(name);
  }
 
  double accumulatedTimePerUpdate(const std::string &name="") {
     if (top_) // Top is null for the head node when nothing is running
       return top_->accumulatedTimePerUpdate(name);
     else
       return timer_.accumulatedTimePerUpdate(name);
   }
  double accumulatedTimePerTimerCall(const std::string &name="") {
     if (top_) // Top is null for the head node when nothing is running
       return top_->accumulatedTimePerTimerCall(name);
     else
       return timer_.accumulatedTimePerTimerCall(name);
   }
  
  const BaseTimer* findBaseTimer(const std::string &name) const {
    const BaseTimer* baseTimer = timer_.findBaseTimer(name);
    TEUCHOS_TEST_FOR_EXCEPTION(baseTimer == nullptr, std::runtime_error,
                               "StackedTimer::findBaseTimer() failed to find a timer named \"" << name << "\"!\n");
    return baseTimer;
  }
 
  BaseTimer::TimeInfo findTimer(const std::string &name) {
    bool foundTimer = false;
    const auto timeInfo = timer_.findTimer(name,foundTimer);
    TEUCHOS_TEST_FOR_EXCEPTION(!foundTimer, std::runtime_error,
      "StackedTimer::findTimer() failed to find a timer named \"" << name << "\"!\n");
    return timeInfo;
  }
 
  void report(std::ostream &os) {
    timer_.report(os);
  }
 
  struct OutputOptions {
    OutputOptions() : output_fraction(false), output_total_updates(false), output_histogram(false),
                      output_minmax(false), num_histogram(10), max_levels(INT_MAX),
                      print_warnings(true), align_columns(false), print_names_before_values(true) {}
    bool output_fraction;
    bool output_total_updates;
    bool output_histogram;
    bool output_minmax;
    int num_histogram;
    int max_levels;
    bool print_warnings;
    bool align_columns;
    bool print_names_before_values;
  };
 
  void report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());
 
 
  // If set to true, print timer start/stop to verbose ostream.
  void enableVerbose(const bool enable_verbose);
 
  // Set the ostream for verbose mode(defaults to std::cout).
  void setVerboseOstream(const Teuchos::RCP<std::ostream>& os);
 
protected:
  LevelTimer *top_;
  LevelTimer timer_;
 
  Array<std::string> flat_names_;
  Array<double> min_;
  Array<double> max_;
  Array<double> sum_;
  Array<double> sum_sq_;
  Array<Array<int>> hist_;
  Array<unsigned long> count_;
  Array<unsigned long long> updates_;
  Array<int> active_;
 
  struct AlignmentWidths {
    std::string::size_type timer_names_;
    std::string::size_type average_time_;
    std::string::size_type fraction_;
    std::string::size_type count_;
    std::string::size_type total_updates_;
    std::string::size_type min_;
    std::string::size_type max_;
    std::string::size_type stddev_;
    std::string::size_type histogram_;
    AlignmentWidths() :
      timer_names_(0),
      average_time_(0),
      fraction_(0),
      count_(0),
      total_updates_(0),
      min_(0),
      max_(0),
      stddev_(0),
      histogram_(0){}
  } alignments_;
 
  bool enable_verbose_;
 
  Teuchos::RCP<std::ostream> verbose_ostream_;
 
   void flatten();
 
   void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);
 
   void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );
 
  double computeColumnWidthsForAligment(std::string prefix, int print_level,
                                        std::vector<bool> &printed, double parent_time,
                                        const OutputOptions &options);
 
  double printLevel(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed,
                    double parent_time, const OutputOptions &options);
 
};  //StackedTimer
 
 
} //namespace Teuchos
 
#endif /* TEUCHOS_STACKED_TIMER_HPP */