Timer IO and recording cached install subtimers

lib/spack/spack/binary_distribution.py

@@ -49,6 +49,7 @@
 import spack.util.gpg
 import spack.util.spack_json as sjson
 import spack.util.spack_yaml as syaml
+import spack.util.timer as timer
 import spack.util.url as url_util
 import spack.util.web as web_util
 from spack.caches import misc_cache_location
@@ -1796,10 +1797,11 @@ def _extract_inner_tarball(spec, filename, extract_to, unsigned, remote_checksum
     return tarfile_path
 
 
-def extract_tarball(spec, download_result, unsigned=False, force=False):
+def extract_tarball(spec, download_result, unsigned=False, force=False, timer=timer.NULL_TIMER):
     """
     extract binary tarball for given package into install area
     """
+    timer.start("extract")
     if os.path.exists(spec.prefix):
         if force:
             shutil.rmtree(spec.prefix)
@@ -1890,7 +1892,9 @@ def extract_tarball(spec, download_result, unsigned=False, force=False):
         raise e
     os.remove(tarfile_path)
     os.remove(specfile_path)
+    timer.stop("extract")
 
+    timer.start("relocate")
     try:
         relocate_package(spec)
     except Exception as e:
@@ -1909,6 +1913,7 @@ def extract_tarball(spec, download_result, unsigned=False, force=False):
         if os.path.exists(filename):
             os.remove(filename)
         _delete_staged_downloads(download_result)
+    timer.stop("relocate")
 
 
 def install_root_node(spec, unsigned=False, force=False, sha256=None):

lib/spack/spack/installer.py

@@ -59,7 +59,6 @@
 import spack.util.timer as timer
 from spack.util.environment import EnvironmentModifications, dump_environment
 from spack.util.executable import which
-import spack.util.spack_json as sjson
 
 #: 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
@@ -86,6 +85,12 @@
 #: queue invariants).
 STATUS_REMOVED = "removed"
 
+
+def _write_timer_json(pkg, timer):
+    with open(pkg.times_log_path, "w") as timelog:
+        timer.write_json(timelog, depth=-1)
+
+
 class InstallAction(object):
     #: Don't perform an install
     NONE = 0
@@ -408,9 +413,9 @@ def _process_binary_cache_tarball(
 
     tty.msg("Extracting {0} from binary cache".format(package_id(pkg)))
 
-    with timer.measure("install"), spack.util.path.filter_padding():
+    with timer.measure("install") as t, spack.util.path.filter_padding():
         binary_distribution.extract_tarball(
-            pkg.spec, download_result, unsigned=unsigned, force=False
+            pkg.spec, download_result, unsigned=unsigned, force=False, timer=t
         )
 
         pkg.installed_from_binary_cache = True

lib/spack/spack/util/timer.py

@@ -21,26 +21,26 @@
 
 Interval = collections.namedtuple("Interval", ("begin", "end"))
 
-#: 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):
+    def start(self, name=None):
         pass
 
-    def stop(self, name=global_timer_name):
+    def stop(self, name=None):
         pass
 
-    def duration(self, name=global_timer_name):
+    def duration(self, name=None):
         return 0.0
 
     @contextmanager
     def measure(self, name):
-        yield
+        yield NullTimer()
+
+    def subtimer(self, name):
+        return NullTimer()
 
     @property
     def phases(self):
@@ -66,22 +66,30 @@ def __init__(self, now=time.time):
             now: function that gives the seconds since e.g. epoch
         """
         self._now = now
-        self._timers: Dict[str, Interval] = collections.OrderedDict()
+        self._timers: Dict[str, Timer] = collections.OrderedDict()
+        self._interval: Interval
 
-        # _global is the overal timer since the instance was created
-        self._timers[global_timer_name] = Interval(self._now(), end=None)
+        self._interval = Interval(self._now(), None)
 
-    def start(self, name=global_timer_name):
+    def start(self, name=None):
         """
         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):
+        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):
         """
         Stop a named timer, or all timers when no name is given. Stopping a
         timer that has not started has no effect.
@@ -90,12 +98,16 @@ def stop(self, name=global_timer_name):
             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):
+        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)
+
+    def duration(self, name=None):
         """
         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
@@ -108,11 +120,14 @@ def duration(self, name=global_timer_name):
             float: duration of timer.
         """
         try:
-            interval = self._timers[name]
+            if name:
+                interval = self._timers[name]._interval
+            else:
+                interval = self._interval
         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()
+        end = interval.end or self._interval.end or self._now()
         return end - interval.begin
 
     @contextmanager
@@ -123,23 +138,47 @@ def measure(self, name):
         Arguments:
             name (str): Name of the timer
         """
-        begin = self._now()
-        yield
-        self._timers[name] = Interval(begin, self._now())
+        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 not name in self._timers:
+            self._timers[name] = Timer(self._now)
+        return self._timers[name]
 
     @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):
+        return [k for k in self._timers.keys()]
+
+    def serialize(self, depth=-1):
+        serialized = {}
+        if self._timers and not depth == 0:
+            serialized = {"seconds": self.duration(), "phases": []}
+            phases = serialized["phases"]
+            for name, t in self._timers.items():
+                phase = {"name": name}
+                phase.update(t.serialize(depth=depth - 1))
+                phases.append(phase)
+        else:
+            serialized = {"seconds": self.duration()}
+
+        return serialized
+
+    def write_json(self, out=sys.stdout, depth=-1):
         """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))
+        out.write(sjson.dump(self.serialize(depth)))
 
     def write_tty(self, out=sys.stdout):
-        """Write a human-readable summary of timings"""
+        """Write a human-readable summary of timings (depth is 1)"""
 
         times = [self.duration(p) for p in self.phases]