Carpet: Avoid nans in timing output

darcs-hash:20071006164252-dae7b-98b2b1c19dc9e52e6c1feaf7b75919766ca1b29c.gz

4 files changed, 182 insertions, 134 deletions

diff --git a/Carpet/Carpet/src/Evolve.cc b/Carpet/Carpet/src/Evolve.cc
index 86a5c0dbc..574dbc246 100644
--- a/Carpet/Carpet/src/Evolve.cc
+++ b/Carpet/Carpet/src/Evolve.cc
@@ -51,9 +51,6 @@ namespace Carpet {
     int const convlev = 0;
     cGH* cctkGH = fc->GH[convlev];
     
-    // Timing statistics
-    InitTiming (cctkGH);
-    
     // Tapered grids
     do_taper = use_tapered_grids;
     
@@ -482,6 +479,11 @@ namespace Carpet {
               // Analysis
               ScheduleTraverse (where, "CCTK_ANALYSIS", cctkGH);
               
+              if (do_global_mode) {
+                // Timing statistics
+                UpdateTimingStats (cctkGH);
+              }
+              
               // Output
               OutputGH (where, cctkGH);
               
diff --git a/Carpet/Carpet/src/Initialise.cc b/Carpet/Carpet/src/Initialise.cc
index 56d6ec12c..a773a8a5a 100644
--- a/Carpet/Carpet/src/Initialise.cc
+++ b/Carpet/Carpet/src/Initialise.cc
@@ -186,14 +186,14 @@ namespace Carpet {
           // Checking
           Poison (cctkGH, alltimes, CCTK_GF);
           
-          // Set up the grids
-          ScheduleTraverse (where, "CCTK_BASEGRID", cctkGH);
-          
           // Timing statistics
           if (do_global_mode) {
-            InitTimingVariables (cctkGH);
+            InitTimingStats (cctkGH);
           }
           
+          // Set up the grids
+          ScheduleTraverse (where, "CCTK_BASEGRID", cctkGH);
+          
           // Recover
           ScheduleTraverse (where, "CCTK_RECOVER_VARIABLES", cctkGH);
           
@@ -280,14 +280,14 @@ namespace Carpet {
           // Checking
           Poison (cctkGH, alltimes, CCTK_GF);
           
-          // Set up the grids
-          ScheduleTraverse (where, "CCTK_BASEGRID", cctkGH);
-          
           // Timing statistics
           if (do_global_mode) {
-            InitTimingVariables (cctkGH);
+            InitTimingStats (cctkGH);
           }
           
+          // Set up the grids
+          ScheduleTraverse (where, "CCTK_BASEGRID", cctkGH);
+          
           int const num_tl =
             init_each_timelevel ? prolongation_order_time+1 : 1;
           bool const old_do_allow_past_timelevels = do_allow_past_timelevels;
@@ -426,6 +426,11 @@ namespace Carpet {
             // Analysis
             ScheduleTraverse (where, "CCTK_ANALYSIS", cctkGH);
             
+            if (do_global_mode) {
+              // Timing statistics
+              UpdateTimingStats (cctkGH);
+            }
+            
             // Output
             OutputGH (where, cctkGH);
             
diff --git a/Carpet/Carpet/src/Timing.cc b/Carpet/Carpet/src/Timing.cc
index 789441653..49fff1177 100644
--- a/Carpet/Carpet/src/Timing.cc
+++ b/Carpet/Carpet/src/Timing.cc
@@ -125,12 +125,15 @@ namespace Carpet {
   
   
   
-  // Initialise the timing variables (to be called during Initialise)
+  // Initialise the timing variables (to be called before basegrid)
   void
-  InitTimingVariables (cGH const * const cctkGH)
+  InitTimingStats (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
     
+    initial_walltime = get_walltime();
+    initial_phystime = cctkGH->cctk_time;
+    
     * physical_time_per_hour = 0.0;
     
     * time_total         = 0.0;
@@ -157,23 +160,12 @@ namespace Carpet {
     * comm_count            = 0.0;
     * comm_bytes_count      = 0.0;
     
-    * grid_points_per_second = 0.0;
+    * grid_points_per_second   = 0.0;
     * grid_point_updates_count = 0.0;
   }
   
   
   
-  // Initialise the timing statistics (to be called at the beginning
-  // of Evolve)
-  void
-  InitTiming (cGH const * const cctkGH)
-  {
-    initial_walltime = get_walltime();
-    initial_phystime = cctkGH->cctk_time;
-  }
-  
-  
-  
   // Take a step on the current refinement and multigrid level (to be
   // called when EVOL is scheduled)
   void
@@ -252,10 +244,9 @@ namespace Carpet {
   
   static
   void
-  PrintTimes (cGH const * const cctkGH)
+  UpdateTimes (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
-    DECLARE_CCTK_PARAMETERS;
     
     assert (timing_state == state_computing);
     
@@ -263,157 +254,201 @@ namespace Carpet {
     * time_total = get_walltime() - initial_walltime;
     
     * time_computing = * time_total - (* time_communicating + * time_io);
-    
-    if (print_timestats_every > 0 and
-        cctkGH->cctk_iteration % print_timestats_every == 0)
-    {
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "Total run time second: %g", double (* time_total));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "(Comp, Comm, I/O) fractions = (%3.1f, %3.1f, %3.1f)",
-                  double (100.0 * * time_computing     / * time_total),
-                  double (100.0 * * time_communicating / * time_total),
-                  double (100.0 * * time_io            / * time_total));
-    }
   }
   
   
   
   static
   void
-  PrintUpdatesPerSecond (cGH const * const cctkGH)
+  UpdateUpdatesPerSecond (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
-    DECLARE_CCTK_PARAMETERS;
     
     // Calculate updates per second
     * local_grid_points_per_second =
-      * local_grid_point_updates_count / * time_computing;
+      * local_grid_point_updates_count / max (* time_computing, 1.0e-15);
     * total_grid_points_per_second =
-      * total_grid_point_updates_count / * time_computing;
+      * total_grid_point_updates_count / max (* time_computing, 1.0e-15);
     
     * grid_points_per_second = * local_grid_points_per_second;
+  }
+  
+  
+  
+  static
+  void
+  UpdateIOStats (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
     
-    if (print_timestats_every > 0 and
-        cctkGH->cctk_iteration % print_timestats_every == 0)
-    {
-      
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "This processor's grid point updates per second (local): %g",
-                  double (* local_grid_points_per_second));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "Overall grid point updates per second (total)         : %g",
-                  double (* total_grid_points_per_second));
+    * io_per_second =
+      * io_count              / max (* time_io, 1.0e-15);
+    * io_bytes_per_second =
+      * io_bytes_count        / max (* time_io, 1.0e-15);
+    * io_bytes_ascii_per_second =
+      * io_bytes_ascii_count  / max (* time_io, 1.0e-15);
+    * io_bytes_binary_per_second =
+      * io_bytes_binary_count / max (* time_io, 1.0e-15);
+  }
+  
+  
+  
+  static
+  void
+  UpdateCommunicationStats (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
     
-#if 0
-      CCTK_REAL const updates_per_second_2 = ipow (updates_per_second, 2);
-      
-      struct {
-        CCTK_REAL ups, ups2;
-      } local, global;
-      local.ups  = updates_per_second;
-      local.ups2 = updates_per_second_2;
-      MPI_Allreduce (& local, & global, 2,
-                     dist::datatype (global.ups), MPI_SUM, dist::comm());
-      
-      int const count = dist::size();
-      CCTK_REAL const avg = global.ups / count;
-      CCTK_REAL const stddev = sqrt (abs (global.ups2 - ipow (avg,2)) / count);
-      
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "Local updates per second:   %g", double (updates_per_second));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "Global updates per second:  %g", double (global.ups));
-      
-      if (verbose) {
-        CCTK_VInfo (CCTK_THORNSTRING,
-                    "Average updates per second: %g", double (avg));
-        CCTK_VInfo (CCTK_THORNSTRING,
-                    "Standard deviation:         %g", double (stddev));
-      }
-#endif
-      
-    }
+    * comm_per_second =
+      * comm_count       / max (* time_communicating, 1.0e-15);
+    * comm_bytes_per_second =
+      * comm_bytes_count / max (* time_communicating, 1.0e-15);
   }
   
   
   
   static
   void
-  PrintIOStats (cGH const * const cctkGH)
+  UpdatePhysicalTimePerHour (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
-    DECLARE_CCTK_PARAMETERS;
     
-    * io_per_second              = * io_count              / * time_io;
-    * io_bytes_per_second        = * io_bytes_count        / * time_io;
-    * io_bytes_ascii_per_second  = * io_bytes_ascii_count  / * time_io;
-    * io_bytes_binary_per_second = * io_bytes_binary_count / * time_io;
+    // Calculate elapsed physical time
+    CCTK_REAL const physical_time = cctkGH->cctk_time - initial_phystime;
     
-    if (print_timestats_every > 0 and
-        cctkGH->cctk_iteration % print_timestats_every == 0)
-    {
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "I/O operations per second:     %g",
-                  double (* io_per_second));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "I/O bytes per second:          %g",
-                  double (* io_bytes_per_second));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "I/O bytes per second (ASCII):  %g",
-                  double (* io_bytes_ascii_per_second));
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "I/O bytes per second (binary): %g",
-                  double (* io_bytes_binary_per_second));
-    }
+    // Calculate physical time per hour
+    * physical_time_per_hour =
+      3600.0 * physical_time / max (* time_computing, 1.0e-15);
+  }
+  
+  
+  
+  // Calculate timing statistics (to be called before output)
+  void
+  UpdateTimingStats (cGH const * const cctkGH)
+  {
+    UpdateTimes (cctkGH);
+    UpdateUpdatesPerSecond (cctkGH);
+    UpdateIOStats (cctkGH);
+    UpdateCommunicationStats (cctkGH);
+    UpdatePhysicalTimePerHour (cctkGH);
   }
   
   
   
   static
   void
