Repository: reframe-hpc/reframe

Issue:
Allow multiple perf_patterns on one line in handlers_perflog
When specifying multiple entries in perf_patterns (for instance as in cscs-checks/microbenchmarks/mpi/halo_exchange/halo_cell_exchange.py), every performance variable is put on a separate line by the logging handler. All attributes that are not related to the performance variable are repeated on all those lines.

For the HaloCellExchangeTest you could argue that every performance represents a separate aspect of the test, so it makes sense to put them on separate lines. However, when you are for instance looking at walltime, CPU time, communication time, memory, ... in one test, it would make more sense to keep those performance variables tied together. At the moment, it is necessary to join lines on some common attribute (such as jobid) to find out which results belong together.

I think it would be a useful feature to allow the `%(check_perf_*)s` attributes to report multiple values, similar to the `%(check_tags)s` attribute. Before attempting to implement this, I would like the opinion of a developer on this. Or maybe there is a hack to work around this issue? 

Discussion:

Patch:
diff --git a/docs/config_reference.rst b/docs/config_reference.rst
index c3c9054b..54ea1bcd 100644
--- a/docs/config_reference.rst
+++ b/docs/config_reference.rst
@@ -782,6 +782,8 @@ They are associated with `system partitions <#system-partition-configuration>`__
    It first looks for definitions for the current partition, then for the containing system and, finally, for global definitions (the ``*`` pseudo-system).
 
 
+.. _logging-config-reference:
+
 Logging Configuration
 ---------------------
 
@@ -830,6 +832,14 @@ You may define different logger objects per system but *not* per partition.
    A list of logging handlers responsible for handling performance data from tests.
 
 
+.. js:attribute:: .logging[].perflog_compat
+
+   :required: No
+   :default: ``false``
+
+   Emit a separate log record for each performance variable.
+   Set this option to ``true`` if you want to keep compatibility with the performance logging prior to ReFrame 4.0.
+
 .. js:attribute:: .logging[].target_systems
 
    :required: No
@@ -889,6 +899,7 @@ All logging handlers share the following set of common attributes:
    :default: ``"%(message)s"``
 
    Log record format string.
+
    ReFrame accepts all log record attributes from Python's `logging <https://docs.python.org/3.8/library/logging.html#logrecord-attributes>`__ mechanism and adds the following:
 
    .. csv-table::
@@ -925,13 +936,7 @@ All logging handlers share the following set of common attributes:
       ``%(check_num_tasks_per_socket)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_tasks_per_socket` attribute.
       ``%(check_outputdir)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.outputdir` attribute.
       ``%(check_partition)s``, The name of the test's :attr:`~reframe.core.pipeline.RegressionTest.current_partition`.
