Carpet: Introduce per-level timers

7 files changed, 129 insertions, 21 deletions

diff --git a/Carpet/Carpet/interface.ccl b/Carpet/Carpet/interface.ccl
index 01241b4eb..023b65ff7 100644
--- a/Carpet/Carpet/interface.ccl
+++ b/Carpet/Carpet/interface.ccl
@@ -315,10 +315,17 @@ CCTK_REAL timing TAGS='checkpoint="no"'
   comm_bytes_per_second
   comm_count
   comm_bytes_count
+  
+  time_levels
 } "Physical timing information"
 
-CCTK_REAL timing2 TYPE=array DIM=1 SIZE=1 DISTRIB=constant TAGS='checkpoint="no"'
+CCTK_REAL timing_procs TYPE=array DIM=1 SIZE=1 DISTRIB=constant TAGS='checkpoint="no"'
 {
   grid_points_per_second
   grid_point_updates_count
 } "Per-processor timing information"
+
+CCTK_REAL timing_levels TYPE=array DIM=1 SIZE=max_refinement_levels DISTRIB=constant TAGS='checkpoint="no"'
+{
+  time_level time_level_count
+} "Per-level timing information"
diff --git a/Carpet/Carpet/schedule.ccl b/Carpet/Carpet/schedule.ccl
index 0f839a5c8..75d4097a5 100644
--- a/Carpet/Carpet/schedule.ccl
+++ b/Carpet/Carpet/schedule.ccl
@@ -1,7 +1,7 @@
 # Schedule definitions for thorn Carpet
 
 storage: point_classification
