Merge pull request #1325 from ekouts/feat/time_profiling

[feat] Add execution time profiling for the framework's pipeline

Author: Vasileios Karakasis

docs/pipeline.rst

@@ -132,3 +132,19 @@ ReFrame tries to keep concurrency high by maintaining as many test cases as poss
 When the `concurrency limit <config_reference.html#.systems[].partitions[].max_jobs>`__ is reached, ReFrame will first try to free up execution slots by checking if any of the spawned jobs have finished, and it will fill that slots first before throttling execution.
 
 ReFrame uses polling to check the status of the spawned jobs, but it does so in a dynamic way, in order to ensure both responsiveness and avoid overloading the system job scheduler with excessive polling.
+
+Timing the Test Pipeline
+------------------------
+
+.. versionadded:: 3.0
+
+ReFrame keeps track of the time a test spends in every pipeline stage and reports that after each test finishes.
+However, it does so from its own perspective and not from that of the scheduler backend used.
+This has some practical implications:
+As soon as a test enters the "run" phase, ReFrame's timer for that phase starts ticking regardless if the associated job is pending.
+Similarly, the "run" phase ends as soon as ReFrame realizes it.
+This will happen after the associated job has finished.
+For this reason, the time spent in the pipeline's "run" phase should *not* be interpreted as the actual runtime of the test, especially if a non-local scheduler backend is used.
+
+Finally, the execution time of the "cleanup" phase is not reported when a test finishes, since it may be deferred in case that there exist tests that depend on that one.
+See :doc:`dependencies` for more information on how ReFrame treats tests with dependencies.

docs/tutorial_basic.rst

@@ -177,50 +177,51 @@ If everything is configured correctly for your system, you should get an output
 
 .. code-block:: none
 