-      ``%(check_perf_lower_thres)s``, The lower threshold of the logged performance variable.
-      ``%(check_perf_ref)s``, The reference value of the logged performance variable.
-      ``%(check_perf_unit)s``, The measurement unit of the logged performance variable.
-      ``%(check_perf_upper)s``, The upper thresholds of the logged performance variable.
-      ``%(check_perf_value)s``, The actual value of the logged performance variable.
-      ``%(check_perf_var)s``, The name of the logged performance variable.
-      ``%(check_perfvalues)s``, All the performance variables of the test combined along with their values, references and thresholds.
+      ``%(check_perfvalues)s``, All the performance variables of the test combined. These will be formatted according to ``format_perfvars``.
       ``%(check_postbuild_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.postbuild_cmds` attribute.
       ``%(check_postrun_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.postrun_cmds` attribute.
       ``%(check_prebuild_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.prebuild_cmds` attribute.
@@ -968,6 +973,37 @@ All logging handlers share the following set of common attributes:
    Limit the number of attributes that can be logged. User attributes or properties must be explicitly marked as "loggable" in order to be selectable for logging.
 
 
+.. js:attribute:: .logging[].handlers[].format_perfvars
+.. js:attribute:: .logging[].handlers_perflog[].format_perfvars
+
+   Format specifier for logging the performance variables.
+
+   This defines how the ``%(check_perfvalues)s`` will be formatted.
+   Since a test may define multiple performance variables, the formatting specified in this field will be repeated for each performance variable sequentially in the *same* line.
+
+   .. important::
+      The last character of this format will be interpreted as the final delimiter of the formatted performance variables to the rest of the record.
+
+   The following log record attributes are defined additionally by this format specifier:
+
+   .. csv-table::
+      :header: "Log record attribute", "Description"
+
+      ``%(check_perf_lower_thres)s``, The lower threshold of the logged performance variable.
+      ``%(check_perf_ref)s``, The reference value of the logged performance variable.
+      ``%(check_perf_unit)s``, The measurement unit of the logged performance variable.
+      ``%(check_perf_upper)s``, The upper thresholds of the logged performance variable.
+      ``%(check_perf_value)s``, The actual value of the logged performance variable.
+      ``%(check_perf_var)s``, The name of the logged performance variable.
+
+
+   .. important::
+      ReFrame versions prior to 4.0 logged a separate line for each performance variable and the ``%(check_perf_*)s`` attributes could be used directly in the ``format``.
+      You can re-enable this behaviour by setting the ``perflog_compat`` logging configuration parameter.
+
+
+   .. versionadded:: 4.0.0
+
 .. js:attribute:: .logging[].handlers[].datefmt
 
 .. object:: .logging[].handlers_perflog[].datefmt
diff --git a/docs/configure.rst b/docs/configure.rst
index 49239ebd..674468ac 100644
--- a/docs/configure.rst
+++ b/docs/configure.rst
@@ -197,9 +197,8 @@ Finally, there is a special set of handlers for handling performance log message
 Performance log messages are generated *only* for `performance tests <tutorial_basics.html#writing-a-performance-test>`__, i.e., tests defining the :attr:`~reframe.core.pipeline.RegressionTest.perf_variables` or the :attr:`~reframe.core.pipeline.RegressionTest.perf_patterns` attributes.
 The performance log handlers are stored in the ``handlers_perflog`` property.
 The ``filelog`` handler used in this example will create a file per test and per system/partition combination (``./<system>/<partition>/<testname>.log``) and will append to it the obtained performance data every time a performance test is run.
-Notice how the message to be logged is structured in the ``format`` property, such that it can be easily parsed from post processing tools.
-Apart from file logging, ReFrame offers more advanced performance logging capabilities through Syslog and Graylog.
-
+Notice how the message to be logged is structured in the ``format`` and ``format_perfvars`` properties, such that it can be easily parsed from post processing tools.
+Apart from file logging, ReFrame offers more advanced performance logging capabilities through Syslog, Graylog and HTTP.
 
 For a complete reference of logging configuration parameters, please refer to the :doc:`config_reference`.
 
diff --git a/docs/listings/perflogs.txt b/docs/listings/perflogs.txt
index 69064259..5751f3a7 100644
--- a/docs/listings/perflogs.txt
+++ b/docs/listings/perflogs.txt
@@ -1,8 +1,4 @@
-2022-01-19T17:17:15|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34545|Copy=24672.4|ref=25200 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:17:15|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34545|Scale=16834.0|ref=16800 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:17:15|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34545|Add=18376.3|ref=18500 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:17:15|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34545|Triad=19071.7|ref=18800 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:18:52|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34622|Copy=24584.3|ref=55200 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:18:52|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34622|Scale=16767.3|ref=16800 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:18:52|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34622|Add=18409.5|ref=18500 (l=-0.05, u=0.05)|MB/s
-2022-01-19T17:18:52|reframe 3.10.0-dev.2+bf404ae1|StreamWithRefTest @catalina:default+gnu|jobid=34622|Triad=18959.5|ref=18800 (l=-0.05, u=0.05)|MB/s
+job_completion_time,version,display_name,system,partition,environ,jobid,result,Copy_value,Copy_unit,Copy_ref,Copy_lower,Copy_upper,Scale_value,Scale_unit,Scale_ref,Scale_lower,Scale_upper,Add_value,Add_unit,Add_ref,Add_lower,Add_upper,Triad_value,Triad_unit,Triad_ref,Triad_lower,Triad_upper
+2022-10-18T21:41:25,4.0.0-dev.2+90fbd3ef,StreamWithRefTest,catalina,default,gnu,81351,pass,24235.6,MB/s,25200,-0.05,0.05,16044.2,MB/s,16800,-0.05,0.05,17733.7,MB/s,18500,-0.05,0.05,18232.0,MB/s,18800,-0.05,0.05
+2022-10-18T21:41:31,4.0.0-dev.2+90fbd3ef,StreamWithRefTest,catalina,default,gnu,81377,fail,23615.4,MB/s,25200,-0.05,0.05,16394.5,MB/s,16800,-0.05,0.05,17841.3,MB/s,18500,-0.05,0.05,18284.1,MB/s,18800,-0.05,0.05
+2022-10-18T21:46:06,4.0.0-dev.2+90fbd3ef,StreamWithRefTest,catalina,default,gnu,81480,fail,23736.4,MB/s,25200,-0.05,0.05,16242.8,MB/s,16800,-0.05,0.05,17699.1,MB/s,18500,-0.05,0.05,18077.3,MB/s,18800,-0.05,0.05
diff --git a/docs/tutorial_basics.rst b/docs/tutorial_basics.rst
index 6f595473..d6b3fd6c 100644
--- a/docs/tutorial_basics.rst
+++ b/docs/tutorial_basics.rst
@@ -565,10 +565,16 @@ Let's inspect the log file from our last test:
 .. literalinclude:: listings/perflogs.txt
    :language: console
 
-Several information are printed for each run, such as the performance variables, their value, their references and thresholds etc.
-The default format is in a form suitable for easy parsing, but you may fully control not only the format, but also what is being logged from the configuration file.
-:doc:`configure` and :doc:`config_reference` cover logging in ReFrame in much more detail.
+The format of this file is controlled by :js:attr:`handlers_perflog` logging configuration parameter and, by default, contains several information about the test.
+For each test, all of its performance variables are logged along with their unit, the obtained value, the reference and the lower and upper threshold.
+The default format is in CSV, so that it can be easily post-processed.
+For this reason, a header is also printed to help identify the different fields.
 
+Since version 4.0, ReFrame is very cautious when generating this file: if a change is detected in the information that is being logged, ReFrame will not append to the file, but it will instead create a new one, saving the old file using the ``.h<N>`` suffix, where ``N`` is an integer that is increased every time a new file is being created due to such changes.
+Examples of changes in the logged information are when the log record format changes or a new performance metric is added, deleted or has its name changed.
+This behavior guarantees that each log file is consistent and it will not break existing parsers.
+
+For more information on configuring performance logging in ReFrame as well as logging in general, you may refer to the :ref:`logging-config-reference` reference.
 
 
 Porting The Tests to an HPC cluster
diff --git a/reframe/core/logging.py b/reframe/core/logging.py
index 6e3e7c53..cfcb70f0 100644
--- a/reframe/core/logging.py
+++ b/reframe/core/logging.py
@@ -11,8 +11,8 @@ import os
 import re
 import requests
 import shutil
-import sys
 import socket
+import sys
 import time
 import urllib
 
@@ -128,7 +128,7 @@ class MultiFileHandler(logging.FileHandler):
     information from the log record.
     '''
 
-    def __init__(self, prefix, mode='a', encoding=None):
+    def __init__(self, prefix, mode='a', encoding=None, fmt=None, perffmt=None):
         super().__init__(prefix, mode, encoding, delay=True)
 
         # Reset FileHandler's filename
@@ -136,7 +136,76 @@ class MultiFileHandler(logging.FileHandler):
         self._prefix = prefix
 
         # Associates filenames with open streams
-        self._streams = {}
+        self.__streams = {}
+
+        # Format specifiers
+        self.__fmt = fmt
+        self.__perffmt = perffmt
+        self.__attr_patt = re.compile(r'\%\((.*?)\)s(.)?')
+
+    def __generate_header(self, record):
+        # Generate the header from the record and fmt
+        header = ''
+        for m in self.__attr_patt.finditer(self.__fmt):
+            attr = m.group(1)
+            delim = m.group(2)
+            if attr == 'check_perfvalues':
+                # Expand based on the perffmt
+                delim_p = ''
+                for var in record.check_perfvalues:
+                    name = var.split(':')[-1]
+                    for m0 in self.__attr_patt.finditer(self.__perffmt):
+                        attr_p  = m0.group(1)
+                        delim_p = m0.group(2)
+                        header += attr_p.replace('check_perf', name)
+                        if delim_p:
+                            header += delim_p
+
+                if delim_p:
+                    header = header.rstrip(delim_p)
+            elif attr.startswith('check_'):
+                header += attr[6:]
+            else:
+                header += attr
+
+            if delim:
+                header += delim
+
+        return header
+
+    def _emit_header(self, record):
+        if self.baseFilename in self.__streams:
+            return
+
+        record_header = self.__generate_header(record)
+
+        # We are opening a file for the first time;
+        # check if the header has changed
+        try:
+            header = None
+            with open(self.baseFilename) as fp:
+                header = fp.readline().strip()
+        except FileNotFoundError:
+            return
+        else:
+            if header == record_header:
+                return
+
+            # Header changed; move the old file
+            hcnt = 0
+            while os.path.exists(self.baseFilename + f'.h{hcnt}'):
+                hcnt += 1
+                continue
+
+            os.rename(self.baseFilename, self.baseFilename + f'.h{hcnt}')
+        finally:
+            # Open the file for writing and write the header
+            fp = open(self.baseFilename,
+                      mode=self.mode, encoding=self.encoding)
+            if record_header != header:
+                fp.write(f'{record_header}\n')
+
+            self.__streams[self.baseFilename] = fp
 
     def emit(self, record):
         try:
@@ -151,13 +220,13 @@ class MultiFileHandler(logging.FileHandler):
         self.baseFilename = os.path.join(
             dirname, f'{record.__rfm_check__.short_name}.log'
         )
-        self.stream = self._streams.get(self.baseFilename, None)
+        self._emit_header(record)
+        self.stream = self.__streams[self.baseFilename]
         super().emit(record)
-        self._streams[self.baseFilename] = self.stream
 
     def close(self):
         # Close all open streams
-        for s in self._streams.values():
+        for s in self.__streams.values():
             self.stream = s
             super().close()
 
@@ -189,11 +258,33 @@ class CheckFieldFormatter(logging.Formatter):
     regression test.'''
 
     # NOTE: This formatter will work only for the '%' style
-    def __init__(self, fmt=None, datefmt=None, style='%'):
+    def __init__(self, fmt=None, datefmt=None, perffmt=None, style='%'):
         super().__init__(fmt, datefmt, style)
 
         self.__fmt = fmt
+        self.__fmtperf = perffmt[:-1] if perffmt else ''
         self.__specs = re.findall(r'\%\((\S+?)\)s', fmt)
+        self.__delim = perffmt[-1] if perffmt else ''
+
+    def _format_perf(self, perfvars):
+        chunks = []
+        for var, info in perfvars.items():
+            val, ref, lower, upper, unit = info
+            record = {
+                'check_perf_var': var.split(':')[-1],
+                'check_perf_value': val,
+                'check_perf_unit': unit,
+                'check_perf_ref': ref,
+                'check_perf_lower': lower,
+                'check_perf_upper': upper
+            }
+            try:
+                chunks.append(self.__fmtperf % record)
+            except ValueError:
+                chunks.append("<error formatting the performance record: "
+                              "please check the 'format_perfvars' string>")
+
+        return self.__delim.join(chunks)
 
     def formatMessage(self, record):
         for s in self.__specs:
@@ -202,7 +293,9 @@ class CheckFieldFormatter(logging.Formatter):
 
         record_proxy = dict(record.__dict__)
         for k, v in record_proxy.items():
-            if k.startswith('check_'):
+            if k == 'check_perfvalues':
+                record_proxy[k] = self._format_perf(v)
+            elif k.startswith('check_'):
                 record_proxy[k] = _xfmt(v)
 
         # Now format `check_job_completion_time` according to `datefmt`
@@ -213,7 +306,11 @@ class CheckFieldFormatter(logging.Formatter):
                 time.localtime(ct), datefmt
             )
 
-        return self.__fmt % record_proxy
+        try:
+            return self.__fmt % record_proxy
+        except ValueError:
+            return ("<error formatting the log message: "
+                    "please check the 'format' string>")
 
 
 class RFC3339Formatter(CheckFieldFormatter):
@@ -272,13 +369,17 @@ def _create_file_handler(site_config, config_prefix):
 
 
 def _create_filelog_handler(site_config, config_prefix):
-    basedir = os.path.abspath(
+    basedir = os.path.abspath(os.path.join(
+        site_config.get(f'systems/0/prefix'),
         osext.expandvars(site_config.get(f'{config_prefix}/basedir'))
-    )
+    ))
     prefix  = osext.expandvars(site_config.get(f'{config_prefix}/prefix'))
     filename_patt = os.path.join(basedir, prefix)
     append = site_config.get(f'{config_prefix}/append')
-    return MultiFileHandler(filename_patt, mode='a+' if append else 'w+')
+    format = site_config.get(f'{config_prefix}/format')
+    format_perf = site_config.get(f'{config_prefix}/format_perfvars')
+    return MultiFileHandler(filename_patt, mode='a+' if append else 'w+',
+                            fmt=format, perffmt=format_perf)
 
 
 def _create_syslog_handler(site_config, config_prefix):
@@ -482,7 +583,9 @@ def _extract_handlers(site_config, handlers_group):
         level = site_config.get(f'{handler_prefix}/{i}/level')
         fmt = site_config.get(f'{handler_prefix}/{i}/format')
         datefmt = site_config.get(f'{handler_prefix}/{i}/datefmt')
-        hdlr.setFormatter(RFC3339Formatter(fmt=fmt, datefmt=datefmt))
+        perffmt = site_config.get(f'{handler_prefix}/{i}/format_perfvars')
+        hdlr.setFormatter(RFC3339Formatter(fmt=fmt,
+                                           datefmt=datefmt, perffmt=perffmt))
         hdlr.setLevel(_check_level(level))
         handlers.append(hdlr)
 
@@ -569,6 +672,7 @@ class LoggerAdapter(logging.LoggerAdapter):
                 'check_perf_lower_thres': None,
                 'check_perf_upper_thres': None,
                 'check_perf_unit': None,
+                'check_result': None,
                 'osuser':  osext.osuser(),
                 'osgroup': osext.osgroup(),
                 'version': osext.reframe_version(),
@@ -617,20 +721,27 @@ class LoggerAdapter(logging.LoggerAdapter):
             '%FT%T%:z'
         )
 
