CarpetLib: Extend timing statistics

Add timers for the new communication infrastructure.

Enhance the timers to also track the minimum and maximum time spent.

Add a parameter to output timing information to files.

darcs-hash:20060731152618-dae7b-1d049b2b37397610c14648078fd0ee92f252ca2a.gz

5 files changed, 101 insertions, 35 deletions

diff --git a/Carpet/CarpetLib/param.ccl b/Carpet/CarpetLib/param.ccl
index c21fa38f1..54501823e 100644
--- a/Carpet/CarpetLib/param.ccl
+++ b/Carpet/CarpetLib/param.ccl
@@ -35,6 +35,12 @@ BOOLEAN print_timestats "Print timing statistics at every iteration" STEERABLE=a
 {
 } "no"
 
+INT print_timestats_every "Print timing statistics periodically" STEERABLE=always
+{
+  0   :: "don't report"
+  1:* :: "report every so many iterations"
+} 0
+
 BOOLEAN save_memory_during_regridding "Save some memory during regridding at the expense of speed" STEERABLE=always
 {
 } "yes"
diff --git a/Carpet/CarpetLib/src/commstate.cc b/Carpet/CarpetLib/src/commstate.cc
index fa0e833c9..ec4bbf667 100644
--- a/Carpet/CarpetLib/src/commstate.cc
+++ b/Carpet/CarpetLib/src/commstate.cc
@@ -7,6 +7,12 @@
 #include "vect.hh"
 
 #include "commstate.hh"
+#include "timestat.hh"
+
+
+
+using namespace std;
+
 
 
 // Communication state control
@@ -89,9 +95,11 @@ void comm_state::step ()
           procbuf.recvbuf = procbuf.recvbufbase;
 
           if (procbuf.recvbufsize > 0) {
+            wtime_commstate_sizes_irecv.start();
             MPI_Irecv (procbuf.recvbufbase, procbuf.recvbufsize,
                        typebufs[type].mpi_datatype, proc, type,
                        dist::comm(), &rrequests[dist::size()*type + proc]);
+            wtime_commstate_sizes_irecv.stop();
             num_posted_recvs++;
           }
         }
@@ -163,7 +171,9 @@ bool comm_state::AllPostedCommunicationsFinished ()
   // check if all outstanding receives have been completed already
   if (num_posted_recvs == num_completed_recvs) {
     // finalize the outstanding sends in one go
+    wtime_commstate_waitall_final.start();
     MPI_Waitall (srequests.size(), &srequests.front(), MPI_STATUSES_IGNORE);
+    wtime_commstate_waitall_final.stop();
 
     return true;
   }
@@ -178,15 +188,19 @@ bool comm_state::AllPostedCommunicationsFinished ()
     }
 
     // wait for completion of all posted receive operations
+    wtime_commstate_waitall.start();
     MPI_Waitall (rrequests.size(), &rrequests.front(), MPI_STATUSES_IGNORE);
+    wtime_commstate_waitall.stop();
     num_completed_recvs = num_posted_recvs;
   } else {
     int num_completed_recvs_ = 0;
     vector<int> completed_recvs(rrequests.size(), -1);
 
     // wait for completion of at least one posted receive operation
+    wtime_commstate_waitsome.start();
     MPI_Waitsome (rrequests.size(), &rrequests.front(), &num_completed_recvs_,
                   &completed_recvs.front(), MPI_STATUSES_IGNORE);
+    wtime_commstate_waitsome.stop();
     assert (0 < num_completed_recvs_);
     num_completed_recvs += num_completed_recvs_;
 
diff --git a/Carpet/CarpetLib/src/gdata.cc b/Carpet/CarpetLib/src/gdata.cc
index 97896639d..428eb6871 100644
--- a/Carpet/CarpetLib/src/gdata.cc
+++ b/Carpet/CarpetLib/src/gdata.cc
@@ -316,6 +316,7 @@ void gdata::copy_into_sendbuffer (comm_state& state,
                  state.typebufs.at(c_datatype()).mpi_datatype,
                  proc(), c_datatype(), dist::comm(),
                  &state.srequests.at(dist::size()*c_datatype() + proc()));
+      wtime_commstate_isend.stop();
     }
   }
 }