-   [ReFrame Setup]
-     version:           3.0-dev6 (rev: 89d50861)
-     command:           './bin/reframe -C tutorial/config/settings.py -c tutorial/example1.py -r'
-     launched by:       user@daint101
-     working directory: '/path/to/reframe'
-     check search path: (R) '/path/to/reframe/tutorial/example1.py'
-     stage directory:   '/path/to/reframe/stage'
-     output directory:  '/path/to/reframe/output'
-
-   [==========] Running 1 check(s)
-   [==========] Started on Sat May  9 22:10:16 2020
-
-   [----------] started processing Example1Test (Simple matrix-vector multiplication example)
-   [ RUN      ] Example1Test on daint:login using PrgEnv-cray
-   [ RUN      ] Example1Test on daint:login using PrgEnv-gnu
-   [ RUN      ] Example1Test on daint:login using PrgEnv-intel
-   [ RUN      ] Example1Test on daint:login using PrgEnv-pgi
-   [ RUN      ] Example1Test on daint:gpu using PrgEnv-cray
-   [ RUN      ] Example1Test on daint:gpu using PrgEnv-gnu
-   [ RUN      ] Example1Test on daint:gpu using PrgEnv-intel
-   [ RUN      ] Example1Test on daint:gpu using PrgEnv-pgi
-   [ RUN      ] Example1Test on daint:mc using PrgEnv-cray
-   [ RUN      ] Example1Test on daint:mc using PrgEnv-gnu
-   [ RUN      ] Example1Test on daint:mc using PrgEnv-intel
-   [ RUN      ] Example1Test on daint:mc using PrgEnv-pgi
-   [----------] finished processing Example1Test (Simple matrix-vector multiplication example)
-
-   [----------] waiting for spawned checks to finish
-   [       OK ] ( 1/12) Example1Test on daint:mc using PrgEnv-cray
-   [       OK ] ( 2/12) Example1Test on daint:gpu using PrgEnv-intel
-   [       OK ] ( 3/12) Example1Test on daint:gpu using PrgEnv-cray
-   [       OK ] ( 4/12) Example1Test on daint:login using PrgEnv-intel
-   [       OK ] ( 5/12) Example1Test on daint:login using PrgEnv-cray
-   [       OK ] ( 6/12) Example1Test on daint:mc using PrgEnv-gnu
-   [       OK ] ( 7/12) Example1Test on daint:gpu using PrgEnv-gnu
-   [       OK ] ( 8/12) Example1Test on daint:login using PrgEnv-gnu
-   [       OK ] ( 9/12) Example1Test on daint:login using PrgEnv-pgi
-   [       OK ] (10/12) Example1Test on daint:gpu using PrgEnv-pgi
-   [       OK ] (11/12) Example1Test on daint:mc using PrgEnv-intel
-   [       OK ] (12/12) Example1Test on daint:mc using PrgEnv-pgi
-   [----------] all spawned checks have finished
-
-   [  PASSED  ] Ran 12 test case(s) from 1 check(s) (0 failure(s))
-   [==========] Finished on Sat May  9 22:10:46 2020
+  [ReFrame Setup]
+    version:           3.0-dev7 (rev: 85ca676f)
+    command:           './bin/reframe -C tutorial/config/settings.py -c tutorial/example1.py -r'
+    launched by:       user@daint104
+    working directory: '/path/to/reframe'
+    settings file:     'tutorial/config/settings.py'
+    check search path: (R) '/path/to/reframe/tutorial/example1.py'
+    stage directory:   '/path/to/reframe/stage'
+    output directory:  '/path/to/reframe/output'
+
+  [==========] Running 1 check(s)
+  [==========] Started on Wed Jun  3 08:50:46 2020
+
+  [----------] started processing Example1Test (Simple matrix-vector multiplication example)
+  [ RUN      ] Example1Test on daint:login using PrgEnv-cray
+  [ RUN      ] Example1Test on daint:login using PrgEnv-gnu
+  [ RUN      ] Example1Test on daint:login using PrgEnv-intel
+  [ RUN      ] Example1Test on daint:login using PrgEnv-pgi
+  [ RUN      ] Example1Test on daint:gpu using PrgEnv-cray
+  [ RUN      ] Example1Test on daint:gpu using PrgEnv-gnu
+  [ RUN      ] Example1Test on daint:gpu using PrgEnv-intel
+  [ RUN      ] Example1Test on daint:gpu using PrgEnv-pgi
+  [ RUN      ] Example1Test on daint:mc using PrgEnv-cray
+  [ RUN      ] Example1Test on daint:mc using PrgEnv-gnu
+  [ RUN      ] Example1Test on daint:mc using PrgEnv-intel
+  [ RUN      ] Example1Test on daint:mc using PrgEnv-pgi
+  [----------] finished processing Example1Test (Simple matrix-vector multiplication example)
+
+  [----------] waiting for spawned checks to finish
+  [       OK ] ( 1/12) Example1Test on daint:login using PrgEnv-intel [compile: 1.940s run: 20.747s total: 23.778s]
+  [       OK ] ( 2/12) Example1Test on daint:login using PrgEnv-cray [compile: 0.347s run: 25.096s total: 26.591s]
+  [       OK ] ( 3/12) Example1Test on daint:mc using PrgEnv-intel [compile: 2.019s run: 6.286s total: 8.357s]
+  [       OK ] ( 4/12) Example1Test on daint:mc using PrgEnv-cray [compile: 0.506s run: 11.056s total: 11.744s]
+  [       OK ] ( 5/12) Example1Test on daint:gpu using PrgEnv-cray [compile: 0.435s run: 19.499s total: 20.483s]
+  [       OK ] ( 6/12) Example1Test on daint:login using PrgEnv-gnu [compile: 1.648s run: 25.631s total: 27.964s]
+  [       OK ] ( 7/12) Example1Test on daint:mc using PrgEnv-gnu [compile: 1.825s run: 10.434s total: 12.301s]
+  [       OK ] ( 8/12) Example1Test on daint:gpu using PrgEnv-intel [compile: 2.018s run: 16.316s total: 18.529s]
+  [       OK ] ( 9/12) Example1Test on daint:login using PrgEnv-pgi [compile: 1.643s run: 22.118s total: 24.090s]
+  [       OK ] (10/12) Example1Test on daint:gpu using PrgEnv-gnu [compile: 1.729s run: 20.028s total: 21.901s]
+  [       OK ] (11/12) Example1Test on daint:gpu using PrgEnv-pgi [compile: 1.753s run: 15.128s total: 16.923s]
+  [       OK ] (12/12) Example1Test on daint:mc using PrgEnv-pgi [compile: 1.732s run: 35.556s total: 37.330s]
+  [----------] all spawned checks have finished
+
+  [  PASSED  ] Ran 12 test case(s) from 1 check(s) (0 failure(s))
+  [==========] Finished on Wed Jun  3 08:51:46 2020
 
 
 Notice how our regression test is run on every partition of the configured system and for every programming environment.