-    def log_performance(self, level, tag, value, ref,
-                        low_thres, upper_thres, unit=None, *, msg=None):
-
-        # Update the performance-relevant extras and log the message
-        self.extra['check_perf_var'] = tag
-        self.extra['check_perf_value'] = value
-        self.extra['check_perf_ref'] = ref
-        self.extra['check_perf_lower_thres'] = low_thres
-        self.extra['check_perf_upper_thres'] = upper_thres
-        self.extra['check_perf_unit'] = unit
+    def log_performance(self, level, task, msg=None, multiline=False):
+        self.extra['check_partition'] = task.testcase.partition.name
+        self.extra['check_environ'] = task.testcase.environ.name
+        self.extra['check_result'] = 'pass' if task.succeeded else 'fail'
         if msg is None:
             msg = 'sent by ' + self.extra['osuser']
 
-        self.log(level, msg)
+        if multiline:
+            # Log one record for each performance variable
+            check = self.extra['__rfm_check__']
+            for var, info in check.perfvalues.items():
+                val, ref, lower, upper, unit = info
+                self.extra['check_perf_var'] = var.split(':')[-1]
+                self.extra['check_perf_value'] = val
+                self.extra['check_perf_ref'] = ref
+                self.extra['check_perf_lower_thres'] = lower
+                self.extra['check_perf_upper_thres'] = upper
+                self.extra['check_perf_unit'] = unit
+                self.log(level, msg)
+        else:
+            self.log(level, msg)
 
     def process(self, msg, kwargs):
         # Setup dynamic fields of the check
