installer.py: show timers for binary install (#33305)

Print a message of the form
```
Fetch mm:ss.  Build: mm:ss.  Total: mm:ss
```
when installing from buildcache. 

Previously this only happened for source builds.

1 files changed, 57 insertions, 23 deletions

diff --git a/lib/spack/spack/installer.py b/lib/spack/spack/installer.py
index 4150302b28..7ec31f0267 100644
--- a/lib/spack/spack/installer.py
+++ b/lib/spack/spack/installer.py
@@ -262,6 +262,30 @@ def _hms(seconds):
     return " ".join(parts)
 
 
+def _log_prefix(pkg_name):
+    """Prefix of the form "[pid]: [pkg name]: ..." when printing a status update during
+    the build."""
+    pid = "{0}: ".format(os.getpid()) if tty.show_pid() else ""
+    return "{0}{1}:".format(pid, pkg_name)
+
+
+def _print_installed_pkg(message):
+    """
+    Output a message with a package icon.
+
+    Args:
+        message (str): message to be output
+    """
+    print(colorize("@*g{[+]} ") + spack.util.path.debug_padded_filter(message))
+
+
+def _print_timer(pre, pkg_id, fetch, build, total):
+    tty.msg(
+        "{0} Successfully installed {1}".format(pre, pkg_id),
+        "Fetch: {0}.  Build: {1}.  Total: {2}.".format(_hms(fetch), _hms(build), _hms(total)),
+    )
+
+
 def _install_from_cache(pkg, cache_only, explicit, unsigned=False):
     """
     Extract the package from binary cache
@@ -278,7 +302,10 @@ def _install_from_cache(pkg, cache_only, explicit, unsigned=False):
         bool: ``True`` if the package was extract from binary cache,
             ``False`` otherwise
     """
-    installed_from_cache = _try_install_from_binary_cache(pkg, explicit, unsigned=unsigned)
+    timer = Timer()
+    installed_from_cache = _try_install_from_binary_cache(
+        pkg, explicit, unsigned=unsigned, timer=timer
+    )
     pkg_id = package_id(pkg)
     if not installed_from_cache:
         pre = "No binary for {0} found".format(pkg_id)
@@ -287,23 +314,20 @@ def _install_from_cache(pkg, cache_only, explicit, unsigned=False):
 
         tty.msg("{0}: installing from source".format(pre))
         return False
-
+    timer.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,
+    )
     _print_installed_pkg(pkg.spec.prefix)
     spack.hooks.post_install(pkg.spec)
     return True
 
 
-def _print_installed_pkg(message):
-    """
-    Output a message with a package icon.
-
-    Args:
-        message (str): message to be output
-    """
-    print(colorize("@*g{[+]} ") + spack.util.path.debug_padded_filter(message))
-
-
 def _process_external_package(pkg, explicit):
     """
     Helper function to run post install hooks and register external packages.
@@ -345,7 +369,9 @@ def _process_external_package(pkg, explicit):
         spack.store.db.add(spec, None, explicit=explicit)
 
 
-def _process_binary_cache_tarball(pkg, binary_spec, explicit, unsigned, mirrors_for_spec=None):
+def _process_binary_cache_tarball(
+    pkg, binary_spec, explicit, unsigned, mirrors_for_spec=None, timer=None
+):
     """
     Process the binary cache tarball.
 
@@ -357,6 +383,7 @@ def _process_binary_cache_tarball(pkg, binary_spec, explicit, unsigned, mirrors_
             otherwise, ``False``
         mirrors_for_spec (list): Optional list of concrete specs and mirrors
         obtained by calling binary_distribution.get_mirrors_for_spec().
+        timer (Timer): timer to keep track of binary install phases.
 
     Return:
         bool: ``True`` if the package was extracted from binary cache,
@@ -365,6 +392,8 @@ def _process_binary_cache_tarball(pkg, binary_spec, explicit, unsigned, mirrors_
     download_result = binary_distribution.download_tarball(
         binary_spec, unsigned, mirrors_for_spec=mirrors_for_spec
     )
+    if timer:
+        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))
@@ -381,10 +410,12 @@ def _process_binary_cache_tarball(pkg, binary_spec, explicit, unsigned, mirrors_
 
     pkg.installed_from_binary_cache = True
     spack.store.db.add(pkg.spec, spack.store.layout, explicit=explicit)
+    if timer:
+        timer.phase("install")
     return True
 
 
-def _try_install_from_binary_cache(pkg, explicit, unsigned=False):
+def _try_install_from_binary_cache(pkg, explicit, unsigned=False, timer=None):
     """
     Try to extract the package from binary cache.
 
@@ -393,16 +424,20 @@ def _try_install_from_binary_cache(pkg, explicit, unsigned=False):
         explicit (bool): the package was explicitly requested by the user
         unsigned (bool): ``True`` if binary package signatures to be checked,
             otherwise, ``False``
+        timer (Timer):
     """
     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")
+
     if not matches:
         return False
 
     return _process_binary_cache_tarball(
-        pkg, pkg.spec, explicit, unsigned, mirrors_for_spec=matches
+        pkg, pkg.spec, explicit, unsigned, mirrors_for_spec=matches, timer=timer
     )
 
 
@@ -1841,8 +1876,7 @@ class BuildProcessInstaller(object):
         self.filter_fn = spack.util.path.padding_filter if padding else None
 
         # info/debug information
-        pid = "{0}: ".format(os.getpid()) if tty.show_pid() else ""
-        self.pre = "{0}{1}:".format(pid, pkg.name)
+        self.pre = _log_prefix(pkg.name)
         self.pkg_id = package_id(pkg)
 
     def run(self):
@@ -1885,12 +1919,12 @@ class BuildProcessInstaller(object):
             # Run post install hooks before build stage is removed.
             spack.hooks.post_install(self.pkg.spec)
 
-        build_time = self.timer.total - self.pkg._fetch_time
-        tty.msg(
-            "{0} Successfully installed {1}".format(self.pre, self.pkg_id),
-            "Fetch: {0}.  Build: {1}.  Total: {2}.".format(
-                _hms(self.pkg._fetch_time), _hms(build_time), _hms(self.timer.total)
-            ),
+        _print_timer(
+            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,
         )
         _print_installed_pkg(self.pkg.prefix)