[feat] Add support for logging all performance variables to a single line

docs/config_reference.rst

@@ -699,7 +699,13 @@ All logging handlers share the following set of common attributes:
    - ``%(check_perf_upper_thres)s``: The upper threshold of the performance difference from the reference value expressed as a fractional value.
      See the :attr:`reframe.core.pipeline.RegressionTest.reference` attribute of regression tests for more details.
    - ``%(check_perf_value)s``: The performance value obtained for a certain performance variable.
-   - ``%(check_perf_var)s``: The name of the `performance variable <tutorial_basic.html#writing-a-performance-test>`__ being logged.
+   - ``%(check_perf_var)s``: The name of the `performance variable <tutorial_basics.html#writing-a-performance-test>`__ being logged.
+   - ``%(check_perf_all_lower_thress)s``: Comma-separated list of lower thresholds of the performance differences from the reference values expressed as fractional values.
+   - ``%(check_perf_all_refs)s``: Comma-separated list of reference performance values of all performance variables.
+   - ``%(check_perf_all_units)s``: Comma-separated list of units of measurement for the measured performance variables.
+   - ``%(check_perf_all_upper_thress)s``: Comma-separated list of upper thresholds of the performance differences from the reference values expressed as a fractional values.
+   - ``%(check_perf_all_values)s``: Comma-separated list of performance values obtained for all performance variables.
+   - ``%(check_perf_all_vars)s``: Comma-separated list of names of the `performance variables <tutorial_basics.html#writing-a-performance-test>`__ being logged.
    - ``%(osuser)s``: The name of the OS user running ReFrame.
    - ``%(osgroup)s``: The name of the OS group running ReFrame.
    - ``%(version)s``: The ReFrame version.

docs/configure.rst

@@ -192,6 +192,29 @@ Finally, there is a special set of handlers for handling performance log message
 These are stored in the ``handlers_perflog`` property.
 The performance handler in this example will create a file per test and per system/partition combination and will append the performance data to it every time the test is run.
 Notice in the ``format`` property how the message to be logged is structured such that it can be easily parsed from post processing tools.
+In the previous example, each performance metric defined in :attr:`reframe.core.pipeline.RegressionTest.perf_patterns` is logged on a separate line. To change this behavior, log record attributes such as ``%(check_perf_value)s`` should be changed to ``%(check_perf_all_values)s``. The following example will log comma-separated lists of all performance metrics on a single line.
+
+.. code:: python
+
+    'handlers_perflog': [
+        {
+            'type': 'filelog',
+            'prefix': '%(check_system)s/%(check_partition)s',
+            'level': 'info',
+            'format': (
+                '%(check_job_completion_time)s|reframe %(version)s|'
+                '%(check_info)s|jobid=%(check_jobid)s|'
+                'perf_vars=%(check_perf_all_vars)s|'
+                'perf_values=%(check_perf_all_values)s|'
+                'perf_refs=%(check_perf_all_refs)s|'
+                'perf_lower_thress=%(check_perf_all_lower_thress)s|'
+                'perf_upper_thress=%(check_perf_all_upper_thress)s|'
+                'perf_units=%(check_perf_all_units)s)'
+            ),
+            'append': True
+        }
+    ]
+
 Apart from file logging, ReFrame offers more advanced performance logging capabilities through Syslog and Graylog.
 
 

reframe/core/pipeline.py

@@ -1484,6 +1484,11 @@ def check_performance(self):
                     ref_tuple = (0, None, None, unit)
                     self.reference.update({'*': {name: ref_tuple}})
 
+            perf_logger = self._perf_logger
+            perf_attrs = ['var', 'value', 'ref', 'lower_thres', 'upper_thres',
+                          'unit']
+            for attr in perf_attrs:
+                perf_logger.extra['check_perf_all_%ss' % attr] = []
             # We first evaluate and log all performance values and then we
             # check them against the reference. This way we always log them
             # even if the don't meet the reference.
@@ -1496,9 +1501,36 @@ def check_performance(self):
                         (tag, self._current_partition.fullname))
 
                 self._perfvalues[key] = (value, *self.reference[key])
-                self._perf_logger.log_performance(logging.INFO, tag, value,
-                                                  *self.reference[key])
+                for attr, val in zip(perf_attrs,
+                                     (tag, value, *self.reference[key])):
+                    perf_logger.extra['check_perf_all_%ss' % attr].append(
+                        '%s' % val)
+
+            for attr in perf_attrs:
+                perf_logger.extra['check_perf_all_%ss' % attr] = ','.join(
+                    perf_logger.extra['check_perf_all_%ss' % attr])
+
+            # If any handler has a formatter that contains a reference to
+            # single performance patterns, we assume we want a separate line
+            # for each performance pattern and call the logger for each.
+            log_separate_lines = False
+            if perf_logger.logger is not None:
+                for handler in perf_logger.logger.handlers:
+                    for attr in perf_attrs:
+                        if 'check_perf_%s' % attr in handler.formatter._fmt:
+                            log_separate_lines = True
+            if log_separate_lines:
+                for tag, expr in self.perf_patterns.items():
+                    value = sn.evaluate(expr)
+                    key = '%s:%s' % (self._current_partition.fullname, tag)
+                    self._perf_logger.log_performance(logging.INFO, tag, value,
+                                                      *self.reference[key])
+            else:
+                msg = 'sent by ' + perf_logger.extra['osuser']
+                perf_logger.log(logging.INFO, msg)
 
+            # All logging is done, now check performance values against
+            # reference values.
             for key, values in self._perfvalues.items():
                 val, ref, low_thres, high_thres, *_ = values