@@ -338,6 +339,7 @@ void gdata::copy_from_recvbuffer (comm_state& state,
   ivect items = (box.upper() - box.lower()) / box.stride() + 1;
   ivect offs  = (box.lower() - ext.lower()) / ext.stride();
 
+  wtime_commstate_memcpy.start();
   assert (dim == 3);
   for (int k = 0; k < items[2]; k++) {
     for (int j = 0; j < items[1]; j++) {
@@ -347,6 +349,7 @@ void gdata::copy_from_recvbuffer (comm_state& state,
       procbuf.recvbuf += datatypesize * items[0];
     }
   }
+  wtime_commstate_memcpy.stop();
 }
 
 
@@ -453,8 +456,10 @@ void gdata
 
     comm_state::gcommbuf * b = make_typed_commbuf (box);
 
+    wtime_commstate_interpolate_irecv.start();
     MPI_Irecv (b->pointer(), b->size(), b->datatype(), src->proc(),
                tag, dist::comm(), &b->request);
+    wtime_commstate_interpolate_irecv.stop();
     state.requests.push_back (b->request);
     state.recvbufs.push (b);
   } else {
@@ -468,8 +473,10 @@ void gdata
                                      order_space, order_time);
     delete tmp;
 
+    wtime_commstate_interpolate_from_isend.start();
     MPI_Isend (b->pointer(), b->size(), b->datatype(), proc(),
                tag, dist::comm(), &b->request);
+    wtime_commstate_interpolate_from_isend.stop();
     state.requests.push_back (b->request);
     state.sendbufs.push (b);
   }
@@ -516,11 +523,13 @@ void gdata
     procbuf.sendbuf += datatypesize * box.size();
   
     // post the send if the buffer is full
-    if (fillstate == procbuf.sendbufsize*datatypesize) {
+    if (fillstate == (int)procbuf.sendbufsize*datatypesize) {
+      wtime_commstate_interpolate_to_isend.start();
       MPI_Isend (procbuf.sendbufbase, procbuf.sendbufsize,
                  state.typebufs.at(c_datatype()).mpi_datatype,
                  proc(), c_datatype(), dist::comm(),
                  &state.srequests.at(dist::size()*c_datatype() + proc()));
+      wtime_commstate_interpolate_to_isend.stop();
     }
   }
 }
diff --git a/Carpet/CarpetLib/src/timestat.cc b/Carpet/CarpetLib/src/timestat.cc
index 86767cff4..f5116481f 100644
--- a/Carpet/CarpetLib/src/timestat.cc
+++ b/Carpet/CarpetLib/src/timestat.cc
@@ -18,7 +18,7 @@ using namespace std;
 
 
 timestat::timestat ()
-  : wtime(0.0), wtime2(0.0), count(0.0),
+  : wtime(0.0), wtime2(0.0), wmin(0.0), wmax(0.0), count(0.0),
     running(false)
 {
 }
@@ -27,6 +27,8 @@ void timestat::addstat (double const t)
 {
   wtime += t;
   wtime2 += t*t;
+  wmin = min (wmin, t);
+  wmax = max (wmax, t);
   ++count;
 }
 
@@ -50,12 +52,14 @@ void timestat::stop ()
 ostream& operator<< (ostream& os, const timestat& wt)
 {
   double const avg = wt.wtime / wt.count;
-  double const stddev = sqrt(max(0.0, wt.wtime2 / wt.count - avg * avg));
+  double const stddev = sqrt (max (0.0, wt.wtime2 / wt.count - pow (avg, 2)));
   os << "timestat[seconds]:"
      << " cnt: " << wt.count
      << " sum: " << wt.wtime
      << " avg: " << avg
-     << " stddev: " << stddev;
+     << " stddev: " << stddev
+     << " min: " << wt.wmin
+     << " max: " << wt.wmax;
   return os;
 }
 
@@ -95,6 +99,16 @@ timestat wtime_isend;
 timestat wtime_isendwait;
 timestat wtime_irecvwait;
 
+timestat wtime_commstate_sizes_irecv;
+timestat wtime_commstate_waitall_final;
+timestat wtime_commstate_waitall;
+timestat wtime_commstate_waitsome;
+timestat wtime_commstate_isend;
+timestat wtime_commstate_memcpy;
+timestat wtime_commstate_interpolate_irecv;
+timestat wtime_commstate_interpolate_from_isend;
+timestat wtime_commstate_interpolate_to_isend;
+
 
 
 extern "C" void CarpetLib_printtimestats (CCTK_ARGUMENTS);
