Add a perflog entry also when sanity fails

Author: vkarak

reframe/core/logging.py

@@ -128,14 +128,6 @@ def ignore_brokenpipe(hdlr, l):
 logging.Handler.handleError = handleError(logging.Handler.handleError)
 
 
-def _expand_params(check):
-    cls = type(check)
-    return {
-        name: getattr(check, name) for name, param in cls.param_space.items
-        if param.is_loggable()
-    }
-
-
 def _guess_delim(s):
     '''Guess the delimiter in the given logging format string'''
     delims = set()

reframe/core/pipeline.py

@@ -2235,14 +2235,11 @@ def check_performance(self):
                 self.perf_variables[var] = sn.make_performance_function(expr,
                                                                         unit)
 
-        if self.is_dry_run():
-            return
-
         # Evaluate the performance function and retrieve the metrics
         with osext.change_dir(self._stagedir):
             for tag, expr in self.perf_variables.items():
                 try:
-                    value = expr.evaluate()
+                    value = expr.evaluate() if not self.is_dry_run() else None
                     unit = expr.unit
                 except Exception as e:
                     logging.getlogger().warning(
@@ -2282,27 +2279,30 @@ def check_performance(self):
 
                 self._perfvalues[key] = (value, *ref, unit)
 
-            # Check the performance variables against their references.
-            for key, values in self._perfvalues.items():
-                val, ref, low_thres, high_thres, *_ = values
+        if self.is_dry_run():
+            return
 
-                # Verify that val is a number
-                if not isinstance(val, numbers.Number):
-                    raise SanityError(
-                        f'the value extracted for performance variable '
-                        f'{key!r} is not a number: {val}'
-                    )
+        # Check the performance variables against their references.
+        for key, values in self._perfvalues.items():
+            val, ref, low_thres, high_thres, *_ = values
 
-                tag = key.split(':')[-1]
-                try:
-                    sn.evaluate(
-                        sn.assert_reference(
-                            val, ref, low_thres, high_thres,
-                            msg=('failed to meet reference: %s={0}, '
-                                 'expected {1} (l={2}, u={3})' % tag))
-                    )
-                except SanityError as e:
-                    raise PerformanceError(e) from None
+            # Verify that val is a number
+            if not isinstance(val, numbers.Number):
+                raise SanityError(
+                    f'the value extracted for performance variable '
+                    f'{key!r} is not a number: {val}'
+                )
+
+            tag = key.split(':')[-1]
+            try:
+                sn.evaluate(
+                    sn.assert_reference(
+                        val, ref, low_thres, high_thres,
+                        msg=('failed to meet reference: %s={0}, '
+                                'expected {1} (l={2}, u={3})' % tag))
+                )
+            except SanityError as e:
+                raise PerformanceError(e) from None
 
     def _copy_job_files(self, job, dst):
         if job is None:

reframe/frontend/cli.py

@@ -1432,7 +1432,7 @@ def module_unuse(*paths):
                         printer, options.duration or options.reruns
                     )
 
-            if options.performance_report:
+            if options.performance_report and not options.dry_run:
                 printer.info(runner.stats.performance_report())
 
             # Generate the report for this session

reframe/frontend/executors/__init__.py

@@ -4,6 +4,7 @@
 # SPDX-License-Identifier: BSD-3-Clause
 
 import abc
+import contextlib
 import copy
 import os
 import signal
@@ -140,6 +141,17 @@ def clone_testcases(cases):
     return dependencies.toposort(dependencies.build_deps(new_cases)[0])
 
 
+class _temp_dry_run:
+    def __init__(self, check):
+        self._check = check
+        self._dry_run_save = check._rfm_dry_run
+
+    def __enter__(self):
+        self._check._rfm_dry_run = True
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        self._check._rfm_dry_run = self._dry_run_save
+
 class RegressionTask:
     '''A class representing a :class:`RegressionTest` through the regression
     pipeline.'''