-storage: timing timing2
+storage: timing timing_procs timing_levels
 
 schedule CarpetMultiModelStartup at STARTUP as MultiModel_Startup before Driver_Startup
 {
diff --git a/Carpet/Carpet/src/Evolve.cc b/Carpet/Carpet/src/Evolve.cc
index 6c65ce0cd..b3d6716b7 100644
--- a/Carpet/Carpet/src/Evolve.cc
+++ b/Carpet/Carpet/src/Evolve.cc
@@ -286,6 +286,8 @@ namespace Carpet {
           {
             BEGIN_MGLEVEL_LOOP (cctkGH) {
               ENTER_LEVEL_MODE (cctkGH, rl) {
+                BeginTimingLevel (cctkGH);
+                
                 do_early_global_mode = reflevel==0;
                 do_late_global_mode = reflevel==reflevels-1;
                 do_early_meta_mode =
@@ -346,6 +348,7 @@ namespace Carpet {
                 
                 do_allow_past_timelevels = old_do_allow_past_timelevels;
                 
+                EndTimingLevel (cctkGH);
               } LEAVE_LEVEL_MODE;
             } END_MGLEVEL_LOOP;
           } // if did_recompose
@@ -388,6 +391,7 @@ namespace Carpet {
         if ((cctkGH->cctk_iteration-1) % do_every == 0) {
           ENTER_GLOBAL_MODE (cctkGH, ml) {
             ENTER_LEVEL_MODE (cctkGH, rl) {
+              BeginTimingLevel (cctkGH);
               
               do_early_global_mode = not have_done_global_mode;
               do_late_global_mode = reflevel==reflevels-1;
@@ -469,6 +473,7 @@ namespace Carpet {
               
               do_taper = false;
               
+              EndTimingLevel (cctkGH);
             } LEAVE_LEVEL_MODE;
           } LEAVE_GLOBAL_MODE;
         } // if do_every
@@ -496,12 +501,14 @@ namespace Carpet {
         if (cctkGH->cctk_iteration % do_every == 0) {
           ENTER_GLOBAL_MODE (cctkGH, ml) {
             ENTER_LEVEL_MODE (cctkGH, rl) {
+              BeginTimingLevel (cctkGH);
               
               Waypoint ("Evolution/Restrict at iteration %d time %g",
                         cctkGH->cctk_iteration, (double)cctkGH->cctk_time);
               
               Restrict (cctkGH);
               
+              EndTimingLevel (cctkGH);
             } LEAVE_LEVEL_MODE;
           } LEAVE_GLOBAL_MODE;
         } // if do_every
@@ -533,6 +540,7 @@ namespace Carpet {
         if (cctkGH->cctk_iteration % do_every == 0) {
           ENTER_GLOBAL_MODE (cctkGH, ml) {
             ENTER_LEVEL_MODE (cctkGH, rl) {
+              BeginTimingLevel (cctkGH);
               
               do_early_global_mode = not have_done_global_mode;
               do_late_global_mode = reflevel==reflevels-1;
@@ -594,6 +602,7 @@ namespace Carpet {
               
               do_taper = false;
               
+              EndTimingLevel (cctkGH);
             } LEAVE_LEVEL_MODE;
           } LEAVE_GLOBAL_MODE;
         } // if do_every
diff --git a/Carpet/Carpet/src/Initialise.cc b/Carpet/Carpet/src/Initialise.cc
index e25b2c6c6..daa563105 100644
--- a/Carpet/Carpet/src/Initialise.cc
+++ b/Carpet/Carpet/src/Initialise.cc
@@ -155,7 +155,9 @@ namespace Carpet {
       {
         int const rl=0;
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
           Poison (cctkGH, alltimes, CCTK_ARRAY);
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       }
       
@@ -187,6 +189,8 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_early_global_mode = reflevel==0;
           do_late_global_mode = reflevel==reflevels-1;
           do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -217,9 +221,12 @@ namespace Carpet {
           }
           
           if (regrid_during_recovery) {
+            EndTimingLevel (cctkGH);
             CallRegridRecoverLevel (cctkGH);
+            BeginTimingLevel (cctkGH);
           }
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -247,6 +254,8 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_early_global_mode = reflevel==0;
           do_late_global_mode = reflevel==reflevels-1;
           do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -309,6 +318,7 @@ namespace Carpet {
           
           CheckChecksums (cctkGH, allbutcurrenttime);
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -337,10 +347,12 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
           
           // Checking
           Poison (cctkGH, alltimes, CCTK_GF);
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -348,6 +360,8 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_early_global_mode = reflevel==0;
           do_late_global_mode = reflevel==reflevels-1;
           do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -428,9 +442,12 @@ namespace Carpet {
           
           if (regrid_during_initialisation and mglevel==0) {
             // Regrid after initialising each level
+            EndTimingLevel (cctkGH);
             CallRegridInitialLevel (cctkGH);
+            BeginTimingLevel (cctkGH);
           }
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -446,12 +463,14 @@ namespace Carpet {
     for (int rl=reflevels-1; rl>=0; --rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
           
           Waypoint ("Initialisation/Restrict at iteration %d time %g",
                     cctkGH->cctk_iteration, (double)cctkGH->cctk_time);
           
           Restrict (cctkGH);
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -469,6 +488,8 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_early_global_mode = reflevel==0;
           do_late_global_mode = reflevel==reflevels-1;
           do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -491,6 +512,7 @@ namespace Carpet {
           PoisonCheck (cctkGH, alltimes);
           CheckChecksums (cctkGH, allbutcurrenttime);
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -510,6 +532,8 @@ namespace Carpet {
     for (int rl=0; rl<reflevels; ++rl) {
       BEGIN_MGLEVEL_LOOP(cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_early_global_mode = reflevel==0;
           do_late_global_mode = reflevel==reflevels-1;
           do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -545,6 +569,7 @@ namespace Carpet {
             CheckChecksums (cctkGH, allbutcurrenttime);
           } // if do_every
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -609,6 +634,8 @@ namespace Carpet {
           if (callpostregrid and (did_recompose or not callregrid)) {
             BEGIN_MGLEVEL_LOOP (cctkGH) {
               ENTER_LEVEL_MODE (cctkGH, rl) {
+                BeginTimingLevel (cctkGH);
+                
                 do_global_mode = reflevel == reflevels - 1;
                 do_meta_mode = do_global_mode and mglevel==mglevels-1;
                 
@@ -678,6 +705,7 @@ namespace Carpet {
                 
                 do_allow_past_timelevels = old_do_allow_past_timelevels;
                 
+                EndTimingLevel (cctkGH);
               } LEAVE_LEVEL_MODE;
             } END_MGLEVEL_LOOP;
           } // if did_recompose
@@ -718,6 +746,8 @@ namespace Carpet {
       
       BEGIN_MGLEVEL_LOOP (cctkGH) {
         ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
           do_global_mode = reflevel == reflevels - 1;
           do_meta_mode = do_global_mode and mglevel==mglevels-1;
           
@@ -772,6 +802,7 @@ namespace Carpet {
           
           do_allow_past_timelevels = old_do_allow_past_timelevels;
           
+          EndTimingLevel (cctkGH);
         } LEAVE_LEVEL_MODE;
       } END_MGLEVEL_LOOP;
     } // for rl
@@ -835,6 +866,8 @@ namespace Carpet {
           if (did_recompose) {
             BEGIN_MGLEVEL_LOOP (cctkGH) {
               ENTER_LEVEL_MODE (cctkGH, rl) {
+                BeginTimingLevel (cctkGH);
+                
                 do_early_global_mode = reflevel==0;
                 do_late_global_mode = reflevel==reflevels-1;
                 do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -894,6 +927,7 @@ namespace Carpet {
                 
                 do_allow_past_timelevels = old_do_allow_past_timelevels;
                 
+                EndTimingLevel (cctkGH);
               } LEAVE_LEVEL_MODE;
             } END_MGLEVEL_LOOP;
           } // if did_recompose
@@ -942,6 +976,7 @@ namespace Carpet {
     
     ENTER_GLOBAL_MODE (cctkGH, 0) {
       ENTER_LEVEL_MODE (cctkGH, 0) {
+        BeginTimingLevel (cctkGH);
         
         // Preregrid
         Waypoint ("Preregridinitial at iteration %d time %g%s%s",
@@ -964,6 +999,7 @@ namespace Carpet {
         
         RegridFree (cctkGH, prolongate_initial_data);
         
+        EndTimingLevel (cctkGH);
       } LEAVE_LEVEL_MODE;
     } LEAVE_GLOBAL_MODE;
     
@@ -1029,6 +1065,8 @@ namespace Carpet {
           if (did_recompose) {
             BEGIN_MGLEVEL_LOOP (cctkGH) {
               ENTER_LEVEL_MODE (cctkGH, rl) {
+                BeginTimingLevel (cctkGH);
+                
                 do_early_global_mode = reflevel==0;
                 do_late_global_mode = reflevel==reflevels-1;
                 do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -1089,6 +1127,7 @@ namespace Carpet {
                 
                 do_allow_past_timelevels = old_do_allow_past_timelevels;
                 
+                EndTimingLevel (cctkGH);
               } LEAVE_LEVEL_MODE;
             } END_MGLEVEL_LOOP;
           } // if did_recompose
@@ -1152,6 +1191,8 @@ namespace Carpet {
     
     BEGIN_MGLEVEL_LOOP(cctkGH) {
       BEGIN_REFLEVEL_LOOP(cctkGH) {
+        BeginTimingLevel (cctkGH);
+        
         do_early_global_mode = reflevel==0;
         do_late_global_mode = reflevel==reflevels-1;
         do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -1165,6 +1206,7 @@ namespace Carpet {
         initialise_3tl_evolve_Ib (cctkGH);
         initialise_3tl_flip_timelevels (cctkGH);
         
+        EndTimingLevel (cctkGH);
       } END_REFLEVEL_LOOP;
     } END_MGLEVEL_LOOP;
     
@@ -1174,6 +1216,8 @@ namespace Carpet {
     
     BEGIN_MGLEVEL_LOOP(cctkGH) {
       BEGIN_REVERSE_REFLEVEL_LOOP(cctkGH) {
+        BeginTimingLevel (cctkGH);
+        
         do_early_global_mode = reflevel==reflevels-1;
         do_late_global_mode = reflevel==0;
         do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -1185,6 +1229,7 @@ namespace Carpet {
         initialise_3tl_advance_time_2 (cctkGH);
         initialise_3tl_evolve_Ic (cctkGH);
         
+        EndTimingLevel (cctkGH);
       } END_REVERSE_REFLEVEL_LOOP;
     } END_MGLEVEL_LOOP;
     
@@ -1192,6 +1237,8 @@ namespace Carpet {
     
     BEGIN_MGLEVEL_LOOP(cctkGH) {
       BEGIN_REVERSE_REFLEVEL_LOOP(cctkGH) {
+        BeginTimingLevel (cctkGH);
+        
         do_early_global_mode = reflevel==reflevels-1;
         do_late_global_mode = reflevel==0;
         do_early_meta_mode = do_early_global_mode and mglevel==mglevels-1;
@@ -1201,6 +1248,7 @@ namespace Carpet {
         
         initialise_3tl_reset_time (cctkGH);
         
+        EndTimingLevel (cctkGH);
       } END_REVERSE_REFLEVEL_LOOP;
     } END_MGLEVEL_LOOP;
     
diff --git a/Carpet/Carpet/src/Shutdown.cc b/Carpet/Carpet/src/Shutdown.cc
index 6da0daf3e..e6171dfcb 100644
--- a/Carpet/Carpet/src/Shutdown.cc
+++ b/Carpet/Carpet/src/Shutdown.cc
@@ -30,25 +30,27 @@ namespace Carpet {
     timer.start();
     for (int rl=reflevels-1; rl>=0; --rl) {
       BEGIN_REVERSE_MGLEVEL_LOOP(cctkGH) {
-        enter_level_mode (cctkGH, rl);
-        
-        do_early_global_mode = reflevel==reflevels-1;
-        do_late_global_mode = reflevel==0;
-        do_early_meta_mode = do_early_global_mode and mglevel==0;
-        do_late_meta_mode = do_late_global_mode and mglevel==mglevels-1;
-        do_global_mode = do_late_global_mode;
-        do_meta_mode = do_late_meta_mode;
-        
-        Checkpoint ("Shutdown at iteration %d time %g%s%s",
-                    cctkGH->cctk_iteration, (double)cctkGH->cctk_time,
-                    (do_global_mode ? " (global)" : ""),
-                    (do_meta_mode ? " (meta)" : ""));
-        
-        // Terminate
-        Checkpoint ("Scheduling TERMINATE");
-        CCTK_ScheduleTraverse ("CCTK_TERMINATE", cctkGH, CallFunction);
-        
-        leave_level_mode (cctkGH);
+        ENTER_LEVEL_MODE (cctkGH, rl) {
+          BeginTimingLevel (cctkGH);
+          
+          do_early_global_mode = reflevel==reflevels-1;
+          do_late_global_mode = reflevel==0;
+          do_early_meta_mode = do_early_global_mode and mglevel==0;
+          do_late_meta_mode = do_late_global_mode and mglevel==mglevels-1;
+          do_global_mode = do_late_global_mode;
+          do_meta_mode = do_late_meta_mode;
+          
+          Checkpoint ("Shutdown at iteration %d time %g%s%s",
+                      cctkGH->cctk_iteration, (double)cctkGH->cctk_time,
+                      (do_global_mode ? " (global)" : ""),
+                      (do_meta_mode ? " (meta)" : ""));
+          
+          // Terminate
+          Checkpoint ("Scheduling TERMINATE");
+          CCTK_ScheduleTraverse ("CCTK_TERMINATE", cctkGH, CallFunction);
+          
+          EndTimingLevel (cctkGH);
+        } LEAVE_LEVEL_MODE;
       } END_REVERSE_MGLEVEL_LOOP;
     } // for rl
     
diff --git a/Carpet/Carpet/src/Timing.cc b/Carpet/Carpet/src/Timing.cc
index 2fd24f3bd..51ecc45e8 100644
--- a/Carpet/Carpet/src/Timing.cc
+++ b/Carpet/Carpet/src/Timing.cc
@@ -132,6 +132,10 @@ namespace Carpet {
   timing_state_t timing_state = state_computing;
   CCTK_REAL time_start;
   
+  // Last starting time for this level
+  int timing_level = -1;
+  CCTK_REAL time_level_start;
+  
   
   
   // Initialise the timing variables (to be called before basegrid)
@@ -139,6 +143,7 @@ namespace Carpet {
   InitTimingStats (cGH const * const cctkGH)
   {
     DECLARE_CCTK_ARGUMENTS;
+    DECLARE_CCTK_PARAMETERS;
     
     startup_walltime = get_walltime();
     
@@ -172,8 +177,15 @@ namespace Carpet {
     * comm_count            = 0.0;
     * comm_bytes_count      = 0.0;
     
+    * time_levels = 0.0;
+    
     * grid_points_per_second   = 0.0;
     * grid_point_updates_count = 0.0;
+    
+    for (int rl=0; rl<max_refinement_levels; ++rl) {
+      time_level      [rl] = 0.0;
+      time_level_count[rl] = 0.0;
+    }
   }
   
   
@@ -215,6 +227,34 @@ namespace Carpet {
   
   
   
+  // Count time spent on individual levels (to be called from Carpet's
+  // initialisation, evolution, and shutdown drivers)
+  void
+  BeginTimingLevel (cGH const * const cctkGH)
+  {
+    assert (reflevel != -1);
+    assert (timing_level == -1);
+    timing_level = reflevel;
+    time_level_start = get_walltime();
+  }
+  
+  void
+  EndTimingLevel (cGH const * const cctkGH)
+  {
+    DECLARE_CCTK_ARGUMENTS;
+    
+    assert (reflevel != -1);
+    assert (timing_level == reflevel);
+    timing_level = -1;
+    CCTK_REAL const time_level_end = get_walltime();
+    
+    time_level[reflevel] += time_level_end - time_level_start;
+    ++ time_level_count[reflevel];
+    * time_levels  += time_level_end - time_level_start;
+  }
+  
+  
+  
   // Count some I/O (to be called from the I/O routine)
   void
   BeginTimingIO (cGH const * const cctkGH)
diff --git a/Carpet/Carpet/src/functions.hh b/Carpet/Carpet/src/functions.hh
index e1fd104b8..5f1539a36 100644
--- a/Carpet/Carpet/src/functions.hh
+++ b/Carpet/Carpet/src/functions.hh
@@ -180,6 +180,8 @@ namespace Carpet {
   void InitTimingStats (cGH const * cctkGH);
   void BeginTimingEvolution (cGH const * cctkGH);
   void StepTimingEvolution (cGH const * cctkGH);
+  void BeginTimingLevel (cGH const * cctkGH);
+  void EndTimingLevel (cGH const * cctkGH);
   void BeginTimingIO (cGH const * cctkGH);
   void EndTimingIO (cGH const * cctkGH,
                     CCTK_REAL files, CCTK_REAL bytes, bool is_binary);