-  PrintCommunicationStats (cGH const * const cctkGH)
+  PrintTimes (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
+    
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Total run time: %g h", double (* time_total / 3600.0));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "(Comp, Comm, I/O) fractions = (%3.1f%%, %3.1f%%, %3.1f%%)",
+                double (100.0 * * time_computing /
+                        max (* time_total, 1.0e-15)),
+                double (100.0 * * time_communicating /
+                        max (* time_total, 1.0e-15)),
+                double (100.0 * * time_io /
+                        max (* time_total, 1.0e-15)));
+  }
+  
+  
+  
+  static
+  void
+  PrintUpdatesPerSecond (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
     DECLARE_CCTK_PARAMETERS;
     
-    * comm_per_second       = * comm_count       / * time_communicating;
-    * comm_bytes_per_second = * comm_bytes_count / * time_communicating;
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "This processor's grid point updates per second (local): %g",
+                double (* local_grid_points_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Overall grid point updates per second (total)         : %g",
+                double (* total_grid_points_per_second));
     
-    if (print_timestats_every > 0 and
-        cctkGH->cctk_iteration % print_timestats_every == 0)
-    {
+#if 0
+    CCTK_REAL const updates_per_second_2 = ipow (updates_per_second, 2);
+    
+    struct {
+      CCTK_REAL ups, ups2;
+    } local, global;
+    local.ups  = updates_per_second;
+    local.ups2 = updates_per_second_2;
+    MPI_Allreduce (& local, & global, 2,
+                   dist::datatype (global.ups), MPI_SUM, dist::comm());
+    
+    int const count = dist::size();
+    CCTK_REAL const avg = global.ups / count;
+    CCTK_REAL const stddev = sqrt (abs (global.ups2 - ipow (avg,2)) / count);
+    
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Local updates per second:   %g",
+                double (updates_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Global updates per second:  %g", double (global.ups));
+    
+    if (verbose) {
       CCTK_VInfo (CCTK_THORNSTRING,
-                  "Communication operations per second: %g",
-                  double (* comm_per_second));
+                  "Average updates per second: %g", double (avg));
       CCTK_VInfo (CCTK_THORNSTRING,
-                  "Communicated bytes per second:       %g",
-                  double (* comm_bytes_per_second));
+                  "Standard deviation:         %g", double (stddev));
     }
+#endif
   }
   
   
   
   static
   void
