From 3f3b57db6d8238c2b94502e278d71ffbc186d3d8 Mon Sep 17 00:00:00 2001 From: Erik Schnetter Date: Sun, 26 May 2013 16:41:45 -0400 Subject: Carpet: Provide global instead of process-local timer output Reduce timer values across all processes before output, reporting both maximum and average. TimerNode::getGlobalTime: new function --- Carpet/Carpet/src/CactusTimer.cc | 56 +++++++++++++------ Carpet/Carpet/src/CactusTimer.hh | 7 ++- Carpet/Carpet/src/Evolve.cc | 7 ++- Carpet/Carpet/src/Initialise.cc | 4 +- Carpet/Carpet/src/Shutdown.cc | 7 ++- Carpet/Carpet/src/TimerNode.cc | 116 +++++++++++++++++++++++++++------------ Carpet/Carpet/src/TimerNode.hh | 1 + 7 files changed, 141 insertions(+), 57 deletions(-) diff --git a/Carpet/Carpet/src/CactusTimer.cc b/Carpet/Carpet/src/CactusTimer.cc index 966fe9d7e..a4250f6ee 100644 --- a/Carpet/Carpet/src/CactusTimer.cc +++ b/Carpet/Carpet/src/CactusTimer.cc @@ -78,33 +78,57 @@ namespace Carpet { DECLARE_CCTK_PARAMETERS; - bool const was_running = running; - if (was_running) stop(); - static cTimerData * timer = 0; if (not timer) timer = CCTK_TimerCreateData (); assert (timer); CCTK_TimerI (handle, timer); - double val = 0; // All these timers will be returned as doubles - - const cTimerVal *tv = CCTK_GetClockValue(timer_xml_clock, timer); + bool const was_running = running; + if (was_running) stop(); + const cTimerVal * tv = CCTK_GetClockValue(timer_xml_clock, timer); + if (was_running) start(); - if (tv != NULL) - { - val = CCTK_TimerClockSeconds(tv); - } - else - { - CCTK_VWarn(1, __LINE__, __FILE__, CCTK_THORNSTRING, + if (not tv) { + CCTK_VWarn(CCTK_WARN_ALERT, __LINE__, __FILE__, CCTK_THORNSTRING, "Clock \"%s\" not found for timer #%d \"%s\"", timer_xml_clock, handle, CCTK_TimerName(handle)); - val = -1; + return -1.0; } - if (was_running) start(); + return CCTK_TimerClockSeconds(tv); + } - return val; + void CactusTimer::getGlobalTime(double& avg, double& max) + { + const cGH *const cctkGH = 0; + + int ierr; + + static int op_sum = -1; + static int op_max = -1; + if (op_sum<0) op_sum = CCTK_ReductionArrayHandle("sum"); + if (op_max<0) op_max = CCTK_ReductionArrayHandle("maximum"); + + const double val = getTime(); + const CCTK_REAL val1 = val; + + CCTK_REAL sum1; + ierr = CCTK_ReduceLocScalar(cctkGH, -1, op_sum, + &val1, &sum1, CCTK_VARIABLE_REAL); + if (ierr) { + CCTK_VWarn(CCTK_WARN_ALERT, __LINE__, __FILE__, CCTK_THORNSTRING, + "Error in sum reduction"); + } + avg = sum1 / CCTK_nProcs(cctkGH); + + CCTK_REAL max1; + ierr = CCTK_ReduceLocScalar(cctkGH, -1, op_max, + &val1, &max1, CCTK_VARIABLE_REAL); + if (ierr) { + CCTK_VWarn(CCTK_WARN_ALERT, __LINE__, __FILE__, CCTK_THORNSTRING, + "Error in maximum reduction"); + } + max = max1; } vector > CactusTimer::getAllTimerNames() const diff --git a/Carpet/Carpet/src/CactusTimer.hh b/Carpet/Carpet/src/CactusTimer.hh index 851bf7ca5..cab4c592a 100644 --- a/Carpet/Carpet/src/CactusTimer.hh +++ b/Carpet/Carpet/src/CactusTimer.hh @@ -41,10 +41,13 @@ namespace Carpet { /// Timer name string name () const; - /// Return the current time of the timer as a double + /// Return the current time of the timer in seconds as a double double getTime(); - /// Return all clock names + /// Return the average and maximum current time over all MPI processes + void getGlobalTime(double& avg, double& max); + + /// Return all clock names and their units vector > getAllTimerNames() const; /// Return all clock values of the timer as double diff --git a/Carpet/Carpet/src/Evolve.cc b/Carpet/Carpet/src/Evolve.cc index 37eaecdcc..0a959b48c 100644 --- a/Carpet/Carpet/src/Evolve.cc +++ b/Carpet/Carpet/src/Evolve.cc @@ -98,8 +98,11 @@ namespace Carpet { cctkGH->cctk_iteration % do_every == 0) { TimerNode *et = main_timer_tree.root->getChildTimer("Evolve"); - et->print(cout, et->getTime(), 0, timer_tree_threshold_percentage, timer_tree_output_precision); - mode_timer_tree.root->print(cout, mode_timer_tree.root->getTime(), 0, timer_tree_threshold_percentage, timer_tree_output_precision); + double total_avg, total_max; + et->getGlobalTime(total_avg, total_max); + et->print(cout, total_max, 0, timer_tree_threshold_percentage, timer_tree_output_precision); + mode_timer_tree.root->getGlobalTime(total_avg, total_max); + mode_timer_tree.root->print(cout, total_max, 0, timer_tree_threshold_percentage, timer_tree_output_precision); } timer.stop(); } diff --git a/Carpet/Carpet/src/Initialise.cc b/Carpet/Carpet/src/Initialise.cc index ac0189af1..7440b5cdc 100644 --- a/Carpet/Carpet/src/Initialise.cc +++ b/Carpet/Carpet/src/Initialise.cc @@ -140,7 +140,9 @@ namespace Carpet { if (output_initialise_timer_tree) { TimerNode *it = main_timer_tree.root->getChildTimer("Initialise"); - it->print(cout, it->getTime(), 0, timer_tree_threshold_percentage, timer_tree_output_precision); + double total_avg, total_max; + it->getGlobalTime(total_avg, total_max); + it->print(cout, total_max, 0, timer_tree_threshold_percentage, timer_tree_output_precision); } Waypoint ("Done with initialisation"); diff --git a/Carpet/Carpet/src/Shutdown.cc b/Carpet/Carpet/src/Shutdown.cc index ca2123fba..0d5fbe244 100644 --- a/Carpet/Carpet/src/Shutdown.cc +++ b/Carpet/Carpet/src/Shutdown.cc @@ -83,8 +83,11 @@ namespace Carpet { if (output_timer_tree_every > 0) { TimerNode *et = main_timer_tree.root->getChildTimer("Evolve"); - et->print(cout, et->getTime(), 0, timer_tree_threshold_percentage, timer_tree_output_precision); - mode_timer_tree.root->print(cout, mode_timer_tree.root->getTime(), 0, timer_tree_threshold_percentage, timer_tree_output_precision); + double total_avg, total_max; + et->getGlobalTime(total_avg, total_max); + et->print(cout, total_max, 0, timer_tree_threshold_percentage, timer_tree_output_precision); + mode_timer_tree.root->getGlobalTime(total_avg, total_max); + mode_timer_tree.root->print(cout, total_max, 0, timer_tree_threshold_percentage, timer_tree_output_precision); } if (output_xml_timer_tree) { diff --git a/Carpet/Carpet/src/TimerNode.cc b/Carpet/Carpet/src/TimerNode.cc index 1753e4e5d..93833a72d 100644 --- a/Carpet/Carpet/src/TimerNode.cc +++ b/Carpet/Carpet/src/TimerNode.cc @@ -29,14 +29,17 @@ #include #include +#include #include #include -#include #include #include #include #include +#include +#include + #include "TimerNode.hh" namespace Carpet { @@ -93,22 +96,17 @@ namespace Carpet { void TimerNode::stop() { - if (d_running) - { - // A timer can only be stopped if it is the current timer - if(this != d_tree->current) - CCTK_VWarn (0, __LINE__, __FILE__, CCTK_THORNSTRING, - "Tried to stop non-current timer '%s'", getName().c_str()); + assert(d_running); - timer->stop(); + // A timer can only be stopped if it is the current timer + if(this != d_tree->current) + CCTK_VError (__LINE__, __FILE__, CCTK_THORNSTRING, + "Tried to stop non-current timer '%s'", getName().c_str()); - d_running = false; - d_tree->current = d_parent; - } - else - { - assert(0); // Timer is not running - } + timer->stop(); + + d_running = false; + d_tree->current = d_parent; } /// Get the name of the timer @@ -144,6 +142,12 @@ namespace Carpet { return timer->getTime(); } + /// Get the global time measured by this timer + void TimerNode::getGlobalTime(double& avg, double& max) + { + return timer->getGlobalTime(avg, max); + } + /// Get the names of all clocks of this timer vector > TimerNode::getAllTimerNames() const { @@ -176,7 +180,9 @@ namespace Carpet { const streamsize oldprecision = out.precision(); const ios_base::fmtflags oldflags = out.flags(); - const double t = getTime(); + // const double t = getTime(); + double tavg, tmax; + getGlobalTime(tavg, tmax); const vector values = getAllTimerValues(); const string hyphens = string(precision-1, '-'); const string spaces = string(precision-1, ' '); @@ -185,39 +191,51 @@ namespace Carpet { { const vector > names = getAllTimerNames(); - out << "--------" << hyphens << "--------" << hyphens - << string(tnw+2, '-'); + out << "--------" << hyphens + << "--------" << hyphens + << "--------" << hyphens + << "--" << string(tnw, '-'); for (size_t i=0; i::iterator iter = d_children.begin(); iter != d_children.end(); iter++) { - if (iter->second->getTime() * 100.0 / total > threshold) - { + const string timername = iter->first; + const string root_timername = + CarpetLib::broadcast_string(dist::comm(), 0, timername); + if (timername != root_timername) { + CCTK_VError(__LINE__, __FILE__, CCTK_THORNSTRING, + "Timers are inconsistent across processes: root process expects timer %s, this process has timer %s instead", + root_timername.c_str(), timername.c_str()); + } + double child_avg, child_max; + iter->second->getGlobalTime(child_avg, child_max); + if (child_max * 100.0 / total > threshold) { iter->second->print(out,total,level+1,threshold,precision); printed_children = true; } - children_time += iter->second->getTime(); + //children_time += iter->second->getTime(); + children_tavg += child_avg; + } + { + const string timername = "[done]"; + const string root_timername = + CarpetLib::broadcast_string(dist::comm(), 0, timername); + if (timername != root_timername) { + CCTK_VError(__LINE__, __FILE__, CCTK_THORNSTRING, + "Timers are inconsistent across processes: root process expects timer %s, this process has timer %s instead", + root_timername.c_str(), timername.c_str()); + } } if (d_children.size() > 0 && printed_children) { - const double untimed = t - children_time; + //const double untimed = t - children_time; + const double untimed = tavg - children_tavg; if (100.0 * untimed / total > threshold) { // Print the untimed portion out << fixed << setw(pcw) << setprecision(1) << 100.0 * untimed / total << "%" << " " << fixed << setw(tw) << setprecision(1) << untimed + << " " << " | " << space << "untimed" << "\n"; } } @@ -256,10 +302,12 @@ namespace Carpet { out.setf (oldflags); if (level == 0) { - out << "--------" << hyphens << "--------" << hyphens - << string(tnw+2, '-'); + out << "--------" << hyphens + << "--------" << hyphens + << "--------" << hyphens + << "--" << string(tnw, '-'); for (size_t i=0; i > getAllTimerNames() const; vector getAllTimerValues(); bool isRunning() const; -- cgit v1.2.3