Teuchos_StackedTimer.hpp

// @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_EnvVariables.hpp"
#include "Teuchos_PerformanceMonitorBase.hpp"
#include "Teuchos_Behavior.hpp"
#include "TeuchosComm_config.h" // for HAVE_TEUCHOSCOMM_MAGISTRATE
#ifdef HAVE_TEUCHOSCOMM_MAGISTRATE
#include "checkpoint/checkpoint.h"
#endif
#ifdef HAVE_TEUCHOSCORE_KOKKOS
#include "Kokkos_Core.hpp"
#endif
#include <string>
#include <vector>
#include <stack>
#include <cassert>
#include <chrono>
#include <climits>
#include <cstdlib> // for 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) {}
 
#ifdef HAVE_TEUCHOSCOMM_MAGISTRATE
  explicit BaseTimer(magistrate::SERIALIZE_CONSTRUCT_TAG) {}

  magistrate_virtual_serialize_root()
 
  
  template<typename Serializer>
  void serialize(Serializer& s) {
 
    // Timers must be stopped when storing data
    if (s.isPacking()) {
      TEUCHOS_ASSERT(!running_);
    }
 
    // Don't serialize start_time_ or running_, these are only used
    // when timer is running.
    s | accumulation_
      | accumulationSquared_
      | count_started_
      | count_updates_;
 
    if (s.isUnpacking()) {
      running_ = false;
    }
  }
#endif

  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()) {}
    bool operator ==(const TimeInfo& ti) const
    {return (time == ti.time) &&
            (stdDev == ti.stdDev) &&
            (count == ti.count) &&
            (updates == ti.updates) &&
            (running == ti.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;
    }
 
#ifdef HAVE_TEUCHOSCOMM_MAGISTRATE
    LevelTimer(magistrate::SERIALIZE_CONSTRUCT_TAG) : parent_(nullptr) {}
 
    // For serialization
    magistrate_virtual_serialize_derived_from(Teuchos::BaseTimer)
 
    
    template<typename Serializer>
    void serialize(Serializer& s) {
 
      s | level_;
      s | name_;
 
      // Manually handle the sub timers vector. The parent pointer
      // needs to be registered before the object is constructed.
      size_t sub_timer_size = sub_timers_.size();
      s | sub_timer_size;
 
      if (s.isUnpacking()) {
        sub_timers_.resize(sub_timer_size);
        for (auto& child : sub_timers_) {
          child.parent_ = this;
        }
      }
      for (size_t i=0; i < sub_timers_.size(); ++i) {
        s | sub_timers_[i];
      }
    }
#endif

    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;
    }
 
    std::string get_name() const {
      std::string my_name(name_);
      return my_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 = Teuchos::getEnvironmentVariableValue("TEUCHOS_ENABLE_VERBOSE_TIMERS");
    if (check_verbose != nullptr)
      enable_verbose_ = true;
 
    auto check_timestamp = Teuchos::getEnvironmentVariableValue("TEUCHOS_ENABLE_VERBOSE_TIMESTAMP_LEVELS");
    if (check_timestamp != nullptr) {
      verbose_timestamp_levels_ = std::atoi(check_timestamp);
    }
  }
 
#ifdef HAVE_TEUCHOSCOMM_MAGISTRATE
  explicit StackedTimer(magistrate::SERIALIZE_CONSTRUCT_TAG) {}
 
  template<typename Serializer>
  void serialize(Serializer& s) {
    s | timer_;
    s | enable_verbose_;
    s | verbose_timestamp_levels_;
    s | enable_timers_;
 
    if (s.isUnpacking()) {
      // Timer is always stopped before serializing
      top_ = &timer_;
      // Can't serialize an ostream pointer so just set to std::cout
      verbose_ostream_ = Teuchos::rcpFromRef(std::cout);
      global_mpi_aggregation_called_ = false;
    }
  }
#endif
 
  std::string name() {
    return timer_.get_full_name();
  }

  void startBaseTimer(const bool push_kokkos_profiling_region = true) {
#ifdef HAVE_TEUCHOSCORE_KOKKOS
    // Fence before starting timer to ignore async kernels started before this timer starts
    if (Behavior::fenceTimers()) {
      Kokkos::fence("timer_fence_begin_"+timer_.get_name());
    }
#endif
    timer_.BaseTimer::start();
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
    if (push_kokkos_profiling_region) {
      ::Kokkos::Tools::pushRegion(timer_.get_name());
    }
#endif
  }

  void stopBaseTimer(const bool pop_kokkos_profiling_region = true) {
#ifdef HAVE_TEUCHOSCORE_KOKKOS
    // Fence before stopping the timer to include async kokkos kernels launched within this timer
    if (Behavior::fenceTimers()) {
      Kokkos::fence("timer_fence_end_"+timer_.get_name());
    }
#endif
#if defined(HAVE_TEUCHOS_KOKKOS_PROFILING) && defined(HAVE_TEUCHOSCORE_KOKKOS)
    if (pop_kokkos_profiling_region) {
      ::Kokkos::Tools::popRegion();
    }
#endif
    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 {
#ifdef HAVE_TEUCHOSCORE_KOKKOS
        // Fence before starting timer to ignore async kernels started before this timer starts
        if (Behavior::fenceTimers()) {
          Kokkos::fence("timer_fence_begin_"+name);
        }
#endif
        top_ = top_->start(name.c_str());
#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_) {
#ifdef HAVE_TEUCHOSCORE_KOKKOS
        // Fence before stopping the timer to include async kokkos kernels launched within this timer
        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
        top_ = top_->stop(name);
      } 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);

  std::stack<std::string> stopAllTimers();

  void startTimers(std::stack<std::string> timers_to_start);
 
 
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 */