Carpet: More work on timers

Store physical timing information in grid scalars for easier output.

Introduce a parameter "Carpet::silent" to switch off periodic output
of the physical timing information.

Add detailed timers for Carpet's main evolution loop, using Cactus
timers.  Their output would usually be written to files.

darcs-hash:20060727165144-dae7b-aac1f402b3d23351153dfa8b48ee52a29d05e94e.gz

7 files changed, 226 insertions, 22 deletions

diff --git a/Carpet/Carpet/interface.ccl b/Carpet/Carpet/interface.ccl
index b5839262d..44f24150b 100644
--- a/Carpet/Carpet/interface.ccl
+++ b/Carpet/Carpet/interface.ccl
@@ -136,3 +136,11 @@ CCTK_INT FUNCTION IO_TruncateOutputFiles \
   (CCTK_POINTER_TO_CONST IN GH)
 
 REQUIRES FUNCTION IO_TruncateOutputFiles
+
+
+
+CCTK_REAL timing
+{
+  grid_points_per_second
+  physical_time_per_hour
+} "Timing information"
diff --git a/Carpet/Carpet/param.ccl b/Carpet/Carpet/param.ccl
index cd1d79ab2..f8270c5da 100644
--- a/Carpet/Carpet/param.ccl
+++ b/Carpet/Carpet/param.ccl
@@ -305,7 +305,11 @@ BOOLEAN suppress_restriction "Suppress the restriction operations.  This makes t
 
 
 
-BOOLEAN verbose "Display info on the screen" STEERABLE=always
+BOOLEAN silent "Display no info on the screen" STEERABLE=always
+{
+} "no"
+
+BOOLEAN verbose "Display more info on the screen" STEERABLE=always
 {
 } "no"
 
@@ -321,6 +325,24 @@ BOOLEAN output_internal_data "Periodically print internal data to the screen for
 {
 } "no"
 
+INT print_timestats_every "Print interesting timing statistics periodically" STEERABLE=always
+{
+  0   :: "don't report"
+  1:* :: "report every so many iterations"
+} 1
+
+INT output_timers_every "Print detailed statistics periodically" STEERABLE=always
+{
+  0   :: "don't report"
+  1:* :: "report every so many iterations"
+} 1
+
+STRING timer_file "File name in which detailed timing statistics are collected" STEERABLE=recover
+{
+  "^$"   :: "empty filename: no file output"
+  "^.+$" :: "file name"
+} "carpet-timing-statistics"
+
 
 
 KEYWORD processor_topology "How to determine the processor topology" STEERABLE=recover
diff --git a/Carpet/Carpet/schedule.ccl b/Carpet/Carpet/schedule.ccl
index 60fd793b3..b5b421e67 100644
--- a/Carpet/Carpet/schedule.ccl
+++ b/Carpet/Carpet/schedule.ccl
@@ -1,5 +1,7 @@
 # Schedule definitions for thorn Carpet
 