-  PrintPhysicalTimePerHour (cGH const * const cctkGH)
+  PrintIOStats (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
-    DECLARE_CCTK_PARAMETERS;
     
-    // Calculate elapsed physical time
-    CCTK_REAL const physical_time = cctkGH->cctk_time - initial_phystime;
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "I/O operations per second:     %g",
+                double (* io_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "I/O bytes per second:          %g",
+                double (* io_bytes_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "I/O bytes per second (ASCII):  %g",
+                double (* io_bytes_ascii_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "I/O bytes per second (binary): %g",
+                double (* io_bytes_binary_per_second));
+  }
+  
+  
+  
+  static
+  void
+  PrintCommunicationStats (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
     
-    // Calculate physical time per hour
-    * physical_time_per_hour = 3600.0 * physical_time / * time_computing;
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Communication operations per second: %g",
+                double (* comm_per_second));
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Communicated bytes per second:       %g",
+                double (* comm_bytes_per_second));
+  }
+  
+  
+  
+  static
+  void
+  PrintPhysicalTimePerHour (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
     
-    if (print_timestats_every > 0 and
-        cctkGH->cctk_iteration % print_timestats_every == 0)
-    {
-      CCTK_VInfo (CCTK_THORNSTRING,
-                  "Physical time per hour: %g",
-                  double (* physical_time_per_hour));
-    }
+    CCTK_VInfo (CCTK_THORNSTRING,
+                "Physical time per hour: %g",
+                double (* physical_time_per_hour));
   }
 
 
