Skip to content

Commit

Permalink
Teuchos: add hooks to disable/reenable stacked timers for async tasks.
Browse files Browse the repository at this point in the history
  • Loading branch information
@rppawlo
rppawlo committed Jun 8, 2021
1 parent 332e870 commit 44de202
Show file tree
Hide file tree
Showing 3 changed files with 106 additions and 49 deletions.
6 changes: 6 additions & 0 deletions packages/teuchos/comm/src/Teuchos_StackedTimer.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -822,4 +822,10 @@ void StackedTimer::enableVerboseTimestamps(const unsigned levels)
void StackedTimer::setVerboseOstream(const Teuchos::RCP<std::ostream>& os)
{verbose_ostream_ = os;}

void StackedTimer::disableTimers()
{enable_timers_ = false;}

void StackedTimer::enableTimers()
{enable_timers_ = true;}

} //namespace Teuchos
114 changes: 65 additions & 49 deletions packages/teuchos/comm/src/Teuchos_StackedTimer.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -473,7 +473,8 @@ class StackedTimer
: timer_(0,name,nullptr,false),
enable_verbose_(false),
verbose_timestamp_levels_(0), // 0 disables
verbose_ostream_(Teuchos::rcpFromRef(std::cout))
verbose_ostream_(Teuchos::rcpFromRef(std::cout)),
enable_timers_(true)
{
top_ = &timer_;
if (start_base_timer)
Expand Down Expand Up @@ -516,33 +517,35 @@ class StackedTimer
*/
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 (enable_timers_) {
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_) {
if (!verbose_timestamp_levels_) {
*verbose_ostream_ << "STARTING: " << name << std::endl;
if (push_kokkos_profiling_region) {
::Kokkos::Profiling::pushRegion(name);
}
// gcc 4.X is incomplete in c++11 standard - missing
// std::put_time. We'll disable this feature for gcc 4.
#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;
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
}
}
}

Expand All @@ -553,34 +556,36 @@ class StackedTimer
*/
void stop(const std::string &name,
const bool pop_kokkos_profiling_region = true) {
if (top_)
top_ = top_->stop(name);
else
timer_.BaseTimer::stop();
if (enable_timers_) {
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_) {
if (!verbose_timestamp_levels_) {
*verbose_ostream_ << "STOPPING: " << name << std::endl;
if (pop_kokkos_profiling_region) {
::Kokkos::Profiling::popRegion();
}
// gcc 4.X is incomplete in c++11 standard - missing
// std::put_time. We'll disable this feature for gcc 4.
#endif
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;
// 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
}
}
}

Expand Down Expand Up @@ -733,15 +738,23 @@ class StackedTimer
*/
std::string reportWatchrXML(const std::string& name, Teuchos::RCP<const Teuchos::Comm<int> > comm);

// If set to true, print timer start/stop to verbose ostream.
/// If set to true, print timer start/stop to verbose ostream.
void enableVerbose(const bool enable_verbose);

// Enable timestamps in verbose mode for the number of levels specified.
/// Enable timestamps in verbose mode for the number of levels specified.
void enableVerboseTimestamps(const unsigned levels);

// Set the ostream for verbose mode(defaults to std::cout).
/// Set the ostream for verbose mode(defaults to std::cout).
void setVerboseOstream(const Teuchos::RCP<std::ostream>& os);

/// Once called, the start and stop calls are no-ops. Used to stop
/// timers during asynchronous execution.
void disableTimers();

/// Once called, the start and stop calls are reenabled. Used to
/// restart timers after a call to disableTimers().
void enableTimers();

protected:
/// Current level running
LevelTimer *top_;
Expand Down Expand Up @@ -795,6 +808,9 @@ class StackedTimer
/// For debugging, this is the ostream used for printing.
Teuchos::RCP<std::ostream> verbose_ostream_;

/// Used to disable timers for asynchronous work.
bool enable_timers_;

/**
* Flatten the timers into a single array
*/
Expand Down
35 changes: 35 additions & 0 deletions packages/teuchos/comm/test/StackedTimer/stacked_timer.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -599,3 +599,38 @@ TEUCHOS_UNIT_TEST(StackedTimer, VerboseTimestamps) {
TEST_ASSERT(os.str().find("L3") == std::string::npos);
}
#endif

// Tests that we can turn off timers for regions of asychronous
// execution.
TEUCHOS_UNIT_TEST(StackedTimer, DisableTimers)
{
Teuchos::StackedTimer timer("My New Timer");
timer.start("Total Time");
{
for (int i=0; i < 10; ++i) {

timer.start("Assembly");
std::this_thread::sleep_for(std::chrono::milliseconds{10});
timer.stop("Assembly");

timer.disableTimers(); // Stop recording timers
timer.start("Solve");
{
timer.start("Prec");
std::this_thread::sleep_for(std::chrono::milliseconds{10});
timer.stop("Prec");
}
timer.stop("Solve");
timer.enableTimers(); // Start recording timers

}
}
timer.stop("Total Time");
timer.stopBaseTimer();

TEST_EQUALITY((timer.findTimer("My New Timer@Total Time")).count, 1);
TEST_EQUALITY((timer.findTimer("My New Timer@Total Time@Assembly")).count, 10);
// Should not exist
TEST_THROW(timer.findTimer("My New Timer@Total Time@Solve"),std::runtime_error);
TEST_THROW(timer.findTimer("My New Timer@Total Time@Solve@Prec"),std::runtime_error);
}

0 comments on commit 44de202

Please sign in to comment.