diff options
| -rw-r--r-- | lib/spack/spack/installer.py | 45 | ||||
| -rw-r--r-- | lib/spack/spack/solver/asp.py | 13 | ||||
| -rw-r--r-- | lib/spack/spack/test/install.py | 8 | ||||
| -rw-r--r-- | lib/spack/spack/test/util/timer.py | 149 | ||||
| -rw-r--r-- | lib/spack/spack/util/timer.py | 155 | ||||
| -rw-r--r-- | var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py | 5 |
6 files changed, 305 insertions, 70 deletions
diff --git a/lib/spack/spack/installer.py b/lib/spack/spack/installer.py index 41860ced19..c348dd58c5 100644 --- a/lib/spack/spack/installer.py +++ b/lib/spack/spack/installer.py @@ -54,9 +54,9 @@ import spack.repo import spack.store import spack.util.executable import spack.util.path +import spack.util.timer as timer from spack.util.environment import EnvironmentModifications, dump_environment from spack.util.executable import which -from spack.util.timer import Timer #: Counter to support unique spec sequencing that is used to ensure packages #: with the same priority are (initially) processed in the order in which they @@ -302,9 +302,9 @@ def _install_from_cache(pkg, cache_only, explicit, unsigned=False): bool: ``True`` if the package was extract from binary cache, ``False`` otherwise """ - timer = Timer() + t = timer.Timer() installed_from_cache = _try_install_from_binary_cache( - pkg, explicit, unsigned=unsigned, timer=timer + pkg, explicit, unsigned=unsigned, timer=t ) pkg_id = package_id(pkg) if not installed_from_cache: @@ -314,14 +314,14 @@ def _install_from_cache(pkg, cache_only, explicit, unsigned=False): tty.msg("{0}: installing from source".format(pre)) return False - timer.stop() + t.stop() tty.debug("Successfully extracted {0} from binary cache".format(pkg_id)) _print_timer( pre=_log_prefix(pkg.name), pkg_id=pkg_id, - fetch=timer.phases.get("search", 0) + timer.phases.get("fetch", 0), - build=timer.phases.get("install", 0), - total=timer.total, + fetch=t.duration("search") + t.duration("fetch"), + build=t.duration("install"), + total=t.duration(), ) _print_installed_pkg(pkg.spec.prefix) spack.hooks.post_install(pkg.spec) @@ -370,7 +370,7 @@ def _process_external_package(pkg, explicit): def _process_binary_cache_tarball( - pkg, binary_spec, explicit, unsigned, mirrors_for_spec=None, timer=None + pkg, binary_spec, explicit, unsigned, mirrors_for_spec=None, timer=timer.NULL_TIMER ): """ Process the binary cache tarball. @@ -389,11 +389,11 @@ def _process_binary_cache_tarball( bool: ``True`` if the package was extracted from binary cache, else ``False`` """ + timer.start("fetch") download_result = binary_distribution.download_tarball( binary_spec, unsigned, mirrors_for_spec=mirrors_for_spec ) - if timer: - timer.phase("fetch") + timer.stop("fetch") # see #10063 : install from source if tarball doesn't exist if download_result is None: tty.msg("{0} exists in binary cache but with different hash".format(pkg.name)) @@ -403,6 +403,7 @@ def _process_binary_cache_tarball( tty.msg("Extracting {0} from binary cache".format(pkg_id)) # don't print long padded paths while extracting/relocating binaries + timer.start("install") with spack.util.path.filter_padding(): binary_distribution.extract_tarball( binary_spec, download_result, allow_root=False, unsigned=unsigned, force=False @@ -410,12 +411,11 @@ def _process_binary_cache_tarball( pkg.installed_from_binary_cache = True spack.store.db.add(pkg.spec, spack.store.layout, explicit=explicit) - if timer: - timer.phase("install") + timer.stop("install") return True -def _try_install_from_binary_cache(pkg, explicit, unsigned=False, timer=None): +def _try_install_from_binary_cache(pkg, explicit, unsigned=False, timer=timer.NULL_TIMER): """ Try to extract the package from binary cache. @@ -428,10 +428,10 @@ def _try_install_from_binary_cache(pkg, explicit, unsigned=False, timer=None): """ pkg_id = package_id(pkg) tty.debug("Searching for binary cache of {0}".format(pkg_id)) - matches = binary_distribution.get_mirrors_for_spec(pkg.spec) - if timer: - timer.phase("search") + timer.start("search") + matches = binary_distribution.get_mirrors_for_spec(pkg.spec) + timer.stop("search") if not matches: return False @@ -1904,7 +1904,7 @@ class BuildProcessInstaller(object): self.env_mods = install_args.get("env_modifications", EnvironmentModifications()) # timer for build phases - self.timer = Timer() + self.timer = timer.Timer() # If we are using a padded path, filter the output to compress padded paths # The real log still has full-length paths. @@ -1959,8 +1959,8 @@ class BuildProcessInstaller(object): pre=self.pre, pkg_id=self.pkg_id, fetch=self.pkg._fetch_time, - build=self.timer.total - self.pkg._fetch_time, - total=self.timer.total, + build=self.timer.duration() - self.pkg._fetch_time, + total=self.timer.duration(), ) _print_installed_pkg(self.pkg.prefix) @@ -2033,6 +2033,7 @@ class BuildProcessInstaller(object): ) with log_contextmanager as logger: + # Redirect stdout and stderr to daemon pipe with logger.force_echo(): inner_debug_level = tty.debug_level() tty.set_debug(debug_level) @@ -2040,12 +2041,12 @@ class BuildProcessInstaller(object): tty.msg(msg.format(self.pre, phase_fn.name)) tty.set_debug(inner_debug_level) - # Redirect stdout and stderr to daemon pipe - self.timer.phase(phase_fn.name) - # Catch any errors to report to logging phase_fn.execute() + + self.timer.start(phase_fn.name) spack.hooks.on_phase_success(pkg, phase_fn.name, log_file) + self.timer.stop(phase_fn.name) except BaseException: combine_phase_logs(pkg.phase_log_files, pkg.log_path) diff --git a/lib/spack/spack/solver/asp.py b/lib/spack/spack/solver/asp.py index c070741c2c..9ff88af4df 100644 --- a/lib/spack/spack/solver/asp.py +++ b/lib/spack/spack/solver/asp.py @@ -619,11 +619,13 @@ class PyclingoDriver(object): self.control = control or default_clingo_control() # set up the problem -- this generates facts and rules self.assumptions = [] + timer.start("setup") with self.control.backend() as backend: self.backend = backend setup.setup(self, specs, reuse=reuse) - timer.phase("setup") + timer.stop("setup") + timer.start("load") # read in the main ASP program and display logic -- these are # handwritten, not generated, so we load them as resources parent_dir = os.path.dirname(__file__) @@ -653,12 +655,13 @@ class PyclingoDriver(object): self.control.load(os.path.join(parent_dir, "concretize.lp")) self.control.load(os.path.join(parent_dir, "os_compatibility.lp")) self.control.load(os.path.join(parent_dir, "display.lp")) - timer.phase("load") + timer.stop("load") # Grounding is the first step in the solve -- it turns our facts # and first-order logic rules into propositional logic. + timer.start("ground") self.control.ground([("base", [])]) - timer.phase("ground") + timer.stop("ground") # With a grounded program, we can run the solve. result = Result(specs) @@ -676,8 +679,10 @@ class PyclingoDriver(object): if clingo_cffi: solve_kwargs["on_unsat"] = cores.append + + timer.start("solve") solve_result = self.control.solve(**solve_kwargs) - timer.phase("solve") + timer.stop("solve") # once done, construct the solve result result.satisfiable = solve_result.satisfiable diff --git a/lib/spack/spack/test/install.py b/lib/spack/spack/test/install.py index da54216402..4f6ef31a41 100644 --- a/lib/spack/spack/test/install.py +++ b/lib/spack/spack/test/install.py @@ -252,12 +252,8 @@ def test_install_times(install_mockery, mock_fetch, mutable_mock_repo): # The order should be maintained phases = [x["name"] for x in times["phases"]] - total = sum([x["seconds"] for x in times["phases"]]) - for name in ["one", "two", "three", "install"]: - assert name in phases - - # Give a generous difference threshold - assert abs(total - times["total"]["seconds"]) < 5 + assert phases == ["one", "two", "three", "install"] + assert all(isinstance(x["seconds"], float) for x in times["phases"]) def test_flatten_deps(install_mockery, mock_fetch, mutable_mock_repo): diff --git a/lib/spack/spack/test/util/timer.py b/lib/spack/spack/test/util/timer.py new file mode 100644 index 0000000000..16c1564663 --- /dev/null +++ b/lib/spack/spack/test/util/timer.py @@ -0,0 +1,149 @@ +# Copyright 2013-2022 Lawrence Livermore National Security, LLC and other +# Spack Project Developers. See the top-level COPYRIGHT file for details. +# +# SPDX-License-Identifier: (Apache-2.0 OR MIT) + +import json +from io import StringIO + +import spack.util.timer as timer + + +class Tick(object): + """Timer that increments the seconds passed by 1 + everytime tick is called.""" + + def __init__(self): + self.time = 0.0 + + def tick(self): + self.time += 1 + return self.time + + +def test_timer(): + # 0 + t = timer.Timer(now=Tick().tick) + + # 1 (restart) + t.start() + + # 2 + t.start("wrapped") + + # 3 + t.start("first") + + # 4 + t.stop("first") + assert t.duration("first") == 1.0 + + # 5 + t.start("second") + + # 6 + t.stop("second") + assert t.duration("second") == 1.0 + + # 7-8 + with t.measure("third"): + pass + assert t.duration("third") == 1.0 + + # 9 + t.stop("wrapped") + assert t.duration("wrapped") == 7.0 + + # tick 10-13 + t.start("not-stopped") + assert t.duration("not-stopped") == 1.0 + assert t.duration("not-stopped") == 2.0 + assert t.duration("not-stopped") == 3.0 + + # 14 + assert t.duration() == 13.0 + + # 15 + t.stop() + assert t.duration() == 14.0 + + +def test_timer_stop_stops_all(): + # Ensure that timer.stop() effectively stops all timers. + + # 0 + t = timer.Timer(now=Tick().tick) + + # 1 + t.start("first") + + # 2 + t.start("second") + + # 3 + t.start("third") + + # 4 + t.stop() + + assert t.duration("first") == 3.0 + assert t.duration("second") == 2.0 + assert t.duration("third") == 1.0 + assert t.duration() == 4.0 + + +def test_stopping_unstarted_timer_is_no_error(): + t = timer.Timer(now=Tick().tick) + assert t.duration("hello") == 0.0 + t.stop("hello") + assert t.duration("hello") == 0.0 + + +def test_timer_write(): + text_buffer = StringIO() + json_buffer = StringIO() + + # 0 + t = timer.Timer(now=Tick().tick) + + # 1 + t.start("timer") + + # 2 + t.stop("timer") + + # 3 + t.stop() + + t.write_tty(text_buffer) + t.write_json(json_buffer) + + output = text_buffer.getvalue().splitlines() + assert "timer" in output[0] + assert "1.000s" in output[0] + assert "total" in output[1] + assert "3.000s" in output[1] + + deserialized = json.loads(json_buffer.getvalue()) + assert deserialized == { + "phases": [{"name": "timer", "seconds": 1.0}], + "total": {"seconds": 3.0}, + } + + +def test_null_timer(): + # Just ensure that the interface of the noop-timer doesn't break at some point + buffer = StringIO() + t = timer.NullTimer() + t.start() + t.start("first") + t.stop("first") + with t.measure("second"): + pass + t.stop() + assert t.duration("first") == 0.0 + assert t.duration() == 0.0 + assert not t.phases + t.write_json(buffer) + t.write_tty(buffer) + assert not buffer.getvalue() diff --git a/lib/spack/spack/util/timer.py b/lib/spack/spack/util/timer.py index f7a9bc8e9d..f7f13e6a3e 100644 --- a/lib/spack/spack/util/timer.py +++ b/lib/spack/spack/util/timer.py @@ -11,51 +11,140 @@ a stack trace and drops the user into an interpreter. """ import sys import time +from collections import OrderedDict, namedtuple +from contextlib import contextmanager + +from llnl.util.lang import pretty_seconds import spack.util.spack_json as sjson +Interval = namedtuple("Interval", ("begin", "end")) -class Timer(object): - """ - Simple timer for timing phases of a solve or install - """ - - def __init__(self): - self.start = time.time() - self.last = self.start - self.phases = {} - self.end = None - - def phase(self, name): - last = self.last - now = time.time() - self.phases[name] = now - last - self.last = now +#: name for the global timer (used in start(), stop(), duration() without arguments) +global_timer_name = "_global" + + +class NullTimer(object): + """Timer interface that does nothing, useful in for "tell + don't ask" style code when timers are optional.""" + + def start(self, name=global_timer_name): + pass + + def stop(self, name=global_timer_name): + pass + + def duration(self, name=global_timer_name): + return 0.0 + + @contextmanager + def measure(self, name): + yield @property - def total(self): - """Return the total time""" - if self.end: - return self.end - self.start - return time.time() - self.start + def phases(self): + return [] + + def write_json(self, out=sys.stdout): + pass - def stop(self): + def write_tty(self, out=sys.stdout): + pass + + +#: instance of a do-nothing timer +NULL_TIMER = NullTimer() + + +class Timer(object): + """Simple interval timer""" + + def __init__(self, now=time.time): """ - Stop the timer to record a total time, if desired. + Arguments: + now: function that gives the seconds since e.g. epoch """ - self.end = time.time() + self._now = now + self._timers = OrderedDict() # type: OrderedDict[str,Interval] - def write_json(self, out=sys.stdout): + # _global is the overal timer since the instance was created + self._timers[global_timer_name] = Interval(self._now(), end=None) + + def start(self, name=global_timer_name): """ - Write a json object with times to file + Start or restart a named timer, or the global timer when no name is given. + + Arguments: + name (str): Optional name of the timer. When no name is passed, the + global timer is started. """ - phases = [{"name": p, "seconds": s} for p, s in self.phases.items()] - times = {"phases": phases, "total": {"seconds": self.total}} + self._timers[name] = Interval(self._now(), None) + + def stop(self, name=global_timer_name): + """ + Stop a named timer, or all timers when no name is given. Stopping a + timer that has not started has no effect. + + Arguments: + name (str): Optional name of the timer. When no name is passed, all + timers are stopped. + """ + interval = self._timers.get(name, None) + if not interval: + return + self._timers[name] = Interval(interval.begin, self._now()) + + def duration(self, name=global_timer_name): + """ + Get the time in seconds of a named timer, or the total time if no + name is passed. The duration is always 0 for timers that have not been + started, no error is raised. + + Arguments: + name (str): (Optional) name of the timer + + Returns: + float: duration of timer. + """ + try: + interval = self._timers[name] + except KeyError: + return 0.0 + # Take either the interval end, the global timer, or now. + end = interval.end or self._timers[global_timer_name].end or self._now() + return end - interval.begin + + @contextmanager + def measure(self, name): + """ + Context manager that allows you to time a block of code. + + Arguments: + name (str): Name of the timer + """ + begin = self._now() + yield + self._timers[name] = Interval(begin, self._now()) + + @property + def phases(self): + """Get all named timers (excluding the global/total timer)""" + return [k for k in self._timers.keys() if k != global_timer_name] + + def write_json(self, out=sys.stdout): + """Write a json object with times to file""" + phases = [{"name": p, "seconds": self.duration(p)} for p in self.phases] + times = {"phases": phases, "total": {"seconds": self.duration()}} out.write(sjson.dump(times)) def write_tty(self, out=sys.stdout): - now = time.time() - out.write("Time:\n") - for phase, t in self.phases.items(): - out.write(" %-15s%.4f\n" % (phase + ":", t)) - out.write("Total: %.4f\n" % (now - self.start)) + """Write a human-readable summary of timings""" + # Individual timers ordered by registration + formatted = [(p, pretty_seconds(self.duration(p))) for p in self.phases] + + # Total time + formatted.append(("total", pretty_seconds(self.duration()))) + + # Write to out + for name, duration in formatted: + out.write(" {:10s} {:>10s}\n".format(name, duration)) diff --git a/var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py b/var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py index 916156c1f5..1576e36ad4 100644 --- a/var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py +++ b/var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py @@ -3,8 +3,6 @@ # # SPDX-License-Identifier: (Apache-2.0 OR MIT) -from time import sleep - from spack.package import * @@ -17,15 +15,12 @@ class DevBuildTestInstallPhases(Package): phases = ["one", "two", "three", "install"] def one(self, spec, prefix): - sleep(1) print("One locomoco") def two(self, spec, prefix): - sleep(2) print("Two locomoco") def three(self, spec, prefix): - sleep(3) print("Three locomoco") def install(self, spec, prefix): |