Fine tune implementation of pipeline timing

Author: Vasileios Karakasis

reframe/frontend/executors/__init__.py

@@ -177,6 +177,17 @@ def _tf(t):
 
         return msg
 
+    def pipeline_timings_all(self):
+        return self.pipeline_timings([
+            'setup', 'compile_complete', 'run_complete',
+            'sanity', 'performance', 'total'
+        ])
+
+    def pipeline_timings_basic(self):
+        return self.pipeline_timings([
+            'compile_complete', 'run_complete', 'total'
+        ])
+
     @property
     def testcase(self):
         return self._case
@@ -210,27 +221,28 @@ def _safe_call(self, fn, *args, **kwargs):
         class update_timestamps:
             '''Context manager to set the start and finish timestamps.'''
 
-            def __init__(self, obj):
-                self.obj = obj
-
-            def __enter__(self):
+            # We use `this` to refer to the update_timestamps object, because
+            # we don't want to masquerade the self argument of our containing
+            # function
+            def __enter__(this):
                 if fn.__name__ != 'poll':
-                    cs = self.obj._current_stage
-                    self.obj._timestamps[f'{cs}_start'] = time.time()
+                    stage = self._current_stage
+                    self._timestamps[f'{stage}_start'] = time.time()
 
-            def __exit__(self, exc_type, exc_value, traceback):
-                cs = self.obj._current_stage
-                self.obj._timestamps[f'{cs}_finish'] = time.time()
-                self.obj._timestamps['pipeline_end'] = time.time()
+            def __exit__(this, exc_type, exc_value, traceback):
+                stage = self._current_stage
+                self._timestamps[f'{stage}_finish'] = time.time()
+                self._timestamps['pipeline_end'] = time.time()
 
         if fn.__name__ != 'poll':
             self._current_stage = fn.__name__
 
         try:
             with logging.logging_context(self.check) as logger:
                 logger.debug(f'entering stage: {self._current_stage}')
-                with update_timestamps(self):
+                with update_timestamps():
                     return fn(*args, **kwargs)
+
         except ABORT_REASONS:
             self.fail()
             raise

reframe/frontend/executors/policies.py

@@ -227,37 +227,19 @@ def on_task_run(self, task):
         self._running_tasks.append(task)
 
     def on_task_failure(self, task):
-        timings = task.pipeline_timings(['compile_complete',
-                                         'run_complete',
-                                         'total'])
-        msg = f'{task.check.info()} [{timings}]'
+        msg = f'{task.check.info()} [{task.pipeline_timings_basic()}]'
         if task.failed_stage == 'cleanup':
             self.printer.status('ERROR', msg, just='right')
         else:
             self._remove_from_running(task)
             self.printer.status('FAIL', msg, just='right')
 
-        timings = task.pipeline_timings(['setup',
-                                         'compile_complete',
-                                         'run_complete',
-                                         'sanity',
-                                         'performance',
-                                         'total'])
-        getlogger().verbose(f"==> {timings}")
+        getlogger().verbose(f"==> {task.pipeline_timings_all()}")
 
     def on_task_success(self, task):
-        timings = task.pipeline_timings(['compile_complete',
-                                         'run_complete',
-                                         'total'])
-        msg = f'{task.check.info()} [{timings}]'
+        msg = f'{task.check.info()} [{task.pipeline_timings_basic()}]'
         self.printer.status('OK', msg, just='right')
-        timings = task.pipeline_timings(['setup',
-                                         'compile_complete',
-                                         'run_complete',
-                                         'sanity',
-                                         'performance',
-                                         'total'])
-        getlogger().verbose(f"==> {timings}")
+        getlogger().verbose(f"==> {task.pipeline_timings_all()}")
         # update reference count of dependencies
         for c in task.testcase.deps:
             self._task_index[c].ref_count -= 1