diff --git a/reframe/core/pipeline.py b/reframe/core/pipeline.py
index e69f64c1..eb783a21 100644
--- a/reframe/core/pipeline.py
+++ b/reframe/core/pipeline.py
@@ -1024,9 +1024,6 @@ class RegressionTest(RegressionMixin, jsonext.JSONSerializable):
         self._build_job = None
         self._compile_proc = None
 
-        # Performance logging
-        self._perf_logger = logging.null_logger
-
         # List of dependencies specified by the user
         self._userdeps = []
 
@@ -1616,9 +1613,6 @@ class RegressionTest(RegressionMixin, jsonext.JSONSerializable):
     def _setup_run_job(self, **job_opts):
         self._job = self._create_job(f'rfm_job', self.local, **job_opts)
 
-    def _setup_perf_logging(self):
-        self._perf_logger = logging.getperflogger(self)
-
     def _setup_container_platform(self):
         try:
             self.container_platform.emit_prepare_commands(self.stagedir)
@@ -2079,6 +2073,10 @@ class RegressionTest(RegressionMixin, jsonext.JSONSerializable):
             if not success:
                 raise SanityError()
 
+    def is_performance_check(self):
+        '''Return :obj:`True` if the test is a performance test.'''
+        return self.perf_variables or hasattr(self, 'perf_patterns')
+
     @final
     def check_performance(self):
         '''The performance checking phase of the regression test pipeline.
@@ -2101,107 +2099,74 @@ class RegressionTest(RegressionMixin, jsonext.JSONSerializable):
 
         '''
 
+        if not self.is_performance_check():
+            return
+
+        perf_patterns = getattr(self, 'perf_patterns', None)
+
+        if perf_patterns is not None and self.perf_variables:
+            raise ReframeSyntaxError(
+                f"you cannot mix 'perf_patterns' and 'perf_variables' syntax"
+            )
+
+        # Convert `perf_patterns` to `perf_variables`
+        if perf_patterns:
+            for var, expr in self.perf_patterns.items():
+                # Retrieve the unit from the reference tuple
+                key = f'{self._current_partition.fullname}:{var}'
+                try:
+                    unit = self.reference[key][3]
+                    if unit is None:
+                        unit = ''
+                except KeyError:
+                    unit = ''
+
+                self.perf_variables[var] = sn.make_performance_function(expr,
+                                                                        unit)
+
+        # Evaluate the performance function and retrieve the metrics
         with osext.change_dir(self._stagedir):
