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

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<pair<string,string> > 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<pair<string,string> > 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 <algorithm>
 #include <cassert>
+#include <fstream>
 #include <iomanip>
 #include <iostream>
-#include <fstream>
 #include <map>
 #include <ostream>
 #include <string>
 #include <utility>
 
+#include <dist.hh>
+#include <mpi_string.hh>
+
 #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<pair<string,string> > 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<double> values = getAllTimerValues();
     const string hyphens = string(precision-1, '-');
     const string spaces  = string(precision-1, ' ');
@@ -185,39 +191,51 @@ namespace Carpet {
     {
       const vector<pair<string,string> > names = getAllTimerNames();
       
-      out << "--------" << hyphens << "--------" << hyphens
-          << string(tnw+2, '-');
+      out << "--------" << hyphens
+          << "--------" << hyphens
+          << "--------" << hyphens
+          << "--" << string(tnw, '-');
       for (size_t i=0; i<values.size(); ++i) {
-        out << string(vw+2, '-');
+        out << "--" << string(vw, '-');
       }
       out << "\n";
       
-      out << "Time    " << spaces  << "  Time  " << spaces
+      // timer names
+      out << "Time    " << spaces
+          << "  Time  " << spaces
+          << " Imblnc " << spaces
           << "  " << setw(tnw) << left << "Timer" << right;
       for (size_t i=0; i<names.size(); ++i) {
         out << "  " << setw(vw) << names[i].first.substr(0,vw);
       }
       out << "\n";
       
-      out << "percent " << spaces  << "  secs  " << spaces
+      // timer units
+      out << "percent " << spaces
+          << "  secs  " << spaces
+          << " percent" << spaces
           << "  " << setw(tnw) << "     ";
       for (size_t i=0; i<names.size(); ++i) {
         out << "  " << setw(vw) << names[i].second.substr(0,vw);
       }
       out << "\n";
       
-      out << "--------" << hyphens << "--------" << hyphens
-          << string(tnw+2, '-');
+      out << "--------" << hyphens
+          << "--------" << hyphens
+          << "--------" << hyphens
+          << "--" << string(tnw, '-');
       for (size_t i=0; i<values.size(); ++i) {
-        out << string(vw+2, '-');
+        out << "--" << string(vw, '-');
       }
       out << "\n";
     }
 
     // Print this timer value
     out << fixed << setw(pcw) << setprecision(precision)
-        << 100.0 * t / total << "%"
-        << " " << fixed << setw(tw) << setprecision(precision) << t
+        << 100.0 * tavg / total << "%"
+        << " " << fixed << setw(tw) << setprecision(precision) << tavg
+        << " " << fixed << setw(pcw) << setprecision(precision)
+        << 100.0 * (1.0 - tavg / tmax) << "%"
         << "  " << space << setw(max(size_t(0), tnw - space.length())) << left
         << d_name.substr(0, max(size_t(10), tnw - space.length())) << right;
     for (size_t i=0; i<values.size(); ++i) {
@@ -226,29 +244,57 @@ namespace Carpet {
     }
     out << "\n";
 
-    double children_time = 0;
+    // TODO: Don't call getGlobalTime for all timers separately.
+    // Instead, call a single function that takes a snapshot of all
+    // timers, and reduces these snapshots to average and maximum.
+    // While printing, access these snapshots.
+    
+    //double children_time = 0;
+    double children_tavg = 0.0;
     bool printed_children = false;
 
     // Recursively print the children
     for(map<string,TimerNode*>::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<values.size(); ++i) {
-        out << string(vw+2, '-');
+        out << "--" << string(vw, '-');
       }
       out << "\n";
     }
diff --git a/Carpet/Carpet/src/TimerNode.hh b/Carpet/Carpet/src/TimerNode.hh
index 91c6c06a6..5852e8379 100644
--- a/Carpet/Carpet/src/TimerNode.hh
+++ b/Carpet/Carpet/src/TimerNode.hh
@@ -95,6 +95,7 @@ public:
   TimerNode* getChildTimer(string name);
 
   double getTime();
+  void getGlobalTime(double& avg, double &max);
   vector<pair<string, string> > getAllTimerNames() const;
   vector<double> getAllTimerValues();
   bool isRunning() const;