+storage: timing
+
 schedule CarpetMultiModelStartup at STARTUP as MultiModel_Startup before Driver_Startup
 {
   LANG: C
diff --git a/Carpet/Carpet/src/Evolve.cc b/Carpet/Carpet/src/Evolve.cc
index 6006303f6..06bd88038 100644
--- a/Carpet/Carpet/src/Evolve.cc
+++ b/Carpet/Carpet/src/Evolve.cc
@@ -1,10 +1,13 @@
 #include <cassert>
+#include <cstdio>
 #include <cstdlib>
 
 #include "cctk.h"
 #include "cctk_Parameters.h"
 #include "cctk_Termination.h"
 
+#include "util_String.h"
+
 // IRIX wants this before <time.h>
 #if HAVE_SYS_TYPES_H
 #  include <sys/types.h>
@@ -22,6 +25,7 @@
 #endif
 
 #if HAVE_UNISTD_H
+#  include <fcntl.h>
 #  include <unistd.h>
 #endif
 
@@ -38,6 +42,18 @@ namespace Carpet {
 
 
 
+  static int evolve_timer            ;
+  static int do_terminate_timer      ;
+  static int advance_time_timer      ;
+  static int preregrid_timer         ;
+  static int regrid_timer            ;
+  static int postregrid_timer        ;
+  static int evolution_i_timer       ;
+  static int evolution_restrict_timer;
+  static int evolution_ii_timer      ;
+
+
+
   static bool do_terminate (const cGH *cgh,
                             const CCTK_REAL time, const int iteration)
   {
@@ -135,13 +151,32 @@ namespace Carpet {
     const int convlev = 0;
     cGH* cgh = fc->GH[convlev];
 
+    // Create timers
+    evolve_timer             = CCTK_TimerCreate ("Carpet::Evolve"           );
+    do_terminate_timer       = CCTK_TimerCreate ("Carpet::do_terminate"     );
+    advance_time_timer       = CCTK_TimerCreate ("Carpet::AdvanceTime"      );
+    preregrid_timer          = CCTK_TimerCreate ("Carpet::PreRegrid"        );
+    regrid_timer             = CCTK_TimerCreate ("Carpet::Regrid"           );
+    postregrid_timer         = CCTK_TimerCreate ("Carpet::PostRegrid"       );
+    evolution_i_timer        = CCTK_TimerCreate ("Carpet::EvolutionI"       );
+    evolution_restrict_timer = CCTK_TimerCreate ("Carpet::EvolutionRestrict");
+    evolution_ii_timer       = CCTK_TimerCreate ("Carpet::EvolutionII"      );
+
     // Timing statistics
     InitTiming (cgh);
 
     // Main loop
-    while (! do_terminate(cgh, cgh->cctk_time, cgh->cctk_iteration)) {
-
+    CCTK_TimerStartI (evolve_timer);
+    for (;;) {
+      CCTK_TimerStartI (do_terminate_timer);
+      bool const do_term =
+        do_terminate (cgh, cgh->cctk_time, cgh->cctk_iteration);
+      CCTK_TimerStopI (do_terminate_timer);
+      if (do_term) break;
+
+      CCTK_TimerStartI (advance_time_timer);
       AdvanceTime( cgh, cctk_initial_time );
+      CCTK_TimerStopI (advance_time_timer);
 
       if ((cgh->cctk_iteration-1)
           % (maxtimereflevelfact / timereffacts.at(reflevels-1)) == 0) {
@@ -149,16 +184,31 @@ namespace Carpet {
                   cgh->cctk_iteration, (double)cgh->cctk_time);
       }
 
-      PreRegrid( cgh );
-
-      if( Regrid( cgh ) )
-        PostRegrid( cgh );
+      CCTK_TimerStartI (preregrid_timer);
+      PreRegrid (cgh);
+      CCTK_TimerStopI (preregrid_timer);
+
+      CCTK_TimerStartI (regrid_timer);
+      bool const did_regrid = Regrid (cgh);
+      CCTK_TimerStopI (regrid_timer);
+      
+      if (did_regrid) {
+        CCTK_TimerStartI (postregrid_timer);
+        PostRegrid (cgh);
+        CCTK_TimerStopI (postregrid_timer);
+      }
 
-      EvolutionI( cgh );
+      CCTK_TimerStartI (evolution_i_timer);
+      EvolutionI (cgh);
+      CCTK_TimerStopI (evolution_i_timer);
 
-      Evolution_Restrict( cgh );
+      CCTK_TimerStartI (evolution_restrict_timer);
+      Evolution_Restrict (cgh);
+      CCTK_TimerStopI (evolution_restrict_timer);
 
-      EvolutionII( cgh );
+      CCTK_TimerStartI (evolution_ii_timer);
+      EvolutionII (cgh);
+      CCTK_TimerStopI (evolution_ii_timer);
 
       if (output_internal_data) {
         CCTK_INFO ("Internal data dump:");
@@ -170,7 +220,94 @@ namespace Carpet {
         cout.precision (oldprecision);
       }
 
-    }
+      if ((cgh->cctk_iteration - 1) %
+          (maxtimereflevelfact / timereffacts.at(reflevels - 1)) == 0 and
+          output_timers_every > 0 and
+          (cgh->cctk_iteration - 1) % output_timers_every == 0)
+      {
+        // Print timer values
+        
+        int fdsave;
+        if (not CCTK_EQUALS (timer_file, "")) {
+#ifndef HAVE_UNISTD_H
+          CCTK_WARN (1, "Cannot redirect timer output to a file; the operating system does not support this");
+#else // #ifdef HAVE_UNISTD_H
+          
+          int const myproc = CCTK_MyProc (cgh);
+          char filename [10000];
+          Util_snprintf (filename, sizeof filename,
+                         "%s/%s.%04d.txt", out_dir, timer_file, myproc);
+          
+          // append
+          int flags = O_WRONLY | O_CREAT | O_APPEND;
+          static bool first_time = true;
+          if (first_time) {
+            first_time = false;
+            if (IO_TruncateOutputFiles (cgh)) {
+              // truncate
+              flags = O_WRONLY | O_CREAT | O_TRUNC;
+            }
+          }
+          
+          // Temporarily redirect stdout
+          fflush (stdout);
+          fdsave = dup (1);      // fd 1 is stdout
+          int const mode = 0644; // rw-r--r--, or a+r u+w
+          int const fdfile = open (filename, flags, mode);
+          if (fdfile < 0)
+          {
+            CCTK_VWarn (1, __LINE__, __FILE__, CCTK_THORNSTRING,
+                        "Could not open timer output file \"%s\"", filename);
+            goto cleanup;
+          }
+          close (1);
+          dup (fdfile);         // dup to 1, i.e., stdout again
+          close (fdfile);
+#endif  // #ifdef HAVE_UNISTD_H
+        }
+        
+        // Output the timers
+        printf ("Carpet Timing information at iteration %d time %g:\n",
+                cgh->cctk_iteration, (double) cgh->cctk_time);
+        CCTK_TimerStopI (evolve_timer);
+        CCTK_TimerPrintDataI (evolve_timer            , -1);
+        CCTK_TimerPrintDataI (do_terminate_timer      , -1);
+        CCTK_TimerPrintDataI (advance_time_timer      , -1);
+        CCTK_TimerPrintDataI (preregrid_timer         , -1);
+        CCTK_TimerPrintDataI (regrid_timer            , -1);
+        CCTK_TimerPrintDataI (postregrid_timer        , -1);
+        CCTK_TimerPrintDataI (evolution_i_timer       , -1);
+        CCTK_TimerPrintDataI (evolution_restrict_timer, -1);
+        CCTK_TimerPrintDataI (evolution_ii_timer      , -1);
+        CCTK_TimerStartI (evolve_timer);
+        printf ("\n********************************************************************************\n");
+        
+        if (not CCTK_EQUALS (timer_file, "")) {
+#ifdef HAVE_UNISTD_H
+          // Redirect stdout back
+          fflush (stdout);
+          close (1);
+          dup (fdsave);
+        cleanup:
+          close (fdsave);
+#endif  // #ifdef HAVE_UNISTD_H
+        }
+        
+      } // if timer output
+
+    } // end main loop
+    CCTK_TimerStopI (evolve_timer);
+
+    // Destroy timers
+    CCTK_TimerDestroyI (evolve_timer            );
+    CCTK_TimerDestroyI (do_terminate_timer      );
+    CCTK_TimerDestroyI (advance_time_timer      );
+    CCTK_TimerDestroyI (preregrid_timer         );
+    CCTK_TimerDestroyI (regrid_timer            );
+    CCTK_TimerDestroyI (postregrid_timer        );
+    CCTK_TimerDestroyI (evolution_i_timer       );
+    CCTK_TimerDestroyI (evolution_restrict_timer);
+    CCTK_TimerDestroyI (evolution_ii_timer      );
 
     Waypoint ("Done with evolution loop");
 
@@ -359,6 +496,8 @@ namespace Carpet {
 
   void EvolutionII( cGH* cgh )
   {
+    DECLARE_CCTK_PARAMETERS;
+
     for (int ml=mglevels-1; ml>=0; --ml) {
 
       bool have_done_global_mode = false;
@@ -422,6 +561,14 @@ namespace Carpet {
           // Checking
           CheckChecksums (cgh, alltimes);
 
+          if (do_global_mode and
+              print_timestats_every > 0 and
+              cgh->cctk_iteration % print_timestats_every == 0)
+          {
+            // Timing statistics
+            PrintTimingStats (cgh);
+          }
+
           leave_level_mode (cgh);
           leave_global_mode (cgh);
         }
@@ -430,11 +577,6 @@ namespace Carpet {
       if (have_done_anything)
         assert (have_done_global_mode);
 
-      if (have_done_anything) {
-        // Timing statistics
-        PrintTimingStats (cgh);
-      }
-
     }
 
   }
diff --git a/Carpet/Carpet/src/Initialise.cc b/Carpet/Carpet/src/Initialise.cc
index c3e60f346..50d284ac3 100644
--- a/Carpet/Carpet/src/Initialise.cc
+++ b/Carpet/Carpet/src/Initialise.cc
@@ -299,6 +299,11 @@ namespace Carpet {
       Checkpoint ("Scheduling BASEGRID");
       CCTK_ScheduleTraverse ("CCTK_BASEGRID", cgh, CallFunction);
 
+      // Timing statistics
+      if (do_global_mode) {
+        InitTimingVariables (cgh);
+      }
+
       const int num_tl = init_each_timelevel ? 3 : 1;
 
       initialise_I_rewind (cgh, num_tl);
diff --git a/Carpet/Carpet/src/Timing.cc b/Carpet/Carpet/src/Timing.cc
index 0af37f964..a6f5d3e2b 100644
--- a/Carpet/Carpet/src/Timing.cc
+++ b/Carpet/Carpet/src/Timing.cc
@@ -4,6 +4,7 @@
 #include <cstdlib>
 
 #include "cctk.h"
+#include "cctk_Arguments.h"
 #include "cctk_Parameters.h"
 
 // IRIX wants this before <time.h>
@@ -112,6 +113,18 @@ namespace Carpet {
   
   
   
+  // Initialise the timing variables (to be called during Initialise)
+  void
+  InitTimingVariables (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
+    
+    * grid_points_per_second = 0;
+    * physical_time_per_hour = 0;
+  }
+  
+  
+  
   // Initialise the timing statistics (to be called at the beginning
   // of Evolve)
   void
@@ -139,6 +152,7 @@ namespace Carpet {
   void
   PrintUpdatesPerSecond (cGH const * const cctkGH)
   {
+    DECLARE_CCTK_ARGUMENTS;
     DECLARE_CCTK_PARAMETERS;
     
     // Measure the elapsed time
@@ -147,9 +161,13 @@ namespace Carpet {
     // Calculate updates per second
     CCTK_REAL const updates_per_second = total_updates / elapsed_walltime;
     
-    CCTK_VInfo (CCTK_THORNSTRING,
-                "Grid point updates per process per second: %g",
-                double (updates_per_second));
+    * grid_points_per_second = updates_per_second;
+    
+    if (not silent) {
+      CCTK_VInfo (CCTK_THORNSTRING,
+                  "Grid point updates per process per second: %g",
+                  double (updates_per_second));
+    }
     
 #if 0
     CCTK_REAL const updates_per_second_2 = ipow (updates_per_second, 2);
@@ -186,6 +204,9 @@ namespace Carpet {
   void
   PrintPhysicalTimePerHour (cGH const * const cctkGH)
   {
+    DECLARE_CCTK_ARGUMENTS;
+    DECLARE_CCTK_PARAMETERS;
+    
     // Measure the elapsed time
     CCTK_REAL const elapsed_walltime = get_walltime() - initial_walltime;
     
@@ -193,11 +214,14 @@ namespace Carpet {
     CCTK_REAL const physical_time = cctkGH->cctk_time - initial_phystime;
     
     // Calculate physical time per hour
-    CCTK_REAL const physical_time_per_hour =
+    * physical_time_per_hour =
       physical_time / elapsed_walltime * CCTK_REAL (3600.0);
     
-    CCTK_VInfo (CCTK_THORNSTRING,
-                "Physical time per hour: %g", double (physical_time_per_hour));
+    if (not silent) {
+      CCTK_VInfo (CCTK_THORNSTRING,
+                  "Physical time per hour: %g",
+                  double (* physical_time_per_hour));
+    }
   }
 
 
diff --git a/Carpet/Carpet/src/functions.hh b/Carpet/Carpet/src/functions.hh
index 75df336fb..968d07036 100644
--- a/Carpet/Carpet/src/functions.hh
+++ b/Carpet/Carpet/src/functions.hh
@@ -123,6 +123,7 @@ namespace Carpet {
   
   
   // Timing statistics functions
+  void InitTimingVariables (cGH const * const cctkGH);
   void InitTiming (cGH const * const cctkGH);
   void StepTiming (cGH const * const cctkGH);
   void PrintTimingStats (cGH const * const cctkGH);