ENH: Improve logging of runtime

mriqc/cli/run.py

@@ -37,7 +37,7 @@ def main():
 
     atexit.register(config.restore_env)
 
-    start_time = time.time()
+    config.settings.start_time = time.time()
 
     # Run parser
     parse_args()
@@ -176,8 +176,12 @@ def main():
 
             generate_reports()
 
-        config.loggers.cli.log(26, messages.PARTICIPANT_FINISHED.format(
-            duration=time.strftime('%Hh %Mmin %Ss', time.gmtime(time.time() - start_time))
+        _subject_duration = time.gmtime(
+            (time.time() - config.settings.start_time)
+            / sum(len(files) for files in config.workflow.inputs.values())
+        )
+        config.loggers.cli.log(25, messages.PARTICIPANT_FINISHED.format(
+            duration=time.strftime('%Hh %Mmin %Ss', _subject_duration)
         ))
 
         if _resmon is not None:
@@ -200,7 +204,7 @@ def main():
 
         from ..utils.misc import generate_tsv  # , generate_pred
 
-        config.loggers.cli.info(messages.GROUP_START)
+        config.loggers.cli.log(26, messages.GROUP_START)
 
         # Generate reports
         mod_group_reports = []
@@ -242,7 +246,11 @@ def main():
     config.loggers.cli.info(messages.BIDS_META)
     write_derivative_description(config.execution.bids_dir, config.execution.output_dir)
     write_bidsignore(config.execution.output_dir)
-    config.loggers.cli.info(messages.RUN_FINISHED)
+    config.loggers.cli.log(26, messages.RUN_FINISHED.format(
+        duration=time.strftime(
+            '%Hh %Mmin %Ss',
+            time.gmtime(time.time() - config.settings.start_time))
+    ))
     sys.exit(exitcode)
 
 

mriqc/config.py

@@ -253,6 +253,8 @@ class settings(_Config):
 
     file_path: Path = None
     """Path to this configuration file."""
+    start_time: float = None
+    """A :obj:`~time.time` timestamp at the time the workflow is started."""
 
     _paths = ('file_path', )
 

mriqc/messages.py

@@ -30,7 +30,11 @@
 DROPPING_NON_NUMERICAL = 'Dropping {n_labels} samples for having non-numerical labels'
 GROUP_FINISHED = 'Group level finished successfully.'
 GROUP_NO_DATA = 'No data found. No group level reports were generated.'
-GROUP_START = 'Group level started...'
+GROUP_START = """\
+------------------------------------------------------------------
+Generating group reports
+------------------------------------------------------------------
+"""
 INDIVIDUAL_REPORT_GENERATED = 'Generated individual log: {out_file}'
 PARTICIPANT_START = """\
 ------------------------------------------------------------------
@@ -42,15 +46,16 @@
 {extra_messages}------------------------------------------------------------------
 """
 PARTICIPANT_FINISHED = """\
-----------------------------------------------------------------
-  Participant level finished successfully ({duration})
-----------------------------------------------------------------
-"""
+Participant level finished successfully averaging {duration} per subject."""
 POST_Z_NANS = 'Columns {nan_columns} contain NaNs after z-scoring.'
 QC_UPLOAD_COMPLETE = 'QC metrics successfully uploaded.'
 QC_UPLOAD_START = 'MRIQC Web API: submitting to <{url}>'
 GROUP_REPORT_GENERATED = 'Group-{modality} report generated: {path}'
-RUN_FINISHED = 'MRIQC completed.'
+RUN_FINISHED = """\
+----------------------------------------------------------------
+  MRIQC completed (elapsed time {duration}).
+----------------------------------------------------------------
+"""
 SUSPICIOUS_DATA_TYPE = "Input image {in_file} has a suspicious data type: '{dtype}'"
 TSV_GENERATED = 'Generated summary TSV table for {modality} data: {path}'
 VOXEL_SIZE_OK = 'Voxel size is large enough.'