@@ -103,41 +117,54 @@ void CarpetLib_printtimestats (CCTK_ARGUMENTS)
 {
   DECLARE_CCTK_ARGUMENTS;
   DECLARE_CCTK_PARAMETERS;
-  if (print_timestats) {
+  if (print_timestats or
+      (print_timestats_every and
+       cctk_iteration % print_timestats_every == 0))
+  {
     cout << "Timing statistics from CarpetLib:" << endl
-         << "   wtime_copyfrom_recv:                  " << wtime_copyfrom_recv                  << endl
-         << "   wtime_copyfrom_send:                  " << wtime_copyfrom_send                  << endl
-         << "   wtime_copyfrom_wait:                  " << wtime_copyfrom_wait                  << endl
+         << "   wtime_copyfrom_recv:                    " << wtime_copyfrom_recv                  << endl
+         << "   wtime_copyfrom_send:                    " << wtime_copyfrom_send                  << endl
+         << "   wtime_copyfrom_wait:                    " << wtime_copyfrom_wait                  << endl
+         << endl
+         << "   wtime_copyfrom_recv_maketyped:          " << wtime_copyfrom_recv_maketyped        << endl   
+         << "   wtime_copyfrom_recv_allocate:           " << wtime_copyfrom_recv_allocate         << endl
+         << "   wtime_copyfrom_recv_changeproc_recv:    " << wtime_copyfrom_recv_changeproc_recv  << endl
+         << "   wtime_copyfrom_send_copyfrom_nocomm1:   " << wtime_copyfrom_send_copyfrom_nocomm1 << endl
+         << "   wtime_copyfrom_send_copyfrom_nocomm2:   " << wtime_copyfrom_send_copyfrom_nocomm2 << endl
+         << "   wtime_copyfrom_send_changeproc_send:    " << wtime_copyfrom_send_changeproc_send  << endl
+         << "   wtime_copyfrom_wait_changeproc_wait:    " << wtime_copyfrom_wait_changeproc_wait  << endl
+         << "   wtime_copyfrom_wait_copyfrom_nocomm2:   " << wtime_copyfrom_wait_copyfrom_nocomm  << endl
+         << "   wtime_copyfrom_wait_delete:             " << wtime_copyfrom_wait_delete           << endl
          << endl
-         << "   wtime_copyfrom_recv_maketyped:        " << wtime_copyfrom_recv_maketyped        << endl   
-         << "   wtime_copyfrom_recv_allocate:         " << wtime_copyfrom_recv_allocate         << endl
-         << "   wtime_copyfrom_recv_changeproc_recv:  " << wtime_copyfrom_recv_changeproc_recv  << endl
-         << "   wtime_copyfrom_send_copyfrom_nocomm1: " << wtime_copyfrom_send_copyfrom_nocomm1 << endl
-         << "   wtime_copyfrom_send_copyfrom_nocomm2: " << wtime_copyfrom_send_copyfrom_nocomm2 << endl
-         << "   wtime_copyfrom_send_changeproc_send:  " << wtime_copyfrom_send_changeproc_send  << endl
-         << "   wtime_copyfrom_wait_changeproc_wait:  " << wtime_copyfrom_wait_changeproc_wait  << endl
-         << "   wtime_copyfrom_wait_copyfrom_nocomm2: " << wtime_copyfrom_wait_copyfrom_nocomm  << endl
-         << "   wtime_copyfrom_wait_delete:           " << wtime_copyfrom_wait_delete           << endl
+         << "   wtime_copyfrom_recvinner_allocate:      " << wtime_copyfrom_recvinner_allocate    << endl
+         << "   wtime_copyfrom_recvinner_recv:          " << wtime_copyfrom_recvinner_recv        << endl
+         << "   wtime_copyfrom_sendinner_allocate:      " << wtime_copyfrom_sendinner_allocate    << endl
+         << "   wtime_copyfrom_sendinner_copy:          " << wtime_copyfrom_sendinner_copy        << endl
+         << "   wtime_copyfrom_sendinner_send:          " << wtime_copyfrom_sendinner_send        << endl
+         << "   wtime_copyfrom_recvwaitinner_wait:      " << wtime_copyfrom_recvwaitinner_wait    << endl
+         << "   wtime_copyfrom_recvwaitinner_copy:      " << wtime_copyfrom_recvwaitinner_copy    << endl
+         << "   wtime_copyfrom_recvwaitinner_delete:    " << wtime_copyfrom_recvwaitinner_delete  << endl
+         << "   wtime_copyfrom_sendwaitinner_wait:      " << wtime_copyfrom_sendwaitinner_wait    << endl
+         << "   wtime_copyfrom_sendwaitinner_delete:    " << wtime_copyfrom_sendwaitinner_delete  << endl
          << endl
-         << "   wtime_copyfrom_recvinner_allocate:    " << wtime_copyfrom_recvinner_allocate    << endl
-         << "   wtime_copyfrom_recvinner_recv:        " << wtime_copyfrom_recvinner_recv        << endl
-         << "   wtime_copyfrom_sendinner_allocate:    " << wtime_copyfrom_sendinner_allocate    << endl
-         << "   wtime_copyfrom_sendinner_copy:        " << wtime_copyfrom_sendinner_copy        << endl
-         << "   wtime_copyfrom_sendinner_send:        " << wtime_copyfrom_sendinner_send        << endl
-         << "   wtime_copyfrom_recvwaitinner_wait:    " << wtime_copyfrom_recvwaitinner_wait    << endl
-         << "   wtime_copyfrom_recvwaitinner_copy:    " << wtime_copyfrom_recvwaitinner_copy    << endl
-         << "   wtime_copyfrom_recvwaitinner_delete:  " << wtime_copyfrom_recvwaitinner_delete  << endl
-         << "   wtime_copyfrom_sendwaitinner_wait:    " << wtime_copyfrom_sendwaitinner_wait    << endl
-         << "   wtime_copyfrom_sendwaitinner_delete:  " << wtime_copyfrom_sendwaitinner_delete  << endl
+         << "   wtime_changeproc_recv:                  " << wtime_changeproc_recv                << endl
+         << "   wtime_changeproc_send:                  " << wtime_changeproc_send                << endl
+         << "   wtime_changeproc_wait:                  " << wtime_changeproc_wait                << endl
          << endl
-         << "   wtime_changeproc_recv:                " << wtime_changeproc_recv                << endl
-         << "   wtime_changeproc_send:                " << wtime_changeproc_send                << endl
-         << "   wtime_changeproc_wait:                " << wtime_changeproc_wait                << endl
+         << "   wtime_irecv:                            " << wtime_irecv                          << endl
+         << "   wtime_isend:                            " << wtime_isend                          << endl
+         << "   wtime_isendwait:                        " << wtime_isendwait                      << endl
+         << "   wtime_irecvwait:                        " << wtime_irecvwait                      << endl
          << endl
-         << "   wtime_irecv:                          " << wtime_irecv                          << endl
-         << "   wtime_isend:                          " << wtime_isend                          << endl
-         << "   wtime_isendwait:                      " << wtime_isendwait                      << endl
-         << "   wtime_irecvwait:                      " << wtime_irecvwait                      << endl
+         << "   wtime_commstate_sizes_irecv:            " << wtime_commstate_sizes_irecv            << endl
+         << "   wtime_commstate_waitall_final:          " << wtime_commstate_waitall_final          << endl
+         << "   wtime_commstate_waitall:                " << wtime_commstate_waitall                << endl
+         << "   wtime_commstate_waitsome:               " << wtime_commstate_waitsome               << endl
+         << "   wtime_commstate_isend:                  " << wtime_commstate_isend                  << endl
+         << "   wtime_commstate_memcpy:                 " << wtime_commstate_memcpy                 << endl
+         << "   wtime_commstate_interpolate_irecv:      " << wtime_commstate_interpolate_irecv      << endl
+         << "   wtime_commstate_interpolate_from_isend: " << wtime_commstate_interpolate_from_isend << endl
+         << "   wtime_commstate_interpolate_to_isend:   " << wtime_commstate_interpolate_to_isend   << endl
          << endl;
   }
 }
diff --git a/Carpet/CarpetLib/src/timestat.hh b/Carpet/CarpetLib/src/timestat.hh
index 11a7a00aa..896b94236 100644
--- a/Carpet/CarpetLib/src/timestat.hh
+++ b/Carpet/CarpetLib/src/timestat.hh
@@ -13,6 +13,8 @@ class timestat {
 public:
   double wtime;
   double wtime2;
+  double wmin;
+  double wmax;
   double count;
   
 public:
@@ -68,6 +70,14 @@ extern timestat wtime_isend;
 extern timestat wtime_irecvwait;
 extern timestat wtime_isendwait;
 
-
+extern timestat wtime_commstate_sizes_irecv;
+extern timestat wtime_commstate_waitall_final;
+extern timestat wtime_commstate_waitall;
+extern timestat wtime_commstate_waitsome;
+extern timestat wtime_commstate_isend;
+extern timestat wtime_commstate_memcpy;
+extern timestat wtime_commstate_interpolate_irecv;
+extern timestat wtime_commstate_interpolate_from_isend;
+extern timestat wtime_commstate_interpolate_to_isend;
 
 #endif  // TIMESTAT_HH