-            if self.perf_variables or self._rfm_perf_fns:
-                if hasattr(self, 'perf_patterns'):
-                    raise ReframeSyntaxError(
-                        f"assigning a value to 'perf_patterns' conflicts ",
-                        f"with using the 'performance_function' decorator ",
-                        f"or setting a value to 'perf_variables'"
+            for tag, expr in self.perf_variables.items():
+                try:
+                    value = expr.evaluate()
+                    unit = expr.unit
+                except Exception as e:
+                    logging.getlogger().warning(
+                        f'skipping evaluation of performance variable '
+                        f'{tag!r}: {e}'
                     )
+                    continue
 
-                # Log the performance variables
-                self._setup_perf_logging()
-                for tag, expr in self.perf_variables.items():
-                    try:
-                        value = expr.evaluate()
-                        unit = expr.unit
-                    except Exception as e:
-                        logging.getlogger().warning(
-                            f'skipping evaluation of performance variable '
-                            f'{tag!r}: {e}'
-                        )
-                        continue
-
-                    key = f'{self._current_partition.fullname}:{tag}'
-                    try:
-                        ref = self.reference[key]
-
-                        # If units are also provided in the reference, raise
-                        # a warning if they match with the units provided by
-                        # the performance function.
-                        if len(ref) == 4:
-                            if ref[3] != unit:
-                                logging.getlogger().warning(
-                                    f'reference unit ({key!r}) for the '
-                                    f'performance variable {tag!r} '
-                                    f'does not match the unit specified '
-                                    f'in the performance function ({unit!r}): '
-                                    f'{unit!r} will be used'
-                                )
-
-                            # Pop the unit from the ref tuple (redundant)
-                            ref = ref[:3]
-                    except KeyError:
-                        if self.require_reference:
-                            raise PerformanceError(
-                                f'no reference value found for '
-                                f'performance variable {tag!r} on '
-                                f'system {self._current_partition.fullname!r}'
-                            ) from None
-
-                        ref = (0, None, None)
-
-                    self._perfvalues[key] = (value, *ref, unit)
-                    self._perf_logger.log_performance(logging.INFO, tag, value,
-                                                      *ref, unit)
-            elif not hasattr(self, 'perf_patterns'):
-                return
-            else:
-                self._setup_perf_logging()
-                # Check if default reference perf values are provided and
-                # store all the variables tested in the performance check
-                has_default = False
-                variables = set()
-                for key, ref in self.reference.items():
-                    keyparts = key.split(self.reference.scope_separator)
-                    system = keyparts[0]
-                    varname = keyparts[-1]
-                    unit = ref[3]
-                    variables.add((varname, unit))
-                    if system == '*':
-                        has_default = True
-                        break
-
-                if not has_default:
-                    if not variables:
-                        # If empty, it means that self.reference was empty, so
-                        # try to infer their name from perf_patterns
-                        variables = {(name, None)
-                                     for name in self.perf_patterns.keys()}
-
-                    for var in variables:
-                        name, unit = var
-                        ref_tuple = (0, None, None, unit)
-                        if not self.require_reference:
-                            self.reference.update({'*': {name: ref_tuple}})
-
-                # 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.
-                for tag, expr in self.perf_patterns.items():
-                    value = sn.evaluate(expr)
-                    key = f'{self._current_partition.fullname}:{tag}'
-                    if key not in self.reference:
+                key = f'{self._current_partition.fullname}:{tag}'
+                try:
+                    ref = self.reference[key]
+
+                    # If units are also provided in the reference, raise
+                    # a warning if they match with the units provided by
+                    # the performance function.
+                    if len(ref) == 4:
+                        if ref[3] != unit:
+                            logging.getlogger().warning(
+                                f'reference unit ({key!r}) for the '
+                                f'performance variable {tag!r} '
+                                f'does not match the unit specified '
+                                f'in the performance function ({unit!r}): '
+                                f'{unit!r} will be used'
+                            )
+
+                        # Pop the unit from the ref tuple (redundant)
+                        ref = ref[:3]
+                except KeyError:
+                    if self.require_reference:
                         raise PerformanceError(
                             f'no reference value found for '
                             f'performance variable {tag!r} on '
                             f'system {self._current_partition.fullname!r}'
-                        )
+                        ) from None
+
+                    ref = (0, None, None)
 
-                    self._perfvalues[key] = (value, *self.reference[key])
-                    self._perf_logger.log_performance(logging.INFO, tag, value,
-                                                      *self.reference[key])
+                self._perfvalues[key] = (value, *ref, unit)
 
             # Check the performance variables against their references.
             for key, values in self._perfvalues.items():
diff --git a/reframe/core/runtime.py b/reframe/core/runtime.py
index 63341a51..54115319 100644
--- a/reframe/core/runtime.py
+++ b/reframe/core/runtime.py
@@ -422,6 +422,7 @@ class temp_runtime:
             _runtime_context = None
         else:
             site_config = config.load_config(config_file)
+            site_config.validate()
             site_config.select_subconfig(sysname, ignore_resolve_errors=True)
             for opt, value in options.items():
                 site_config.add_sticky_option(opt, value)
diff --git a/reframe/core/settings.py b/reframe/core/settings.py
index 7d17581b..e8b6ec81 100644
--- a/reframe/core/settings.py
+++ b/reframe/core/settings.py
@@ -55,13 +55,15 @@ site_configuration = {
                     '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|'
-                        '%(check_perf_var)s=%(check_perf_value)s|'
-                        'ref=%(check_perf_ref)s '
-                        '(l=%(check_perf_lower_thres)s, '
-                        'u=%(check_perf_upper_thres)s)|'
-                        '%(check_perf_unit)s'
+                        '%(check_job_completion_time)s,%(version)s,'
+                        '%(check_display_name)s,%(check_system)s,'
+                        '%(check_partition)s,%(check_environ)s,'
+                        '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s'
+                    ),
+                    'format_perfvars': (
+                        '%(check_perf_value)s,%(check_perf_unit)s,'
+                        '%(check_perf_ref)s,%(check_perf_lower)s,'
+                        '%(check_perf_upper)s,'
                     ),
                     'append': True
                 }
