From 948d3f26ec6d5645ec258ca08c0e002445f4a944 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Sat, 25 Jun 2022 11:26:22 +0200 Subject: [PATCH 1/4] Add a lightweight time profiler for the framework --- reframe/core/logging.py | 9 ++++ reframe/frontend/cli.py | 1 + reframe/utility/profile.py | 90 ++++++++++++++++++++++++++++++++++++++ unittests/test_profiler.py | 58 ++++++++++++++++++++++++ 4 files changed, 158 insertions(+) create mode 100644 reframe/utility/profile.py create mode 100644 unittests/test_profiler.py diff --git a/reframe/core/logging.py b/reframe/core/logging.py index e8deb699a1..18cc02fd7f 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -20,6 +20,7 @@ import reframe.utility.jsonext as jsonext import reframe.utility.osext as osext from reframe.core.exceptions import ConfigError, LoggingError +from reframe.utility.profile import TimeProfiler # Global configuration options for logging @@ -726,3 +727,11 @@ def getlogger(): def getperflogger(check): return LoggerAdapter(_perf_logger, check) + + +# Global framework profiler +_profiler = TimeProfiler() + + +def getprofiler(): + return _profiler diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index abd8550ce1..a50625f65d 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -27,6 +27,7 @@ import reframe.frontend.runreport as runreport import reframe.utility.jsonext as jsonext import reframe.utility.osext as osext +import reframe.utility.profile as prof import reframe.utility.typecheck as typ diff --git a/reframe/utility/profile.py b/reframe/utility/profile.py new file mode 100644 index 0000000000..8adb32b0de --- /dev/null +++ b/reframe/utility/profile.py @@ -0,0 +1,90 @@ +# Copyright 2016-2022 Swiss National Supercomputing Centre (CSCS/ETH Zurich) +# ReFrame Project Developers. See the top-level LICENSE file for details. +# +# SPDX-License-Identifier: BSD-3-Clause + +# A lightweight time profiler + +import time + + +class ProfilerError(Exception): + pass + + +class time_region: + '''Context manager for timing a code region''' + + def __init__(self, region, profiler=None): + self._profiler = profiler or TimeProfiler() + self._region = region + + def __enter__(self): + self._profiler.enter_region(self._region) + return self._profiler + + def __exit__(self, exc_type, exc_val, exc_tb): + self._profiler.exit_region() + + +class TimeProfiler: + def __init__(self): + self._region_stack = ['root'] + self._region_times = {} + + @property + def current_region(self): + return self._region_stack[-1] + + def enter_region(self, region_name): + timestamp = time.time() + region_fullname = f'{self.current_region}:{region_name}' + if region_fullname in self._region_times: + elapsed = self._region_times[region_fullname][1] + else: + elapsed = 0.0 + + self._region_times[region_fullname] = (timestamp, elapsed) + self._region_stack.append(region_fullname) + + def exit_region(self): + timestamp = time.time() + region = self.current_region + t_start, elapsed = self._region_times[region] + self._region_times[region] = (None, elapsed + timestamp - t_start) + self._region_stack.pop() + + def total_time(self, region_name): + for region in reversed(self._region_times): + if (region == region_name or + region.rsplit(':', maxsplit=1)[-1] == region_name): + timestamp, elapsed = self._region_times[region] + if timestamp: + raise ProfilerError( + f'region {region_name!r} has not exited' + ) + + return elapsed + + raise ProfilerError(f'unknown region: {region_name!r}') + + def time_region(self, region): + return globals()['time_region'](region, self) + + def print_report(self, print_fn=None): + if print_fn is None: + print_fn = print + + print_fn('>>> timing report [start] <<<') + for name, t_info in self._region_times.items(): + # Remove the root prefix + levels = name.count(':') + indent = ' '*4*(levels - 1) + region_name = name.rsplit(':', maxsplit=1)[-1] + msg = f'{indent}{region_name}: {t_info[1]:.6f} s' + if t_info[0]: + msg += ' ' + + print_fn(msg) + + print_fn('>>> timing report [ end ] <<<') diff --git a/unittests/test_profiler.py b/unittests/test_profiler.py new file mode 100644 index 0000000000..deaf5118da --- /dev/null +++ b/unittests/test_profiler.py @@ -0,0 +1,58 @@ +# Copyright 2016-2022 Swiss National Supercomputing Centre (CSCS/ETH Zurich) +# ReFrame Project Developers. See the top-level LICENSE file for details. +# +# SPDX-License-Identifier: BSD-3-Clause + + +import pytest +import time + +import reframe.utility.profile as prof + + +def test_region_profiling(): + profiler = prof.TimeProfiler() + profiler.enter_region('forloop') + for _ in range(10): + profiler.enter_region('sleep') + time.sleep(.1) + profiler.exit_region() + + profiler.exit_region() + + t_sleep = profiler.total_time('sleep') + t_forloop = profiler.total_time('forloop') + assert t_sleep >= 1 + assert t_forloop > t_sleep + + with pytest.raises(prof.ProfilerError): + profiler.total_time('foo') + + profiler.enter_region('unexited') + with pytest.raises(prof.ProfilerError): + profiler.total_time('unexited') + + +def test_time_region_ctxmgr(): + with prof.time_region('forloop') as profiler: + for _ in range(10): + with prof.time_region('sleep', profiler): + time.sleep(.1) + + t_sleep = profiler.total_time('sleep') + t_forloop = profiler.total_time('forloop') + assert t_sleep >= 1 + assert t_forloop > t_sleep + + +def test_time_region_profiler_ctxmgr(): + profiler = prof.TimeProfiler() + with profiler.time_region('forloop'): + for _ in range(10): + with profiler.time_region('sleep'): + time.sleep(.1) + + t_sleep = profiler.total_time('sleep') + t_forloop = profiler.total_time('forloop') + assert t_sleep >= 1 + assert t_forloop > t_sleep From ebd17b1aa726460343f2ee504cf8d8b4305de67f Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Mon, 27 Jun 2022 11:57:41 +0200 Subject: [PATCH 2/4] Profile critical functions of the framework --- reframe/core/decorators.py | 3 ++- reframe/core/logging.py | 20 ++++++++++++++++++++ reframe/frontend/cli.py | 9 +++++++++ reframe/frontend/dependencies.py | 6 +++++- reframe/frontend/executors/__init__.py | 13 +++++++++++++ reframe/frontend/loader.py | 3 ++- reframe/frontend/testgenerators.py | 5 ++++- reframe/utility/profile.py | 4 ++-- 8 files changed, 57 insertions(+), 6 deletions(-) diff --git a/reframe/core/decorators.py b/reframe/core/decorators.py index 997cd25b67..2efd793fcb 100644 --- a/reframe/core/decorators.py +++ b/reframe/core/decorators.py @@ -23,7 +23,7 @@ import reframe.core.hooks as hooks from reframe.core.exceptions import ReframeSyntaxError, SkipTestError, what from reframe.core.fixtures import FixtureRegistry -from reframe.core.logging import getlogger +from reframe.core.logging import getlogger, time_function from reframe.core.pipeline import RegressionTest from reframe.utility.versioning import VersionValidator @@ -64,6 +64,7 @@ def skip(self, test): '''Add a test to the skip set.''' self._skip_tests.add(test) + @time_function def instantiate_all(self, reset_sysenv=0): '''Instantiate all the registered tests. diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 18cc02fd7f..8a66fed422 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -735,3 +735,23 @@ def getperflogger(check): def getprofiler(): return _profiler + + +def time_function(fn): + '''Decorator for timing a function using the global profiler''' + + def _fn(*args, **kwargs): + with _profiler.time_region(fn.__qualname__): + return fn(*args, **kwargs) + + return _fn + + +def time_function_noexit(fn): + '''Decorator for timing a function using the global profiler''' + + def _fn(*args, **kwargs): + _profiler.enter_region(fn.__qualname__) + return fn(*args, **kwargs) + + return _fn diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index a50625f65d..a07e19de51 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -48,6 +48,7 @@ def format_env(envvars): return ret +@logging.time_function def list_checks(testcases, printer, detailed=False, concretized=False): printer.info('[List of matched checks]') unique_checks = set() @@ -115,6 +116,7 @@ def dep_lines(u, *, prefix, depth=0, lines=None, printed=None): printer.info(f'Found {len(unique_checks)} check(s)\n') +@logging.time_function def describe_checks(testcases, printer): records = [] unique_names = set() @@ -187,6 +189,7 @@ def calc_verbosity(site_config, quiesce): return curr_verbosity - quiesce +@logging.time_function_noexit def main(): # Setup command line options argparser = argparse.ArgumentParser() @@ -946,6 +949,8 @@ def print_infoline(param, value): print_infoline('output directory', repr(session_info['prefix_output'])) printer.info('') try: + logging.getprofiler().enter_region('test processing') + # Need to parse the cli options before loading the tests parsed_job_options = [] for opt in options.job_options: @@ -1362,6 +1367,7 @@ def module_unuse(*paths): sys.exit(1) finally: try: + logging.getprofiler().exit_region() # region: 'test processing' log_files = logging.log_files() if site_config.get('general/0/save_log_files'): log_files = logging.save_log_files(rt.output_prefix) @@ -1372,3 +1378,6 @@ def module_unuse(*paths): finally: if not restrict_logging(): printer.info(logfiles_message()) + + logging.getprofiler().exit_region() # region: 'main' + logging.getprofiler().print_report(printer.debug) diff --git a/reframe/frontend/dependencies.py b/reframe/frontend/dependencies.py index 5c719c4d4c..4242ab5ee1 100644 --- a/reframe/frontend/dependencies.py +++ b/reframe/frontend/dependencies.py @@ -13,9 +13,10 @@ import reframe.utility as util from reframe.core.exceptions import DependencyError -from reframe.core.logging import getlogger +from reframe.core.logging import getlogger, time_function +@time_function def build_deps(cases, default_cases=None): '''Build dependency graph from test cases. @@ -139,6 +140,7 @@ def _reduce_deps(graph): return ret +@time_function def validate_deps(graph): '''Validate dependency graph.''' @@ -181,6 +183,7 @@ def validate_deps(graph): sources -= visited +@time_function def prune_deps(graph, testcases, max_depth=None): '''Prune the graph so that it contains only the specified cases and their dependencies up to max_depth. @@ -205,6 +208,7 @@ def prune_deps(graph, testcases, max_depth=None): return pruned_graph +@time_function def toposort(graph, is_subgraph=False): '''Return a list of the graph nodes topologically sorted. diff --git a/reframe/frontend/executors/__init__.py b/reframe/frontend/executors/__init__.py index 7c0acb543a..c2c6fd8e07 100644 --- a/reframe/frontend/executors/__init__.py +++ b/reframe/frontend/executors/__init__.py @@ -106,6 +106,7 @@ def clone(self): return TestCase(self._check_orig, self._partition, self._environ) +@logging.time_function def generate_testcases(checks, prepare=False): '''Generate concrete test cases from checks. @@ -313,22 +314,27 @@ def __exit__(this, exc_type, exc_value, traceback): self.fail() raise TaskExit from e + @logging.time_function def setup(self, *args, **kwargs): self.testcase.prepare() self._safe_call(self.check.setup, *args, **kwargs) self._notify_listeners('on_task_setup') + @logging.time_function def compile(self): self._safe_call(self.check.compile) self._notify_listeners('on_task_compile') + @logging.time_function def compile_wait(self): self._safe_call(self.check.compile_wait) + @logging.time_function def run(self): self._safe_call(self.check.run) self._notify_listeners('on_task_run') + @logging.time_function def run_complete(self): done = self._safe_call(self.check.run_complete) if done: @@ -337,6 +343,7 @@ def run_complete(self): return done + @logging.time_function def compile_complete(self): done = self._safe_call(self.check.compile_complete) if done: @@ -344,16 +351,20 @@ def compile_complete(self): return done + @logging.time_function def run_wait(self): self._safe_call(self.check.run_wait) self.zombie = False + @logging.time_function def sanity(self): self._safe_call(self.check.sanity) + @logging.time_function def performance(self): self._safe_call(self.check.performance) + @logging.time_function def finalize(self): try: jsonfile = os.path.join(self.check.stagedir, '.rfm_testcase.json') @@ -367,6 +378,7 @@ def finalize(self): self._current_stage = 'finalize' self._notify_listeners('on_task_success') + @logging.time_function def cleanup(self, *args, **kwargs): self._safe_call(self.check.cleanup, *args, **kwargs) @@ -479,6 +491,7 @@ def policy(self): def stats(self): return self._stats + @logging.time_function def runall(self, testcases, restored_cases=None): num_checks = len({tc.check.unique_name for tc in testcases}) self._printer.separator('short double line', diff --git a/reframe/frontend/loader.py b/reframe/frontend/loader.py index e4bff19675..ab664872e8 100644 --- a/reframe/frontend/loader.py +++ b/reframe/frontend/loader.py @@ -18,7 +18,7 @@ import reframe.utility as util import reframe.utility.osext as osext from reframe.core.exceptions import NameConflictError, is_severe, what -from reframe.core.logging import getlogger +from reframe.core.logging import getlogger, time_function class RegressionCheckValidator(ast.NodeVisitor): @@ -267,6 +267,7 @@ def load_from_dir(self, dirname, recurse=False, force=False): return checks + @time_function def load_all(self, force=False): '''Load all checks in self._load_path. diff --git a/reframe/frontend/testgenerators.py b/reframe/frontend/testgenerators.py index 2f9030ad5f..b92ba8a34e 100644 --- a/reframe/frontend/testgenerators.py +++ b/reframe/frontend/testgenerators.py @@ -9,12 +9,13 @@ import reframe.utility as util from reframe.core.decorators import TestRegistry -from reframe.core.logging import getlogger +from reframe.core.logging import getlogger, getprofiler, time_function from reframe.core.meta import make_test from reframe.core.schedulers import Job from reframe.frontend.executors import generate_testcases +@time_function def getallnodes(state='all', jobs_cli_options=None): rt = runtime.runtime() nodes = {} @@ -72,6 +73,7 @@ def _rfm_set_valid_systems(obj): return _rfm_set_valid_systems +@time_function def distribute_tests(testcases, node_map): '''Returns new testcases that will be parameterized to run in node of their partitions based on the nodemap @@ -126,6 +128,7 @@ def distribute_tests(testcases, node_map): return generate_testcases(new_checks) +@time_function def repeat_tests(testcases, num_repeats): '''Returns new test cases parameterized over their repetition number''' diff --git a/reframe/utility/profile.py b/reframe/utility/profile.py index 8adb32b0de..825387f34f 100644 --- a/reframe/utility/profile.py +++ b/reframe/utility/profile.py @@ -75,7 +75,7 @@ def print_report(self, print_fn=None): if print_fn is None: print_fn = print - print_fn('>>> timing report [start] <<<') + print_fn('>>> profiler report [start] <<<') for name, t_info in self._region_times.items(): # Remove the root prefix levels = name.count(':') @@ -87,4 +87,4 @@ def print_report(self, print_fn=None): print_fn(msg) - print_fn('>>> timing report [ end ] <<<') + print_fn('>>> profiler report [ end ] <<<') From 4f684ec5da50d2893005e7c2be5100c383af070c Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Mon, 27 Jun 2022 16:29:46 +0200 Subject: [PATCH 3/4] Remove unused imports --- reframe/frontend/cli.py | 1 - reframe/frontend/testgenerators.py | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/reframe/frontend/cli.py b/reframe/frontend/cli.py index a07e19de51..c6893e4c56 100644 --- a/reframe/frontend/cli.py +++ b/reframe/frontend/cli.py @@ -27,7 +27,6 @@ import reframe.frontend.runreport as runreport import reframe.utility.jsonext as jsonext import reframe.utility.osext as osext -import reframe.utility.profile as prof import reframe.utility.typecheck as typ diff --git a/reframe/frontend/testgenerators.py b/reframe/frontend/testgenerators.py index b92ba8a34e..3004a1e19a 100644 --- a/reframe/frontend/testgenerators.py +++ b/reframe/frontend/testgenerators.py @@ -9,7 +9,7 @@ import reframe.utility as util from reframe.core.decorators import TestRegistry -from reframe.core.logging import getlogger, getprofiler, time_function +from reframe.core.logging import getlogger, time_function from reframe.core.meta import make_test from reframe.core.schedulers import Job from reframe.frontend.executors import generate_testcases From a87bd19667fbac39c7745430aec2c110333b1900 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Mon, 27 Jun 2022 16:31:16 +0200 Subject: [PATCH 4/4] Use an `OrderedDict` for Python 3.6 and 3.7 --- reframe/utility/profile.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/reframe/utility/profile.py b/reframe/utility/profile.py index 825387f34f..2107c380c5 100644 --- a/reframe/utility/profile.py +++ b/reframe/utility/profile.py @@ -6,6 +6,9 @@ # A lightweight time profiler import time +import sys + +from collections import OrderedDict class ProfilerError(Exception): @@ -30,7 +33,10 @@ def __exit__(self, exc_type, exc_val, exc_tb): class TimeProfiler: def __init__(self): self._region_stack = ['root'] - self._region_times = {} + if sys.version_info[:2] < (3, 8): + self._region_times = OrderedDict() + else: + self._region_times = {} @property def current_region(self): @@ -55,7 +61,7 @@ def exit_region(self): self._region_stack.pop() def total_time(self, region_name): - for region in reversed(self._region_times): + for region in reversed(self._region_times.keys()): if (region == region_name or region.rsplit(':', maxsplit=1)[-1] == region_name): timestamp, elapsed = self._region_times[region]