Teuchos_StackedTimer.hpp

Go to the documentation of this file.

// @HEADER
// *****************************************************************************
//                    Teuchos: Common Tools Package
//
// Copyright 2004 NTESS and the Teuchos contributors.
// SPDX-License-Identifier: BSD-3-Clause
// *****************************************************************************
// @HEADER

#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 "Teuchos_Behavior.hpp"
#ifdef HAVE_TEUCHOSCORE_KOKKOS
#include "Kokkos_Core.hpp"
#endif
#include <string>
#include <vector>
#include <cassert>
#include <chrono>
#include <climits>
#include <cstdlib> // for std::getenv and atoi
#include <ctime> // for timestamp support
#include <iostream>

#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
namespace Kokkos {
namespace Tools {
extern void pushRegion (const std::string&);
extern void popRegion ();
} // namespace Profiling
} // namespace Kokkos
#endif


namespace Teuchos {

TEUCHOSCOMM_LIB_DLL_EXPORT 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), accumulationSquared_(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");
    auto elapsed = std::chrono::duration_cast<std::chrono::duration<double>>(Clock::now() - start_time_).count();
    accumulation_ += elapsed;
    accumulationSquared_ += elapsed*elapsed;
    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; }

  void setAccumulatedTimeSquared(double accumSq=0)  {accumulationSquared_=accumSq;}
  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 timePerCallStdDev() const {
    if (count_started_ > 0) {
      double mean = accumulatedTimePerTimerCall();
      return sqrt(std::max<double>(accumulationSquared_ / count_started_ - mean*mean, 0.0));
    } 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), stdDev(0.0), count(0), updates(0), running(false){}
    TimeInfo(BaseTimer* t): time(t->accumulation_), stdDev(t->timePerCallStdDev()), count(t->count_started_), updates(t->count_updates_), running(t->running()) {}
    double time;
    double stdDev;
    unsigned long count;
    unsigned long long updates;
    bool running;
  };

protected:
  double accumulation_;       // total time
  double accumulationSquared_;  // Sum of squares of elapsed times
  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 TEUCHOSCOMM_LIB_DLL_EXPORT 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;
    }

    unsigned level() const
    {return level_;}

  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);

  }; // LevelTimer


