From 9ae4dc006afe5e201f4d366ab743dba187efb1e7 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 16 May 2023 01:00:43 +0200 Subject: [PATCH 1/4] Combine logs for parameterised tests Also: - New special log format specifier that dumps all the loggable test attributes --- reframe/core/logging.py | 73 +++++++++++++++++++++++++++++++++----- reframe/core/settings.py | 42 +++++++++++++++++----- unittests/test_policies.py | 53 +++++++++++++++++++++++++++ 3 files changed, 151 insertions(+), 17 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 44d3d62f6e..0ff07baa33 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 for 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/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 From d2267294196bdcfb37983379cb677fe0780eeb7f Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 23 May 2023 23:45:06 +0200 Subject: [PATCH 2/4] Update docs + configuration schema --- docs/config_reference.rst | 19 +++++++++++++++++-- reframe/schemas/config.json | 7 ++++++- 2 files changed, 23 insertions(+), 3 deletions(-) diff --git a/docs/config_reference.rst b/docs/config_reference.rst index e2f29c4879..00c85af1b8 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -999,7 +999,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. @@ -1059,6 +1058,10 @@ 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. + Since this can lead to very length 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. @@ -1068,6 +1071,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 @@ -1175,6 +1181,15 @@ The additional properties for the ``filelog`` handler are the following: The base directory of performance data log files. +.. py:attribute:: logging.handlers..filelog..ignore_keys + +.. 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..filelog..prefix .. py:attribute:: logging.handlers_perflog..filelog..prefix @@ -1182,7 +1197,7 @@ The additional properties for the ``filelog`` handler are the following: :required: Yes This is a directory prefix (usually dynamic), appended to the :attr:`~config.logging.handlers..filelog..basedir`, where the performance logs of a test will be stored. - This attribute accepts any of the check-specific `formatting placeholders <#config.logging.handlers_perflog.format>`__. + This attribute accepts any of the check-specific `formatting specifiers <#config.logging.handlers_perflog.format>`__. This allows to create dynamic paths based on the current system, partition and/or programming environment a test executes with. For example, a value of ``%(check_system)s/%(check_partition)s`` would generate the following structure of performance log files: diff --git a/reframe/schemas/config.json b/reframe/schemas/config.json index 3589bca972..2aa601e529 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"] } @@ -573,6 +577,7 @@ "logging/handlers*/file_timestamp": false, "logging/handlers*/filelog_append": true, "logging/handlers*/filelog_basedir": "./perflogs", + "logging/handlers*/filelog_ignore_keys": [], "logging/handlers*/graylog_extras": {}, "logging/handlers*/httpjson_extras": {}, "logging/handlers*/httpjson_ignore_keys": [], From 95c690dcd3b9a920a69c9279beed6467aa39b904 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 23 May 2023 23:51:00 +0200 Subject: [PATCH 3/4] Change default delimiter of %(check_#ALL)s --- docs/config_reference.rst | 3 +++ reframe/core/logging.py | 2 +- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/docs/config_reference.rst b/docs/config_reference.rst index 00c85af1b8..868fe0d208 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -1060,6 +1060,9 @@ All logging handlers share the following set of common attributes: 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 length 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 diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 0ff07baa33..ba3c422486 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -147,7 +147,7 @@ def _guess_delim(s): if len(delims) == 1: return delims.pop() else: - return ',' + return '|' class MultiFileHandler(logging.FileHandler): From 7350ee185d623b7fc927f9260ed7af37a3446d25 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 13 Jun 2023 01:13:59 +0200 Subject: [PATCH 4/4] Apply suggestions from code review Co-authored-by: Eirini Koutsaniti --- docs/config_reference.rst | 2 +- reframe/core/logging.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/config_reference.rst b/docs/config_reference.rst index 868fe0d208..4d33bfa0ed 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -1063,7 +1063,7 @@ All logging handlers share the following set of common attributes: 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 length 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. + 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. diff --git a/reframe/core/logging.py b/reframe/core/logging.py index ba3c422486..6794dc6ffc 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -175,7 +175,7 @@ def __init__(self, prefix, mode='a', encoding=None, fmt=None, def __generate_header(self, record): # Generate the header from the record and fmt - # Expand the for the special check_#ALL specifier + # Expand the special check_#ALL specifier if '%(check_#ALL)s' in self.__fmt: delim = _guess_delim(self.__fmt) self.__fmt = self.__fmt.replace(