diff --git a/reframe/frontend/executors/__init__.py b/reframe/frontend/executors/__init__.py
index b06a1abb..dbeb54cb 100644
--- a/reframe/frontend/executors/__init__.py
+++ b/reframe/frontend/executors/__init__.py
@@ -156,6 +156,12 @@ class RegressionTask:
 
         self._aborted = False
 
+        # Performance logging
+        self._perflogger = logging.null_logger
+        self._perflog_compat = runtime.runtime().get_option(
+            'logging/0/perflog_compat'
+        )
+
     def duration(self, phase):
         # Treat pseudo-phases first
         if phase == 'compile_complete':
@@ -362,6 +368,9 @@ class RegressionTask:
 
     @logging.time_function
     def performance(self):
+        if self.check.is_performance_check():
+            self._perflogger = logging.getperflogger(self.check)
+
         self._safe_call(self.check.performance)
 
     @logging.time_function
@@ -377,6 +386,8 @@ class RegressionTask:
 
         self._current_stage = 'finalize'
         self._notify_listeners('on_task_success')
+        self._perflogger.log_performance(logging.INFO, self,
+                                         multiline=self._perflog_compat)
 
     @logging.time_function
     def cleanup(self, *args, **kwargs):
@@ -386,6 +397,8 @@ class RegressionTask:
         self._failed_stage = self._current_stage
         self._exc_info = exc_info or sys.exc_info()
         self._notify_listeners('on_task_failure')
+        self._perflogger.log_performance(logging.INFO, self,
+                                         multiline=self._perflog_compat)
 
     def skip(self, exc_info=None):
         self._skipped = True
diff --git a/reframe/schemas/config.json b/reframe/schemas/config.json
index 3897fc7b..65806d49 100644
--- a/reframe/schemas/config.json
+++ b/reframe/schemas/config.json
@@ -55,6 +55,7 @@
                 },
                 "level": {"$ref": "#/defs/loglevel"},
                 "format": {"type": "string"},
+                "format_perfvars": {"type": "string"},
                 "datefmt": {"type": "string"}
             },
             "required": ["type"]
