Flat event based timer variation

Event based timer allows for easily starting and stopping timers without
wiping sub-timer data. It also requires less branching logic when
tracking time.

The json output is non-hierarchical in this version and hierarchy is
less rigidly enforced between starting and stopping.

lib/spack/spack/installer.py

@@ -90,7 +90,7 @@ def _write_timer_json(pkg, timer, cache):
     extra_attributes = {"name": pkg.name, "hash": pkg.spec.dag_hash(), "cache": cache}
     try:
         with open(pkg.times_log_path, "w") as timelog:
-            timer.write_json(timelog, depth=-1, extra_attributes=extra_attributes)
+            timer.write_json(timelog, extra_attributes=extra_attributes)
     except Exception as e:
         tty.debug(e)
         return
@@ -417,9 +417,9 @@ def _process_binary_cache_tarball(
 
     tty.msg("Extracting {0} from binary cache".format(package_id(pkg)))
 
-    with timer.measure("install") as t, spack.util.path.filter_padding():
+    with timer.measure("install"), spack.util.path.filter_padding():
         binary_distribution.extract_tarball(
-            pkg.spec, download_result, unsigned=unsigned, force=False, timer=t
+            pkg.spec, download_result, unsigned=unsigned, force=False, timer=timer
         )
 
         pkg.installed_from_binary_cache = True

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

@@ -125,7 +125,7 @@ def test_timer_write():
     assert "3.000s" in output[1]
 
     deserialized = json.loads(json_buffer.getvalue())
-    assert deserialized == {"phases": [{"name": "timer", "seconds": 1.0}], "seconds": 3.0}
+    assert deserialized == {"phases": [{"name": "timer", "seconds": 1.0}], "total": 3.0}
 
 
 def test_null_timer():

lib/spack/spack/util/timer.py

@@ -19,7 +19,11 @@
 
 import spack.util.spack_json as sjson
 
-Interval = collections.namedtuple("Interval", ("begin", "end"))
+TimerEvent = collections.namedtuple("TimerEvent", ("time", "running", "label"))
+TimeTracker = collections.namedtuple("TimeTracker", ("total", "start"))
+
+#: name for the global timer (used in start(), stop(), duration() without arguments)
+global_timer_name = "_global"
 
 
 class NullTimer:
@@ -66,30 +70,24 @@ def __init__(self, now=time.time):
             now: function that gives the seconds since e.g. epoch
         """
         self._now = now
-        self._timers: Dict[str, Timer] = collections.OrderedDict()
-        self._interval: Interval
+        self._timers: Dict[str, TimeTracker] = collections.OrderedDict()
+        self._timer_stack: list(str) = []
 
-        self._interval = Interval(self._now(), None)
+        self._events: list(TimerEvent) = []
+        # Push start event
+        self._events.append(TimerEvent(self._now(), True, global_timer_name))
 
-    def start(self, name=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._events.append(TimerEvent(self._now(), True, name))
 
-        if name:
-            if self._interval.end:
-                self.start()
-            self._timers[name] = Timer(self._now)
-        else:
-            # Reset all of the sub-timers when restarting the global timer
-            self._timers = {}
-            self._interval = Interval(self._now(), None)
-
-    def stop(self, name=None, when=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.
@@ -98,16 +96,9 @@ def stop(self, name=None, when=None):
             name (str): Optional name of the timer. When no name is passed, all
                 timers are stopped.
         """
-        if name in self._timers:
-            self._timers[name].stop(when=when)
-        else:
-            if self._interval.end:
-                return
-            self._interval = Interval(self._interval.begin, when or self._now())
-            for name in self._timers:
-                self._timers[name].stop(when=self._interval.end)
+        self._events.append(TimerEvent(self._now(), False, name))
 
-    def duration(self, name=None):
+    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
@@ -119,16 +110,13 @@ def duration(self, name=None):
         Returns:
             float: duration of timer.
         """
-        try:
-            if name:
-                interval = self._timers[name]._interval
-            else:
-                interval = self._interval
-        except KeyError:
+        self._flatten()
+        if name in self._timers:
+            if name in self._timer_stack:
+                return self._timers[name].total + (self._now() - self._timers[name].start)
+            return self._timers[name].total
+        else:
             return 0.0
-        # Take either the interval end, the global timer, or now.
-        end = interval.end or self._interval.end or self._now()
-        return end - interval.begin
 
     @contextmanager
     def measure(self, name):
@@ -138,49 +126,51 @@ def measure(self, name):
         Arguments:
             name (str): Name of the timer
         """
-        timer = Timer(self._now)
-        self._timers[name] = timer
-        yield timer
-        timer.stop()
-
-    def subtimer(self, name):
-        """
-        Get the Timer object for the named subtimer
-
-        Arguments:
-            name (str): Name of the timer
-        """
-        if name not in self._timers:
-            self._timers[name] = Timer(self._now)
-        return self._timers[name]
+        self.start(name)
+        yield self
+        self.stop(name)
 
     @property
     def phases(self):
         """Get all named timers (excluding the global/total timer)"""
-        return [k for k in self._timers.keys()]
-
-    def flatten(self, depth=-1, extra_attributes={}):
-        flat = {}
-        if self._timers and not depth == 0:
-            flat = {"seconds": self.duration(), "phases": []}
-            phases = flat["phases"]
-            for name, t in self._timers.items():
-                phase = {"name": name}
-                phase.update(t.flatten(depth=depth - 1))
-                phases.append(phase)
-        else:
-            flat = {"seconds": self.duration()}
-
-        if extra_attributes:
-            flat.update(extra_attributes)
-        return flat
-
-    def write_json(self, out=sys.stdout, depth=-1, extra_attributes={}):
+        self._flatten()
+        return [k for k in self._timers.keys() if not k == global_timer_name]
+
+    def _flatten(self):
+        for event in self._events:
+            if event.running:
+                if event.label not in self._timer_stack:
+                    self._timer_stack.append(event.label)
+                tracker = self._timers.get(event.label, TimeTracker(0.0, event.time))
+                self._timers[event.label] = TimeTracker(tracker.total, event.time)
+            else:  # if not event.running:
+                if event.label in self._timer_stack:
+                    index = self._timer_stack.index(event.label)
+                    for label in self._timer_stack[index:]:
+                        tracker = self._timers[label]
+                        self._timers[label] = TimeTracker(
+                            tracker.total + (event.time - tracker.start), None
+                        )
+                    self._timer_stack = self._timer_stack[: max(0, index)]
+        # clear events
+        self._events = []
+
+    def write_json(self, out=sys.stdout, extra_attributes={}):
         """Write a json object with times to file"""
-        out.write(sjson.dump(self.flatten(depth, extra_attributes)))
+        self._flatten()
+        data = {
+            "total": self._timers[global_timer_name].total,
+            "phases": [
+                {"name": phase, "seconds": self._timers[phase].total} for phase in self.phases
+            ],
+        }
+        if extra_attributes:
+            data.update(extra_attributes)
+        out.write(sjson.dump(data))
 
     def write_tty(self, out=sys.stdout):
         """Write a human-readable summary of timings (depth is 1)"""
+        self._flatten()
 
         times = [self.duration(p) for p in self.phases]