diff --git a/docs/config_reference.rst b/docs/config_reference.rst index 8256b819b4..4dbcab805a 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -1013,7 +1013,6 @@ All logging handlers share the following set of common attributes: ReFrame accepts all log record attributes from Python's `logging `__ mechanism and adds the following attributes: .. csv-table:: - :header: "Log record attribute", "Description" ``%(check_build_locally)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.build_locally` attribute. ``%(check_build_time_limit)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.build_time_limit` attribute. @@ -1073,6 +1072,13 @@ All logging handlers share the following set of common attributes: ReFrame allows you to log any test variable, parameter or property if they are marked as "loggable". The log record attribute will have the form ``%(check_NAME)s`` where ``NAME`` is the variable name, the parameter name or the property name that is marked as loggable. + There is also the special ``%(check_#ALL)s`` format specifier which expands to all the loggable test attributes. + These include all the above specifiers and any additional loggable variables or parameters defined by the test. + On expanding this specifier, ReFrame will try to guess the delimiter to use for separating the different attributes based on the existing format. + If it cannot guess it, it will default to ``|``. + + Since this can lead to very long records, you may consider using it with the :attr:`~logging.handlers_perflog..filelog..ignore_keys` parameter to filter out some attributes that are not of interest. + .. versionadded:: 3.3 Allow arbitrary test attributes to be logged. @@ -1082,6 +1088,9 @@ All logging handlers share the following set of common attributes: .. versionchanged:: 3.11.0 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. +.. versionadded:: 4.3 + The ``%(check_#ALL)s`` special specifier is added. + .. py:attribute:: logging.handlers.format_perfvars .. py:attribute:: logging.handlers_perflog.format_perfvars @@ -1185,6 +1194,13 @@ The additional properties for the ``filelog`` handler are the following: The base directory of performance data log files. +.. py:attribute:: logging.handlers_perflog..filelog..ignore_keys + + A list of log record `format specifiers <#config.logging.handlers.format>`__ that will be ignored by the special ``%(check_#ALL)s`` specifier. + + .. versionadded:: 4.3 + + .. py:attribute:: logging.handlers_perflog..filelog..prefix :required: Yes diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 44d3d62f6e..6794dc6ffc 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -128,12 +128,35 @@ 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() + for m in re.finditer(r'\%\((.*?)\)s(.)?', s): + d = m.group(2) + if d: + delims.add(d) + + if len(delims) == 1: + return delims.pop() + else: + return '|' + + class MultiFileHandler(logging.FileHandler): '''A file handler that allows writing on different log files based on information from the log record. ''' - def __init__(self, prefix, mode='a', encoding=None, fmt=None, perffmt=None): + def __init__(self, prefix, mode='a', encoding=None, fmt=None, + perffmt=None, ignore_keys=None): super().__init__(prefix, mode, encoding, delay=True) # Reset FileHandler's filename @@ -147,9 +170,21 @@ def __init__(self, prefix, mode='a', encoding=None, fmt=None, perffmt=None): self.__fmt = fmt self.__perffmt = perffmt self.__attr_patt = re.compile(r'\%\((.*?)\)s(.)?') + self.__ignore_keys = set(ignore_keys) if ignore_keys else set() def __generate_header(self, record): # Generate the header from the record and fmt + + # Expand the special check_#ALL specifier + if '%(check_#ALL)s' in self.__fmt: + delim = _guess_delim(self.__fmt) + self.__fmt = self.__fmt.replace( + '%(check_#ALL)s', + delim.join(f'%({x})s' + for x in sorted(record.__rfm_loggable_attrs__) + if x not in self.__ignore_keys) + ) + header = '' for m in self.__attr_patt.finditer(self.__fmt): attr = m.group(1) @@ -222,9 +257,8 @@ def emit(self, record): except OSError as e: raise LoggingError('logging failed') from e - self.baseFilename = os.path.join( - dirname, f'{record.__rfm_check__.short_name}.log' - ) + check_basename = type(record.__rfm_check__).variant_name() + self.baseFilename = os.path.join(dirname, f'{check_basename}.log') self._emit_header(record) self.stream = self.__streams[self.baseFilename] super().emit(record) @@ -263,13 +297,28 @@ class CheckFieldFormatter(logging.Formatter): regression test.''' # NOTE: This formatter will work only for the '%' style - def __init__(self, fmt=None, datefmt=None, perffmt=None, style='%'): + def __init__(self, fmt=None, datefmt=None, perffmt=None, + ignore_keys=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 '' + self.__expand_vars = '%(check_#ALL)s' in self.__fmt + self.__expanded = False + self.__ignore_keys = set(ignore_keys) if ignore_keys else set() + + def _expand_fmt(self, attrs): + if not self.__expand_vars or self.__expanded: + return self.__fmt + + delim = _guess_delim(self.__fmt) + self.__fmt = self.__fmt.replace( + '%(check_#ALL)s', delim.join(f'%({x})s' for x in attrs + if x not in self.__ignore_keys) + ) + self.__expanded = True def _format_perf(self, perfvars): chunks = [] @@ -292,6 +341,7 @@ def _format_perf(self, perfvars): return self.__delim.join(chunks) def formatMessage(self, record): + self._expand_fmt(sorted(record.__rfm_loggable_attrs__)) for s in self.__specs: if not hasattr(record, s): setattr(record, s, None) @@ -383,8 +433,10 @@ def _create_filelog_handler(site_config, config_prefix): append = site_config.get(f'{config_prefix}/append') format = site_config.get(f'{config_prefix}/format') format_perf = site_config.get(f'{config_prefix}/format_perfvars') + ignore_keys = site_config.get(f'{config_prefix}/ignore_keys') return MultiFileHandler(filename_patt, mode='a+' if append else 'w+', - fmt=format, perffmt=format_perf) + fmt=format, perffmt=format_perf, + ignore_keys=ignore_keys) def _create_syslog_handler(site_config, config_prefix): @@ -658,8 +710,10 @@ def _extract_handlers(site_config, handlers_group): fmt = site_config.get(f'{handler_prefix}/{i}/format') datefmt = site_config.get(f'{handler_prefix}/{i}/datefmt') perffmt = site_config.get(f'{handler_prefix}/{i}/format_perfvars') + ignore_keys = site_config.get(f'{handler_prefix}/{i}/ignore_keys') hdlr.setFormatter(RFC3339Formatter(fmt=fmt, - datefmt=datefmt, perffmt=perffmt)) + datefmt=datefmt, perffmt=perffmt, + ignore_keys=ignore_keys)) hdlr.setLevel(_check_level(level)) hdlr._rfm_type = handler_type handlers.append(hdlr) @@ -733,6 +787,7 @@ def __init__(self, logger=None, check=None): # Here we only set the format specifiers that do not # correspond directly to check attributes '__rfm_check__': check, + '__rfm_loggable_attrs__': [], 'check_name': 'reframe', 'check_jobid': None, 'check_job_completion_time': None, @@ -786,7 +841,9 @@ def _update_check_extras(self): # Attribute is parameter, so format it val = check_type.raw_params[attr].format(val) - self.extra[f'check_{extra_name}'] = val + key = f'check_{extra_name}' + self.extra['__rfm_loggable_attrs__'].append(key) + self.extra[key] = val # Add special extras self.extra['check_info'] = self.check.info() diff --git a/reframe/core/settings.py b/reframe/core/settings.py index cc7e4a3e52..dbd196a07a 100644 --- a/reframe/core/settings.py +++ b/reframe/core/settings.py @@ -54,16 +54,40 @@ 'type': 'filelog', 'prefix': '%(check_system)s/%(check_partition)s', 'level': 'info', - 'format': ( - '%(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': ('%(check_result)s|' + '%(check_job_completion_time)s|%(check_#ALL)s'), + 'ignore_keys': [ + 'check_build_locally', + 'check_build_time_limit', + 'check_display_name', + 'check_executable', + 'check_executable_opts', + 'check_hashcode', + 'check_keep_files', + 'check_local', + 'check_maintainers', + 'check_max_pending_time', + 'check_outputdir', + 'check_prebuild_cmds', + 'check_prefix', + 'check_prerun_cmds', + 'check_postbuild_cmds', + 'check_postrun_cmds', + 'check_readonly_files', + 'check_sourcepath', + 'check_sourcesdir', + 'check_stagedir', + 'check_strict_check', + 'check_tags', + 'check_time_limit', + 'check_valid_prog_environs', + 'check_valid_systems', + 'check_variables' + ], 'format_perfvars': ( - '%(check_perf_value)s,%(check_perf_unit)s,' - '%(check_perf_ref)s,%(check_perf_lower_thres)s,' - '%(check_perf_upper_thres)s,' + '%(check_perf_value)s|%(check_perf_unit)s|' + '%(check_perf_ref)s|%(check_perf_lower_thres)s|' + '%(check_perf_upper_thres)s|' ), 'append': True } diff --git a/reframe/schemas/config.json b/reframe/schemas/config.json index 19b25a75b3..59a1d8f9ec 100644 --- a/reframe/schemas/config.json +++ b/reframe/schemas/config.json @@ -84,7 +84,11 @@ "properties": { "basedir": {"type": "string"}, "prefix": {"type": "string"}, - "append": {"type": "boolean"} + "append": {"type": "boolean"}, + "ignore_keys": { + "type": "array", + "items": {"type": "string"} + } }, "required": ["prefix"] } @@ -577,6 +581,7 @@ "logging/handlers*/syslog_facility": "user", "logging/handlers_perflog/filelog_append": true, "logging/handlers_perflog/filelog_basedir": "./perflogs", + "logging/handlers_perflog/filelog_ignore_keys": [], "logging/handlers_perflog/graylog_extras": {}, "logging/handlers_perflog/httpjson_extras": {}, "logging/handlers_perflog/httpjson_ignore_keys": [], diff --git a/unittests/test_policies.py b/unittests/test_policies.py index 6c6ec4366d..e4b77bc37f 100644 --- a/unittests/test_policies.py +++ b/unittests/test_policies.py @@ -1021,6 +1021,29 @@ def perf1(self): return _MyTest() +@pytest.fixture +def perf_param_tests(): + class _MyTest(rfm.RunOnlyRegressionTest): + valid_systems = ['*'] + valid_prog_environs = ['*'] + executable = 'echo perf0=100 && echo perf1=50' + p = parameter([1, 2]) + + @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(variant_num=v) for v in range(_MyTest.num_variants)] + + @pytest.fixture def failing_perf_test(): class _MyFailingTest(rfm.RunOnlyRegressionTest): @@ -1321,3 +1344,33 @@ def test_perf_logging_lazy(make_runner, make_exec_ctx, lazy_perf_test, logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_LazyPerfTest.log' assert os.path.exists(logfile) + + +def test_perf_logging_all_attrs(make_runner, make_exec_ctx, perf_test, + config_perflog, tmp_path): + make_exec_ctx(config_perflog(fmt='%(check_result)s|%(check_#ALL)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) + with open(logfile) as fp: + header = fp.readline() + + loggable_attrs = type(perf_test).loggable_attrs() + assert len(header.split('|')) == len(loggable_attrs) + 1 + + +def test_perf_logging_param_test(make_runner, make_exec_ctx, perf_param_tests, + config_perflog, tmp_path): + make_exec_ctx(config_perflog(fmt='%(check_result)s|%(check_#ALL)s')) + logging.configure_logging(rt.runtime().site_config) + runner = make_runner() + testcases = executors.generate_testcases(perf_param_tests) + runner.runall(testcases) + + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + assert os.path.exists(logfile) + assert _count_lines(logfile) == 3