@@ -328,6 +340,27 @@ def __exit__(this, exc_type, exc_value, traceback):
             self.fail()
             raise TaskExit from e
 
+    def _dry_run_call(self, fn, *args, **kwargs):
+        '''Call check's fn method in dry-run mode.'''
+
+        @contextlib.contextmanager
+        def temp_dry_run(check):
+            dry_run_save = check._rfm_dry_run
+            try:
+                check._rfm_dry_run = True
+                yield check
+            except ABORT_REASONS:
+                raise
+            except BaseException:
+                pass
+            finally:
+                check._rfm_dry_run = dry_run_save
+
+        with runtime.temp_config(self.testcase.partition.fullname):
+            with temp_dry_run(self.check):
+                return fn(*args, **kwargs)
+
+
     @logging.time_function
     def setup(self, *args, **kwargs):
         self.testcase.prepare()
@@ -372,12 +405,15 @@ def run_wait(self):
 
     @logging.time_function
     def sanity(self):
+        self._perflogger = logging.getperflogger(self.check)
         self._safe_call(self.check.sanity)
 
     @logging.time_function
-    def performance(self):
-        self._perflogger = logging.getperflogger(self.check)
-        self._safe_call(self.check.performance)
+    def performance(self, dry_run=False):
+        if dry_run:
+            self._dry_run_call(self.check.performance)
+        else:
+            self._safe_call(self.check.performance)
 
     @logging.time_function
     def finalize(self):

reframe/frontend/executors/policies.py

@@ -199,6 +199,10 @@ def on_task_failure(self, task):
             self.printer.status('FAIL', msg, just='right')
 
         _print_perf(task)
+        if task.failed_stage == 'sanity':
+            # Dry-run the performance stage to trigger performance logging
+            task.performance(dry_run=True)
+
         timings = task.pipeline_timings(['setup',
                                          'compile_complete',
                                          'run_complete',
@@ -617,6 +621,10 @@ def on_task_failure(self, task):
             self.printer.status('FAIL', msg, just='right')
 
         _print_perf(task)
+        if task.failed_stage == 'sanity':
+            # Dry-run the performance stage to trigger performance logging
+            task.performance(dry_run=True)
+
         timings = task.pipeline_timings(['setup',
                                          'compile_complete',
                                          'run_complete',

unittests/test_cli.py

@@ -423,7 +423,7 @@ def test_perflogdir_from_env(run_reframe, tmp_path, monkeypatch):
 def test_performance_report(run_reframe, run_action):
     returncode, stdout, _ = run_reframe(
         checkpath=['unittests/resources/checks/frontend_checks.py'],
-        more_options=['-n', 'PerformanceFailureCheck', '--performance-report'],
+        more_options=['-n', '^PerformanceFailureCheck', '--performance-report'],
         action=run_action
     )
     if run_action == 'run':

unittests/test_policies.py

@@ -1400,3 +1400,26 @@ def test_perf_logging_param_test(make_runner, make_exec_ctx, perf_param_tests,
                'default' / '_MyPerfParamTest.log')
     assert os.path.exists(logfile)
     assert _count_lines(logfile) == 3
+
+
+def test_perf_logging_sanity_failure(make_runner, make_exec_ctx,
+                                     config_perflog, tmp_path):
+    class _X(_MyPerfTest):
+        @sanity_function
+        def validate(self):
+            return False
+
+    make_exec_ctx(config_perflog(fmt='%(check_result)s|%(check_perfvalues)s',
+                                 perffmt='%(check_perf_value)s|'))
+    logging.configure_logging(rt.runtime().site_config)
+    runner = make_runner()
+    testcases = executors.generate_testcases([_X()])
+    _assert_no_logging_error(runner.runall, testcases)
+
+    logfile = (tmp_path / 'perflogs' / 'generic' / 'default' / '_X.log')
+    assert os.path.exists(logfile)
+    with open(logfile) as fp:
+        lines = fp.readlines()
+
+    assert len(lines) == 2
+    assert lines[1] == 'fail|None|None\n'