[grid] in tlau/gridpacks/MG5aMC_patches add python timers to all rele…

…vant cudacpp debug printputs

epochX/cudacpp/tlau/gridpacks/MG5aMC_patches/cluster.py

@@ -728,12 +728,16 @@ def launch_and_wait(self, prog, argument=[], cwd=None, stdout=None,
                                 stderr=None, log=None, **opts):
         """launch one job and wait for it"""    
         print("__CUDACPP_DEBUG: MultiCore.launch_and_wait starting '" + prog + "'")
+        cudacpp_start = time.perf_counter()
         if isinstance(stdout, str):
             stdout = open(stdout, 'w')
         if isinstance(stderr, str):
             stdout = open(stderr, 'w')        
-        return misc.call([prog] + argument, stdout=stdout, stderr=stderr, cwd=cwd) 
-        print("__CUDACPP_DEBUG: MultiCore.launch_and_wait finished '" + prog + "'")
+        out = misc.call([prog] + argument, stdout=stdout, stderr=stderr, cwd=cwd) 
+        cudacpp_end = time.perf_counter()
+        cudacpp_length = cudacpp_end - cudacpp_start
+        print("__CUDACPP_DEBUG: MultiCore.launch_and_wait finished '" + prog + "' in %.4f seconds"%cudacpp_length)
+        return out
 
     def remove(self, error=None):
         """Ensure that all thread are killed"""

epochX/cudacpp/tlau/gridpacks/MG5aMC_patches/gen_ximprove.py

@@ -30,6 +30,7 @@
 import stat
 import sys
 import six
+import time # for __CUDACPP_DEBUG
 from six.moves import range
 from six.moves import zip
 
@@ -1069,6 +1070,7 @@ def __call__(self):
     def launch(self):
         """running """  
         print("__CUDACPP_DEBUG: gen_ximprove.launch starting")
+        cudacpp_start = time.perf_counter()
         #start the run
         self.handle_seed()
         self.results = sum_html.collect_result(self.cmd, 
@@ -1079,7 +1081,9 @@ def launch(self):
         else:
             # We run to achieve a given precision
             self.get_job_for_precision()
-        print("__CUDACPP_DEBUG: gen_ximprove.launch finished")
+        cudacpp_end = time.perf_counter()
+        cudacpp_length = cudacpp_end - cudacpp_start
+        print("__CUDACPP_DEBUG: gen_ximprove.launch finished in %.4f seconds"%cudacpp_length)
 
 
     def configure(self, opt):
@@ -1883,7 +1887,7 @@ def get_job_for_event(self):
         """generate the script in order to generate a given number of event"""
         # correspond to write_gen in the fortran version
         print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event starting")
-
+        cudacpp_start = time.perf_counter()
 
         goal_lum, to_refine = self.find_job_for_event()
 
@@ -1956,7 +1960,6 @@ def get_job_for_event(self):
             print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event will call launch_and_wait '" + exe + "'")
             cluster.onecore.launch_and_wait(exe, cwd=pwd, packet_member=j['packet'])
             print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event back from launch_and_wait '" + exe + "'")
-            print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event starting dumping logs from '" + exe + "'")
             for log in glob.glob(pwd+'/G*/GridRun_21_app.log'):
                 print(log)
                 with open(log, 'r') as f:
@@ -1967,7 +1970,9 @@ def get_job_for_event(self):
         write_dir = '.' if self.readonly else pjoin(self.me_dir, 'SubProcesses')
 
         self.check_events(goal_lum, to_refine, jobs, write_dir)
-        print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event finished")
+        cudacpp_end = time.perf_counter()
+        cudacpp_length = cudacpp_end - cudacpp_start
+        print("__CUDACPP_DEBUG: gen_ximprove_gridpack.get_job_for_event finished in %.4f seconds"%cudacpp_length)
 
     def check_events(self, goal_lum, to_refine, jobs, Sdir):
         """check that we get the number of requested events if not resubmit."""

epochX/cudacpp/tlau/gridpacks/MG5aMC_patches/madevent_interface.py

@@ -6723,6 +6723,7 @@ def prepare_local_dir(self):
     def launch(self, nb_event, seed):
         """ launch the generation for the grid """
         print("__CUDACPP_DEBUG: GridPackCmd.launch starting")
+        cudacpp_start = time.perf_counter()
         # 1) Restore the default data
         print("__CUDACPP_DEBUG: GridPackCmd.launch (1) restore_data")
         logger.info('generate %s events' % nb_event)
@@ -6765,11 +6766,14 @@ def launch(self, nb_event, seed):
             self.exec_cmd('systematics %s --from_card' % 
                           pjoin('Events', self.run_name, 'unweighted_events.lhe.gz'),
                                                postcmd=False,printcmd=False)
-        print("__CUDACPP_DEBUG: GridPackCmd.launch finished")
+        cudacpp_end = time.perf_counter()
+        cudacpp_length = cudacpp_end - cudacpp_start
+        print("__CUDACPP_DEBUG: GridPackCmd.launch finished in %.4f seconds"%cudacpp_length)
 
     def refine4grid(self, nb_event):
         """Special refine for gridpack run."""
         print("__CUDACPP_DEBUG: GridPackCmd.refine4grid starting")
+        cudacpp_start = time.perf_counter()
         self.nb_refine += 1
 
         precision = nb_event
@@ -6798,8 +6802,10 @@ def refine4grid(self, nb_event):
         #print 'run combine!!!'
         #combine_runs.CombineRuns(self.me_dir)
 
-        print("__CUDACPP_DEBUG: GridPackCmd.refine4grid finished") # ?!? what is the code after return ?!?
-        return
+        cudacpp_end = time.perf_counter()
+        cudacpp_length = cudacpp_end - cudacpp_start
+        print("__CUDACPP_DEBUG: GridPackCmd.refine4grid finished in %.4f seconds"%cudacpp_length)
+        return # ?!? what is the code after return ?!?
         #update html output
         Presults = sum_html.collect_result(self)
         cross, error = Presults.xsec, Presults.xerru