@@ -423,11 +458,17 @@ namespace Carpet {
   void
   PrintTimingStats (cGH const * const cctkGH)
   {
-    PrintTimes (cctkGH);
-    PrintUpdatesPerSecond (cctkGH);
-    PrintIOStats (cctkGH);
-    PrintCommunicationStats (cctkGH);
-    PrintPhysicalTimePerHour (cctkGH);
+    DECLARE_CCTK_PARAMETERS;
+    
+    if (print_timestats_every > 0 and
+        cctkGH->cctk_iteration % print_timestats_every == 0)
+    {
+      PrintTimes (cctkGH);
+      PrintUpdatesPerSecond (cctkGH);
+      PrintIOStats (cctkGH);
+      PrintCommunicationStats (cctkGH);
+      PrintPhysicalTimePerHour (cctkGH);
+    }
   }
   
 } // namespace Carpet
diff --git a/Carpet/Carpet/src/functions.hh b/Carpet/Carpet/src/functions.hh
index 62490dab1..812230cc4 100644
--- a/Carpet/Carpet/src/functions.hh
+++ b/Carpet/Carpet/src/functions.hh
@@ -161,8 +161,7 @@ namespace Carpet {
   
   
   // Timing statistics functions
-  void InitTimingVariables (cGH const * cctkGH);
-  void InitTiming (cGH const * cctkGH);
+  void InitTimingStats (cGH const * cctkGH);
   void StepTiming (cGH const * cctkGH);
   void BeginTimingIO (cGH const * cctkGH);
   void EndTimingIO (cGH const * cctkGH,
@@ -170,6 +169,7 @@ namespace Carpet {
   void BeginTimingCommunication (cGH const * cctkGH);
   void EndTimingCommunication (cGH const * cctkGH,
                                CCTK_REAL messages, CCTK_REAL bytes);
+  void UpdateTimingStats (cGH const * cctkGH);
   void PrintTimingStats (cGH const * cctkGH);
   
 } // namespace Carpet