diff --git a/docs/config_reference.rst b/docs/config_reference.rst index d91da8d8b4..4a34f9a965 100644 --- a/docs/config_reference.rst +++ b/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 `__ being logged. + - ``%(check_perf_var)s``: The name of the `performance variable `__ 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 `__ 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. diff --git a/docs/configure.rst b/docs/configure.rst index acb524738e..8c3651e738 100644 --- a/docs/configure.rst +++ b/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. diff --git a/reframe/core/pipeline.py b/reframe/core/pipeline.py index f5dc3654e2..89408a0976 100644 --- a/reframe/core/pipeline.py +++ b/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