docs/tutorial_deps.rst

@@ -77,7 +77,7 @@ Here is the output when running the OSU tests with the asynchronous execution po
 .. code-block:: none
 
   [==========] Running 7 check(s)
-  [==========] Started on Wed Mar 25 13:51:06 2020
+  [==========] Started on Wed Jun  3 09:00:40 2020
 
   [----------] started processing OSUBuildTest (OSU benchmarks build test)
   [ RUN      ] OSUBuildTest on daint:gpu using PrgEnv-gnu
@@ -140,31 +140,31 @@ Here is the output when running the OSU tests with the asynchronous execution po
   [----------] finished processing OSUAllreduceTest_16 (OSU Allreduce test)
 
   [----------] waiting for spawned checks to finish
-  [       OK ] ( 1/21) OSUBuildTest on daint:gpu using PrgEnv-pgi
-  [       OK ] ( 2/21) OSUBuildTest on daint:gpu using PrgEnv-gnu
-  [       OK ] ( 3/21) OSUBuildTest on daint:gpu using PrgEnv-intel
-  [       OK ] ( 4/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-pgi
-  [       OK ] ( 5/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-pgi
-  [       OK ] ( 6/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-pgi
-  [       OK ] ( 7/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-pgi
-  [       OK ] ( 8/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-gnu
-  [       OK ] ( 9/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-gnu
-  [       OK ] (10/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-gnu
-  [       OK ] (11/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-intel
-  [       OK ] (12/21) OSULatencyTest on daint:gpu using PrgEnv-pgi
-  [       OK ] (13/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-gnu
-  [       OK ] (14/21) OSULatencyTest on daint:gpu using PrgEnv-gnu
-  [       OK ] (15/21) OSUBandwidthTest on daint:gpu using PrgEnv-pgi
-  [       OK ] (16/21) OSUBandwidthTest on daint:gpu using PrgEnv-gnu
-  [       OK ] (17/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-intel
-  [       OK ] (18/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-intel
-  [       OK ] (19/21) OSULatencyTest on daint:gpu using PrgEnv-intel
-  [       OK ] (20/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-intel
-  [       OK ] (21/21) OSUBandwidthTest on daint:gpu using PrgEnv-intel
+  [       OK ] ( 1/21) OSUBuildTest on daint:gpu using PrgEnv-pgi [compile: 29.581s run: 0.086s total: 29.708s]
+  [       OK ] ( 2/21) OSUBuildTest on daint:gpu using PrgEnv-gnu [compile: 26.250s run: 69.120s total: 95.437s]
+  [       OK ] ( 3/21) OSUBuildTest on daint:gpu using PrgEnv-intel [compile: 39.385s run: 89.213s total: 129.871s]
+  [       OK ] ( 4/21) OSULatencyTest on daint:gpu using PrgEnv-pgi [compile: 0.012s run: 145.355s total: 154.504s]
+  [       OK ] ( 5/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-pgi [compile: 0.014s run: 148.276s total: 154.433s]
+  [       OK ] ( 6/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-pgi [compile: 0.011s run: 149.763s total: 154.407s]
+  [       OK ] ( 7/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-pgi [compile: 0.013s run: 151.262s total: 154.378s]
+  [       OK ] ( 8/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-pgi [compile: 0.010s run: 152.716s total: 154.360s]
+  [       OK ] ( 9/21) OSULatencyTest on daint:gpu using PrgEnv-gnu [compile: 0.014s run: 210.952s total: 220.847s]
+  [       OK ] (10/21) OSUBandwidthTest on daint:gpu using PrgEnv-pgi [compile: 0.015s run: 213.285s total: 220.758s]
+  [       OK ] (11/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-gnu [compile: 0.011s run: 215.596s total: 220.717s]
+  [       OK ] (12/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-gnu [compile: 0.011s run: 218.742s total: 220.651s]
+  [       OK ] (13/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-intel [compile: 0.013s run: 203.214s total: 206.115s]
+  [       OK ] (14/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-intel [compile: 0.016s run: 204.819s total: 206.078s]
+  [       OK ] (15/21) OSUBandwidthTest on daint:gpu using PrgEnv-gnu [compile: 0.012s run: 258.772s total: 266.873s]
+  [       OK ] (16/21) OSUAllreduceTest_8 on daint:gpu using PrgEnv-gnu [compile: 0.014s run: 263.576s total: 266.752s]
+  [       OK ] (17/21) OSULatencyTest on daint:gpu using PrgEnv-intel [compile: 0.011s run: 227.234s total: 231.789s]
+  [       OK ] (18/21) OSUAllreduceTest_4 on daint:gpu using PrgEnv-intel [compile: 0.013s run: 229.729s total: 231.724s]
+  [       OK ] (19/21) OSUAllreduceTest_2 on daint:gpu using PrgEnv-gnu [compile: 0.013s run: 286.203s total: 292.444s]
+  [       OK ] (20/21) OSUAllreduceTest_16 on daint:gpu using PrgEnv-intel [compile: 0.028s run: 242.030s total: 242.091s]
+  [       OK ] (21/21) OSUBandwidthTest on daint:gpu using PrgEnv-intel [compile: 0.013s run: 243.719s total: 247.384s]
   [----------] all spawned checks have finished
 
   [  PASSED  ] Ran 21 test case(s) from 7 check(s) (0 failure(s))
-  [==========] Finished on Wed Mar 25 14:37:53 2020
+  [==========] Finished on Wed Jun  3 09:07:24 2020
 
 Before starting running the tests, ReFrame topologically sorts them based on their dependencies and schedules them for running using the selected execution policy.
 With the serial execution policy, ReFrame simply executes the tests to completion as they "arrive", since the tests are already topologically sorted.

reframe/frontend/executors/__init__.py

@@ -7,6 +7,7 @@
 import copy
 import signal
 import sys
+import time
 import weakref
 
 import reframe.core.debug as debug
@@ -130,6 +131,63 @@ def __init__(self, case, listeners=[]):
         # Test case has finished, but has not been waited for yet
         self.zombie = False
 
+        # Timestamps for the start and finish phases of the pipeline
+        self._timestamps = {}
+
+    def duration(self, phase):
+        # Treat pseudo-phases first
+        if phase == 'compile_complete':
+            t_start = 'compile_start'
+            t_finish = 'compile_wait_finish'
+        elif phase == 'run_complete':
+            t_start = 'run_start'
+            t_finish = 'wait_finish'
+        elif phase == 'total':
+            t_start = 'setup_start'
+            t_finish = 'pipeline_end'
+        else:
+            t_start  = f'{phase}_start'
+            t_finish = f'{phase}_finish'
+
+        start = self._timestamps.get(t_start)
+        if not start:
+            return None
+
+        finish = self._timestamps.get(t_finish)
+        if not finish:
+            finish = self._timestamps.get('pipeline_end')
+
+        return finish - start
+
+    def pipeline_timings(self, phases):
+        def _tf(t):
+            return f'{t:.3f}s' if t else 'n/a'
+
+        msg = ''
+        for phase in phases:
+            if phase == 'compile_complete':
+                msg += f"compile: {_tf(self.duration('compile_complete'))} "
+            elif phase == 'run_complete':
+                msg += f"run: {_tf(self.duration('run_complete'))} "
+            else:
+                msg += f"{phase}: {_tf(self.duration(phase))} "
+
+        if msg:
+            msg = msg[:-1]
+
+        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
@@ -160,13 +218,31 @@ def _notify_listeners(self, callback_name):
             callback(self)
 
     def _safe_call(self, fn, *args, **kwargs):
+        class update_timestamps:
+            '''Context manager to set the start and finish timestamps.'''
+
+            # 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':
+                    stage = self._current_stage
+                    self._timestamps[f'{stage}_start'] = 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('entering stage: %s' % self._current_stage)
-                return fn(*args, **kwargs)
+                logger.debug(f'entering stage: {self._current_stage}')
+                with update_timestamps():
+                    return fn(*args, **kwargs)
+
         except ABORT_REASONS:
             self.fail()
             raise

reframe/frontend/executors/policies.py

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