Changed log variable to check_job_completion_time

Also:

- Fine tune documentation

Author: Vasileios Karakasis

docs/running.rst

@@ -840,17 +840,20 @@ All handlers accept the following set of attributes (keys) in their configuratio
 * ``format`` (default: ``'%(message)s'``): Format string for the printout of the log record.
   ReFrame supports all the `format strings <https://docs.python.org/3.6/library/logging.html#logrecord-attributes>`__ from Python's logging library and provides the following additional ones:
 
-  - ``check_completion_time``: A timestamp with the completion time of the regression test.
-    The ``slurm`` scheduler relies on job accounting (``sacct`` command) and returns the actual termination time of the job.
-    The rest of the schedulers report as completion time the moment the framework realizes the test has finished, as soon as the ``wait`` phase ends.
-    The accuracy is dependent on the polling rate of the ``wait`` phase and can be lower for tests that take more time.
-    If a job or process is not yet completed, ``None`` will be printed.
   - ``check_environ``: The programming environment a test is currently executing for.
   - ``check_info``: Print live information of the currently executing check.
     By default this field has the form ``<check_name> on <current_partition> using <current_environment>``.
     It can be configured on a per test basis by overriding the :func:`info <reframe.core.pipeline.RegressionTest.info>` method of a specific regression test.
   - ``check_jobid``: Prints the job or process id of the job or process associated with the currently executing regression test.
     If a job or process is not yet created, ``-1`` will be printed.
+  - ``check_job_completion_time``: *[new in 2.21]* The completion time of the job spawned by this regression test.
+    This timestamp will be formatted according to ``datefmt`` (see below).
+    The accuracy of the timestamp depends on the backend scheduler.
+    The ``slurm`` scheduler backend relies on job accounting and returns the actual termination time of the job.
+    The rest of the backends report as completion time the moment when the framework realizes that the spawned job has finished.
+    In this case, the accuracy depends on the execution policy used.
+    If tests are executed with the serial execution policy, this is close to the real completion time, but if the asynchronous execution policy is used, it can differ significantly.
+    If the job completion time cannot be retrieved, ``None`` will be printed.
   - ``check_name``: Prints the name of the regression test on behalf of which ReFrame is currently executing.
     If ReFrame is not in the context of regression test, ``reframe`` will be printed.
   - ``check_num_tasks``: The number of tasks assigned to the regression test.

reframe/core/logging.py

@@ -367,14 +367,14 @@ def __init__(self, logger=None, check=None):
             {
                 'check_name': 'reframe',
                 'check_jobid': '-1',
+                'check_job_completion_time': None,
                 'check_info': 'reframe',
                 'check_system': None,
                 'check_partition': None,
                 'check_environ': None,
                 'check_outputdir': None,
                 'check_stagedir': None,
                 'check_num_tasks': None,
-                'check_completion_time': None,
                 'check_perf_var': None,
                 'check_perf_value': None,
                 'check_perf_ref': None,
@@ -433,7 +433,7 @@ def _update_check_extras(self):
                 # NOTE: All handlers use the same date format
                 fmt = self.logger.handlers[0].formatter.datefmt
                 ct = self.check.job.completion_time.strftime(fmt)
-                self.extra['check_completion_time'] = ct
+                self.extra['check_job_completion_time'] = ct
 
     def log_performance(self, level, tag, value, ref,
                         low_thres, upper_thres, unit=None, *, msg=None):