public:
  explicit StackedTimer(const char *name, const bool start_base_timer = true)
    : timer_(0,name,nullptr,false),
      global_mpi_aggregation_called_(false),
      enable_verbose_(false),
      verbose_timestamp_levels_(0), // 0 disables
      verbose_ostream_(Teuchos::rcpFromRef(std::cout)),
      enable_timers_(true)
  {
    top_ = &timer_;
    if (start_base_timer)
      this->startBaseTimer();

    auto check_verbose = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMERS");
    if (check_verbose != nullptr)
      enable_verbose_ = true;

    auto check_timestamp = std::getenv("TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
    if (check_timestamp != nullptr) {
      verbose_timestamp_levels_ = std::atoi(check_timestamp);
    }
  }

  std::string name() {
    return timer_.get_full_name();
  }

  void startBaseTimer() {
    timer_.BaseTimer::start();
  }

  void stopBaseTimer() {
    timer_.BaseTimer::stop();
  }

  void start(const std::string name,
             const bool push_kokkos_profiling_region = true) {
    if (enable_timers_) {
      if (top_ == nullptr) {
        top_ = timer_.start(name.c_str());
      } else {
        top_ = top_->start(name.c_str());
#ifdef HAVE_TEUCHOSCORE_KOKKOS
        if (Behavior::fenceTimers()) {
          Kokkos::fence("timer_fence_begin_"+name);
        }
#endif
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
        if (push_kokkos_profiling_region) {
          ::Kokkos::Tools::pushRegion(name);
        }
#endif
      }
    }
    if (enable_verbose_) {
      if (!verbose_timestamp_levels_) {
        *verbose_ostream_ << "STARTING: " << name << std::endl;
      }
      // gcc 4.X is incomplete in c++11 standard - missing
      // std::put_time. We'll disable this feature for gcc 4.
#if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
      else if (top_ != nullptr) {
        if ( top_->level() <= verbose_timestamp_levels_) {
          auto now = std::chrono::system_clock::now();
          auto now_time = std::chrono::system_clock::to_time_t(now);
          auto gmt = gmtime(&now_time);
          auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
          auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
          *verbose_ostream_ << "STARTING: " << name << " LEVEL: " << top_->level() << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
        }
      }
#endif
    }
  }

  void stop(const std::string &name,
            const bool pop_kokkos_profiling_region = true) {
    if (enable_timers_) {
      if (top_) {
        top_ = top_->stop(name);
#ifdef HAVE_TEUCHOSCORE_KOKKOS
        if (Behavior::fenceTimers()) {
          Kokkos::fence("timer_fence_end_"+name);
        }
#endif
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
        if (pop_kokkos_profiling_region) {
          ::Kokkos::Tools::popRegion();
        }
#endif
      } else {
        timer_.BaseTimer::stop();
      }
    }
    if (enable_verbose_) {
      if (!verbose_timestamp_levels_) {
        *verbose_ostream_ << "STOPPING: " << name << std::endl;
      }
      // gcc 4.X is incomplete in c++11 standard - missing
      // std::put_time. We'll disable this feature for gcc 4.
#if !defined(__GNUC__) || ( defined(__GNUC__) && (__GNUC__ > 4) )
      // The stop adjusts the top level, need to adjust by +1 for printing
      else if (top_ != nullptr) {
        if ( (top_->level()+1) <= verbose_timestamp_levels_) {
          auto now = std::chrono::system_clock::now();
          auto now_time = std::chrono::system_clock::to_time_t(now);
          auto gmt = gmtime(&now_time);
          auto timestamp = std::put_time(gmt, "%Y-%m-%d %H:%M:%S");
          auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
          *verbose_ostream_ << "STOPPING: " << name << " LEVEL: " << top_->level()+1 << " COUNT: " << timer_.numCalls() << " TIMESTAMP: " << timestamp << "." << ms.count() << std::endl;
        }
      }
#endif
    }
  }

  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), output_proc_minmax(false), num_histogram(10), max_levels(INT_MAX),
                      print_warnings(true), align_columns(false), print_names_before_values(true),
                      drop_time(-1.0), output_per_proc_stddev(false) {}
    bool output_fraction;
    bool output_total_updates;
    bool output_histogram;
    bool output_minmax;
    bool output_proc_minmax;
    int num_histogram;
    int max_levels;
    bool print_warnings;
    bool align_columns;
    bool print_names_before_values;
    double drop_time;
    bool output_per_proc_stddev;
  };

  void report(std::ostream &os, Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());

  void reportXML(std::ostream &os, const std::string& datestamp, const std::string& timestamp, Teuchos::RCP<const Teuchos::Comm<int> > comm);

  std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);

  void enableVerbose(const bool enable_verbose);

  void enableVerboseTimestamps(const unsigned levels);

  void setVerboseOstream(const Teuchos::RCP<std::ostream>& os);

  void disableTimers();

  void enableTimers();

  void aggregateMpiData(Teuchos::RCP<const Teuchos::Comm<int> > comm, OutputOptions options = OutputOptions());

  double getMpiAverageTime(const std::string& flat_timer_name);

  double getMpiAverageCount(const std::string& flat_timer_name);

  bool isTimer(const std::string& flat_timer_name);

protected:
  LevelTimer *top_;
  LevelTimer timer_;

  // Global MPI aggregation arrays
  Array<std::string> flat_names_;
  Array<double> min_;
  Array<double> max_;
  Array<int> procmin_;
  Array<int> procmax_;
  Array<double> sum_;
  Array<double> sum_sq_;
  Array<Array<int>> hist_;
  Array<double> per_proc_stddev_min_;
  Array<double> per_proc_stddev_max_;
  Array<unsigned long> count_;
  Array<unsigned long long> updates_;
  Array<int> active_;
  bool global_mpi_aggregation_called_;

  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 procmin_;
    std::string::size_type procmax_;
    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),
      procmax_(0),
      stddev_(0),
      histogram_(0){}
  } alignments_;

  bool enable_verbose_;

  unsigned verbose_timestamp_levels_;

  Teuchos::RCP<std::ostream> verbose_ostream_;

  bool enable_timers_;

   void flatten();

   void merge(Teuchos::RCP<const Teuchos::Comm<int> > comm);

   void collectRemoteData(Teuchos::RCP<const Teuchos::Comm<int> > comm, const OutputOptions &options );

   int getFlatNameIndex(const std::string& flat_timer_name);

  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);

  double printLevelXML(std::string prefix, int level, std::ostream &os, std::vector<bool> &printed, double parent_time, const std::string& rootName = "");

};  //StackedTimer


} //namespace Teuchos

#endif /* TEUCHOS_STACKED_TIMER_HPP */