Fix incorrect timer (#33900)

Revamp the timer so we always have a designated begin and end.

Fix a bug where the phase timer was stopped before the phase started,
resulting in incorrect timing reports in timers.json.

lib/spack/spack/installer.py

@@ -56,9 +56,9 @@
 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
@@ -304,9 +304,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:
@@ -316,14 +316,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),
+        fetch=t.duration("search") + t.duration("fetch"),
-        build=timer.phases.get("install", 0),
+        build=t.duration("install"),
-        total=timer.total,
+        total=t.duration(),
     )
     _print_installed_pkg(pkg.spec.prefix)
     spack.hooks.post_install(pkg.spec)
@@ -372,7 +372,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.
@@ -391,11 +391,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.stop("fetch")
-        timer.phase("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))
@@ -405,6 +405,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
@@ -412,12 +413,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.stop("install")
-        timer.phase("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.
 
@@ -430,10 +430,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.start("search")
-        timer.phase("search")
+    matches = binary_distribution.get_mirrors_for_spec(pkg.spec)
+    timer.stop("search")
 
     if not matches:
         return False
@@ -1906,7 +1906,7 @@ def __init__(self, pkg, install_args):
         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.
@@ -1961,8 +1961,8 @@ def run(self):
             pre=self.pre,
             pkg_id=self.pkg_id,
             fetch=self.pkg._fetch_time,
-            build=self.timer.total - self.pkg._fetch_time,
+            build=self.timer.duration() - self.pkg._fetch_time,
-            total=self.timer.total,
+            total=self.timer.duration(),
         )
         _print_installed_pkg(self.pkg.prefix)
 
@@ -2035,6 +2035,7 @@ def _real_install(self):
                     )
 
                     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)
@@ -2042,12 +2043,12 @@ def _real_install(self):
                             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)

lib/spack/spack/solver/asp.py

@@ -622,11 +622,13 @@ def solve(self, setup, specs, reuse=None, output=None, control=None):
         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__)
@@ -656,12 +658,13 @@ def visit(node):
         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)
@@ -679,8 +682,10 @@ def on_model(model):
 
         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

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"]])
+    assert phases == ["one", "two", "three", "install"]
-    for name in ["one", "two", "three", "install"]:
+    assert all(isinstance(x["seconds"], float) for x in times["phases"])
-        assert name in phases
-
-    # Give a generous difference threshold
-    assert abs(total - times["total"]["seconds"]) < 5
 
 
 def test_flatten_deps(install_mockery, mock_fetch, mutable_mock_repo):

lib/spack/spack/test/util/timer.py

@@ -0,0 +1,150 @@
+# 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 six 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()

lib/spack/spack/util/timer.py

@@ -11,51 +11,140 @@
 """
 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):
+#: name for the global timer (used in start(), stop(), duration() without arguments)
-    """
+global_timer_name = "_global"
-    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):
+class NullTimer(object):
-        last = self.last
+    """Timer interface that does nothing, useful in for "tell
-        now = time.time()
+    don't ask" style code when timers are optional."""
-        self.phases[name] = now - last
+
-        self.last = now
+    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):
+    def phases(self):
-        """Return the total time"""
+        return []
-        if self.end:
-            return self.end - self.start
-        return time.time() - self.start
-
-    def stop(self):
-        """
-        Stop the timer to record a total time, if desired.
-        """
-        self.end = time.time()
 
     def write_json(self, out=sys.stdout):
+        pass
+
+    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):
         """
-        Write a json object with times to file
+        Arguments:
+            now: function that gives the seconds since e.g. epoch
         """
-        phases = [{"name": p, "seconds": s} for p, s in self.phases.items()]
+        self._now = now
-        times = {"phases": phases, "total": {"seconds": self.total}}
+        self._timers = OrderedDict()  # type: OrderedDict[str,Interval]
+
+        # _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):
+        """
+        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.
+        """
+        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()
+        """Write a human-readable summary of timings"""
-        out.write("Time:\n")
+        # Individual timers ordered by registration
-        for phase, t in self.phases.items():
+        formatted = [(p, pretty_seconds(self.duration(p))) for p in self.phases]
-            out.write("    %-15s%.4f\n" % (phase + ":", t))
+
-        out.write("Total: %.4f\n" % (now - self.start))
+        # 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))

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):