Merge pull request #112 from xylar/add-step-timers

Add timers to steps as they run in a suite or task

polaris/run/serial.py

@@ -4,6 +4,7 @@
 import pickle
 import sys
 import time
+from datetime import timedelta
 
 import mpas_tools.io
 from mpas_tools.logging import LoggingContext, check_call
@@ -231,15 +232,11 @@ def _log_test_runtimes(stdout_logger, test_times, success_strs, suite_time,
     """
     stdout_logger.info('Test Runtimes:')
     for test_name, test_time in test_times.items():
-        secs = round(test_time)
-        mins = secs // 60
-        secs -= 60 * mins
-        stdout_logger.info(f'{mins:02d}:{secs:02d} '
+        test_time_str = str(timedelta(seconds=round(test_time)))
+        stdout_logger.info(f'{test_time_str} '
                            f'{success_strs[test_name]} {test_name}')
-    secs = round(suite_time)
-    mins = secs // 60
-    secs -= 60 * mins
-    stdout_logger.info(f'Total runtime {mins:02d}:{secs:02d}')
+    suite_time_str = str(timedelta(seconds=round(suite_time)))
+    stdout_logger.info(f'Total runtime: {suite_time_str}')
 
     if failures == 0:
         stdout_logger.info('PASS: All passed successfully!')
@@ -380,11 +377,9 @@ def _log_and_run_test(test_case, stdout_logger, test_logger, quiet,
 
         test_time = time.time() - test_start
 
-        secs = round(test_time)
-        mins = secs // 60
-        secs -= 60 * mins
+        test_time_str = str(timedelta(seconds=round(test_time)))
         stdout_logger.info(f'  test runtime:        '
-                           f'{start_time_color}{mins:02d}:{secs:02d}{end}')
+                           f'{start_time_color}{test_time_str}{end}')
 
         return success_str, success, test_time
 
@@ -393,10 +388,15 @@ def _run_test(test_case, available_resources):
     """
     Run each step of the test case
     """
+    start_time_color = '\033[94m'
+    end = '\033[0m'
+
     logger = test_case.logger
     cwd = os.getcwd()
     for step_name in test_case.steps_to_run:
         step = test_case.steps[step_name]
+        step_start = time.time()
+
         if step.cached:
             logger.info(f'  * Cached step: {step_name}')
             continue
@@ -419,6 +419,11 @@ def _run_test(test_case, available_resources):
             _print_to_stdout(test_case, '      Failed')
             raise
         os.chdir(cwd)
+        step_time = time.time() - step_start
+        step_time_str = str(timedelta(seconds=round(step_time)))
+        _print_to_stdout(test_case,
+                         f'          runtime:     '
+                         f'{start_time_color}{step_time_str}{end}')
 
 
 def _run_step(test_case, step, new_log_file, available_resources,