@@ -410,6 +411,7 @@
                 "type": "object",
                 "properties": {
                     "level": {"$ref": "#/defs/loglevel"},
+                    "perflog_compat": {"type": "boolean"},
                     "handlers": {
                         "type": "array",
                         "items": {
@@ -558,11 +560,13 @@
         "general/user_modules": [],
         "general/verbose": 0,
         "logging/level": "undefined",
+        "logging/perflog_compat": false,
         "logging/target_systems": ["*"],
         "logging/handlers": [],
         "logging/handlers_perflog": [],
         "logging/handlers*/*_level": "info",
         "logging/handlers*/*_format": "%(message)s",
+        "logging/handlers*/*_format_perfvars": "",
         "logging/handlers*/*_datefmt": "%FT%T",
         "logging/handlers*/file_append": false,
         "logging/handlers*/file_name": "",


Test patch:
diff --git a/unittests/conftest.py b/unittests/conftest.py
index a27f0660..5416d5e2 100644
--- a/unittests/conftest.py
+++ b/unittests/conftest.py
@@ -8,9 +8,13 @@
 #
 
 import contextlib
+import copy
 import pytest
+import tempfile
 
+import reframe.core.settings as settings
 import reframe.core.runtime as rt
+import reframe.utility as util
 
 from .utility import TEST_CONFIG_FILE
 
@@ -74,3 +78,34 @@ def make_exec_ctx_g(make_exec_ctx):
         yield ctx
 
     yield _make_exec_ctx
+
+
+@pytest.fixture
+def make_config_file(tmp_path):
+    '''Create a temporary configuration file from the given configuration.
+
+    Returns the name of the temporary configuration file.
+    '''
+
+    def _make_config_file(config):
+        site_config = copy.deepcopy(settings.site_configuration)
+        site_config.update(config)
+        with tempfile.NamedTemporaryFile(mode='w+t', dir=str(tmp_path),
+                                         suffix='.py', delete=False) as fp:
+            fp.write(f'site_configuration = {util.ppretty(site_config)}')
+
+        return fp.name
+
+    return _make_config_file
+
+
+@pytest.fixture
+def make_config_file_g(make_config_file):
+    '''Same as the `make_config_file` but to be used in `yield from`
+    expressions.'''
+
+    def _make_config_file(*args, **kwargs):
+        config_file = make_config_file(*args, **kwargs)
+        yield config_file
+
+    yield _make_config_file
diff --git a/unittests/test_logging.py b/unittests/test_logging.py
index e9823400..7aa492ae 100644
--- a/unittests/test_logging.py
+++ b/unittests/test_logging.py
@@ -3,22 +3,18 @@
 #
 # SPDX-License-Identifier: BSD-3-Clause
 
-import copy
 import logging
 import logging.handlers
 import os
 import pytest
 import re
 import sys
-import tempfile
 import time
 from datetime import datetime
 
 import reframe as rfm
 import reframe.core.logging as rlog
 import reframe.core.runtime as rt
-import reframe.core.settings as settings
-import reframe.utility as util
 from reframe.core.exceptions import ConfigError, ReframeError
 from reframe.core.backends import (getlauncher, getscheduler)
 from reframe.core.schedulers import Job
@@ -226,7 +222,7 @@ def _found_in_logfile(string, filename):
 
 
 @pytest.fixture
-def config_file(tmp_path, logfile):
+def config_file(make_config_file, logfile):
     def _config_file(logging_config=None):
         if logging_config is None:
             logging_config = {
@@ -245,13 +241,7 @@ def config_file(tmp_path, logfile):
                 'handlers_perflog': []
             }
 
-        site_config = copy.deepcopy(settings.site_configuration)
-        site_config['logging'] = [logging_config]
-        with tempfile.NamedTemporaryFile(mode='w+t', dir=str(tmp_path),
-                                         suffix='.py', delete=False) as fp:
-            fp.write(f'site_configuration = {util.ppretty(site_config)}')
-
-        return fp.name
+        return make_config_file({'logging': [logging_config]})
 
     return _config_file
 
@@ -317,6 +307,29 @@ def test_handler_noappend(make_exec_ctx, config_file, logfile):
     assert _found_in_logfile('bar', logfile)
 
 
+def test_handler_bad_format(make_exec_ctx, config_file, logfile):
+    make_exec_ctx(
+        config_file({
+            'level': 'info',
+            'handlers': [
+                {
+                    'type': 'file',
+                    'name': str(logfile),
+                    'level': 'warning',
+                    'format': '[%(asctime)s] %(levelname)s: %(message)',
+                    'datefmt': '%F',
+                    'append': False,
+                }
+            ],
+            'handlers_perflog': []
+        })
+    )
+
+    rlog.configure_logging(rt.runtime().site_config)
+    rlog.getlogger().warning('foo')
+    assert _found_in_logfile('<error formatting the log message:', logfile)
+
+
 def test_warn_once(default_exec_ctx, logfile):
     rlog.configure_logging(rt.runtime().site_config)
     rlog.getlogger().warning('foo', cache=True)
diff --git a/unittests/test_pipeline.py b/unittests/test_pipeline.py
index b21b354e..5e98b553 100644
--- a/unittests/test_pipeline.py
+++ b/unittests/test_pipeline.py
@@ -1434,8 +1434,7 @@ def test_reference_unknown_tag(dummytest, sanity_file,
             'foo': (3.1, -0.1, 0.1, None),
         }
     }
-    with pytest.raises(PerformanceError):
-        _run_sanity(dummytest, *dummy_gpu_exec_ctx)
+    _run_sanity(dummytest, *dummy_gpu_exec_ctx)
 
 
 def test_reference_unknown_system(dummytest, sanity_file,
diff --git a/unittests/test_policies.py b/unittests/test_policies.py
index 61485837..f86a1a22 100644
--- a/unittests/test_policies.py
+++ b/unittests/test_policies.py
@@ -13,6 +13,7 @@ import sys
 import time
 
 import reframe as rfm
+import reframe.core.logging as logging
 import reframe.core.runtime as rt
 import reframe.frontend.dependencies as dependencies
 import reframe.frontend.executors as executors
@@ -20,6 +21,7 @@ import reframe.frontend.executors.policies as policies
 import reframe.frontend.runreport as runreport
 import reframe.utility.jsonext as jsonext
 import reframe.utility.osext as osext
+import reframe.utility.sanity as sn
 import unittests.utility as test_util
 
 from lxml import etree
@@ -960,3 +962,243 @@ def test_config_params(make_runner, make_exec_ctx):
     runner.runall(testcases)
     assert runner.stats.num_cases() == 2
     assert not runner.stats.failed()
+
+
+@pytest.fixture
+def perf_test():
+    class _MyTest(rfm.RunOnlyRegressionTest):
+        valid_systems = ['*']
+        valid_prog_environs = ['*']
+        executable = 'echo perf0=100 && echo perf1=50'
+
+        @sanity_function
+        def validate(self):
+            return sn.assert_found(r'perf0', self.stdout)
+
+        @performance_function('unit0')
+        def perf0(self):
+            return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float)
+
+        @performance_function('unit1')
+        def perf1(self):
+            return sn.extractsingle(r'perf1=(\S+)', self.stdout, 1, float)
+
+    return _MyTest()
+
+
+@pytest.fixture
+def config_perflog(make_config_file):
+    def _config_perflog(fmt, perffmt=None, logging_opts=None):
+        logging_config = {
+            'level': 'debug2',
+            'handlers': [{
+                'type': 'stream',
+                'name': 'stdout',
+                'level': 'info',
+                'format': '%(message)s'
+            }],
+            'handlers_perflog': [{
+                'type': 'filelog',
+                'prefix': '%(check_system)s/%(check_partition)s',
+                'level': 'info',
+                'format': fmt
+            }]
+        }
+        if logging_opts:
+            logging_config.update(logging_opts)
+
+        if perffmt is not None:
+            logging_config['handlers_perflog'][0]['format_perfvars'] = perffmt
+
+        return make_config_file({'logging': [logging_config]})
+
+    return _config_perflog
+
+
+def _count_lines(filepath):
+    count = 0
+    with open(filepath) as fp:
+        for line in fp:
+            count += 1
+
+    return count
+
+
+def _assert_header(filepath, header):
+    with open(filepath) as fp:
+        assert fp.readline().strip() == header
+
+
+def test_perf_logging(make_runner, make_exec_ctx, perf_test,
+                      config_perflog, tmp_path):
+    make_exec_ctx(
+        config_perflog(
+            fmt=(
+                '%(check_job_completion_time)s,%(version)s,'
+                '%(check_display_name)s,%(check_system)s,'
+                '%(check_partition)s,%(check_environ)s,'
+                '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s'
+            ),
+            perffmt=(
+                '%(check_perf_value)s,%(check_perf_unit)s,'
+                '%(check_perf_ref)s,%(check_perf_lower)s,'
+                '%(check_perf_upper)s,'
+            )
+        )
+    )
+    logging.configure_logging(rt.runtime().site_config)
+    runner = make_runner()
+    testcases = executors.generate_testcases([perf_test])
+    runner.runall(testcases)
+
+    logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log'
+    assert os.path.exists(logfile)
+    assert _count_lines(logfile) == 2
+
+    # Rerun with the same configuration and check that new entry is appended
+    testcases = executors.generate_testcases([perf_test])
+    runner = make_runner()
+    runner.runall(testcases)
+    assert _count_lines(logfile) == 3
+
+    # Change the configuration and rerun
+    make_exec_ctx(
+        config_perflog(
+            fmt=(
+                '%(check_job_completion_time)s,%(version)s,'
+                '%(check_display_name)s,%(check_system)s,'
+                '%(check_partition)s,%(check_environ)s,'
+                '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s'
+            ),
+            perffmt='%(check_perf_value)s,%(check_perf_unit)s,'
+        )
+    )
+    logging.configure_logging(rt.runtime().site_config)
+    testcases = executors.generate_testcases([perf_test])
+    runner = make_runner()
+    runner.runall(testcases)
+    assert _count_lines(logfile) == 2
+    _assert_header(logfile,
+                   'job_completion_time,version,display_name,system,partition,'
+                   'environ,jobid,result,perf0_value,perf0_unit,'
+                   'perf1_value,perf1_unit')
+
+    logfile_prev = [(str(logfile) + '.h0', 3)]
+    for f, num_lines in logfile_prev:
+        assert os.path.exists(f)
+        _count_lines(f) == num_lines
+
+    # Change the test and rerun
+    perf_test.perf_variables['perfN'] = perf_test.perf_variables['perf1']
+
+    # We reconfigure the logging in order for the filelog handler to start
+    # from a clean state
+    logging.configure_logging(rt.runtime().site_config)
+    testcases = executors.generate_testcases([perf_test])
+    runner = make_runner()
+    runner.runall(testcases)
+    assert _count_lines(logfile) == 2
+    _assert_header(logfile,
+                   'job_completion_time,version,display_name,system,partition,'
+                   'environ,jobid,result,perf0_value,perf0_unit,'
+                   'perf1_value,perf1_unit,perfN_value,perfN_unit')
+
+    logfile_prev = [(str(logfile) + '.h0', 3), (str(logfile) + '.h1', 2)]
+    for f, num_lines in logfile_prev:
+        assert os.path.exists(f)
+        _count_lines(f) == num_lines
+
+
+def test_perf_logging_no_end_delim(make_runner, make_exec_ctx, perf_test,
+                                   config_perflog, tmp_path):
+    make_exec_ctx(
+        config_perflog(
+            fmt=(
+                '%(check_job_completion_time)s,%(version)s,'
+                '%(check_display_name)s,%(check_system)s,'
+                '%(check_partition)s,%(check_environ)s,'
+                '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s'
+            ),
+            perffmt='%(check_perf_value)s,%(check_perf_unit)s'
+        )
+    )
+    logging.configure_logging(rt.runtime().site_config)
+    runner = make_runner()
+    testcases = executors.generate_testcases([perf_test])
+    runner.runall(testcases)
+
+    logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log'
+    assert os.path.exists(logfile)
+    assert _count_lines(logfile) == 2
+
+    with open(logfile) as fp:
+        lines = fp.readlines()
+
+    assert len(lines) == 2
+    assert lines[0] == (
+        'job_completion_time,version,display_name,system,partition,'
+        'environ,jobid,result,perf0_value,perf0_unitperf1_value,perf1_unit\n'
+    )
+    assert '<error formatting the performance record' in lines[1]
+
+
+def test_perf_logging_no_perfvars(make_runner, make_exec_ctx, perf_test,
+                                  config_perflog, tmp_path):
+    make_exec_ctx(
+        config_perflog(
+            fmt=(
+                '%(check_job_completion_time)s,%(version)s,'
+                '%(check_display_name)s,%(check_system)s,'
+                '%(check_partition)s,%(check_environ)s,'
+                '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s'
+            )
+        )
+    )
+    logging.configure_logging(rt.runtime().site_config)
+    runner = make_runner()
+    testcases = executors.generate_testcases([perf_test])
+    runner.runall(testcases)
+
+    logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log'
+    assert os.path.exists(logfile)
+    assert _count_lines(logfile) == 2
+
+    with open(logfile) as fp:
+        lines = fp.readlines()
+
+    assert len(lines) == 2
+    assert lines[0] == (
+        'job_completion_time,version,display_name,system,partition,'
+        'environ,jobid,result,\n'
+    )
+    assert 'error' not in lines[1]
+
+
+def test_perf_logging_multiline(make_runner, make_exec_ctx, perf_test,
+                                config_perflog, tmp_path):
+    make_exec_ctx(
+        config_perflog(
+            fmt=(
+                '%(check_job_completion_time)s,%(version)s,'
+                '%(check_display_name)s,%(check_system)s,'
+                '%(check_partition)s,%(check_environ)s,'
+                '%(check_jobid)s,%(check_result)s,'
+                '%(check_perf_var)s=%(check_perf_value)s,%(check_perf_unit)s'
+            ),
+            logging_opts={'perflog_compat': True}
+        )
+    )
+    logging.configure_logging(rt.runtime().site_config)
+    runner = make_runner()
+    testcases = executors.generate_testcases([perf_test])
+    runner.runall(testcases)
+
+    logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log'
+    assert os.path.exists(logfile)
+    assert _count_lines(logfile) == 3
+
+    # assert that the emitted lines are correct
+    with open(logfile) as fp:
+        lines = fp.readlines()
+        assert ',perf0=100.0,unit0' in lines[1]
+        assert ',perf1=50.0,unit1'  in lines[2]