adding save of build times on install (#24350)

Here we are adding an install_times.json into the spack install metadata folder.
We record a total, global time, along with the times for each phase. The type
of phase or install start / end is included (e.g., build or fail)

Signed-off-by: vsoch <vsoch@users.noreply.github.com>

Co-authored-by: vsoch <vsoch@users.noreply.github.com>

6 files changed, 123 insertions, 44 deletions

diff --git a/lib/spack/spack/installer.py b/lib/spack/spack/installer.py
index 4ee56db26d..fd6bc31d4b 100644
--- a/lib/spack/spack/installer.py
+++ b/lib/spack/spack/installer.py
@@ -56,7 +56,7 @@ from llnl.util.tty.color import colorize
 from llnl.util.tty.log import log_output
 from spack.util.environment import 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
@@ -1685,7 +1685,7 @@ def build_process(pkg, kwargs):
     unmodified_env = kwargs.get('unmodified_env', {})
     verbose = kwargs.get('verbose', False)
 
-    start_time = time.time()
+    timer = Timer()
     if not fake:
         if not skip_patch:
             pkg.do_patch()
@@ -1770,9 +1770,9 @@ def build_process(pkg, kwargs):
 
                             # Redirect stdout and stderr to daemon pipe
                             phase = getattr(pkg, phase_attr)
+                            timer.phase(phase_name)
 
                             # Catch any errors to report to logging
-
                             phase(pkg.spec, pkg.prefix)
                             spack.hooks.on_phase_success(pkg, phase_name, log_file)
 
@@ -1788,17 +1788,19 @@ def build_process(pkg, kwargs):
             combine_phase_logs(pkg.phase_log_files, pkg.log_path)
             log(pkg)
 
+        # Stop the timer and save results
+        timer.stop()
+        with open(pkg.times_log_path, 'w') as timelog:
+            timer.write_json(timelog)
+
         # Run post install hooks before build stage is removed.
         spack.hooks.post_install(pkg.spec)
 
-    # Stop the timer
-    pkg._total_time = time.time() - start_time
-    build_time = pkg._total_time - pkg._fetch_time
-
+    build_time = timer.total - pkg._fetch_time
     tty.msg('{0} Successfully installed {1}'.format(pre, pkg_id),
             'Fetch: {0}.  Build: {1}.  Total: {2}.'
             .format(_hms(pkg._fetch_time), _hms(build_time),
-                    _hms(pkg._total_time)))
+                    _hms(timer.total)))
     _print_installed_pkg(pkg.prefix)
 
     # Send final status that install is successful
diff --git a/lib/spack/spack/package.py b/lib/spack/spack/package.py
index 051f135667..7db7f76589 100644
--- a/lib/spack/spack/package.py
+++ b/lib/spack/spack/package.py
@@ -71,6 +71,9 @@ _spack_build_logfile = 'spack-build-out.txt'
 # Filename for the Spack build/install environment file.
 _spack_build_envfile = 'spack-build-env.txt'
 
+# Filename of json with total build and phase times (seconds)
+_spack_times_log = 'install_times.json'
+
 # Filename for the Spack configure args file.
 _spack_configure_argsfile = 'spack-configure-args.txt'
 
@@ -699,7 +702,6 @@ class PackageBase(six.with_metaclass(PackageMeta, PackageViewMixin, object)):
 
         # Set up timing variables
         self._fetch_time = 0.0
-        self._total_time = 0.0
 
         if self.is_extension:
             spack.repo.get(self.extendee_spec)._check_extendable()
@@ -1093,6 +1095,11 @@ class PackageBase(six.with_metaclass(PackageMeta, PackageViewMixin, object)):
         return os.path.join(self.stage.path, _spack_configure_argsfile)
 
     @property
+    def times_log_path(self):
+        """Return the times log json file."""
+        return os.path.join(self.metadata_dir, _spack_times_log)
+
+    @property
     def install_configure_args_path(self):
         """Return the configure args file path on successful installation."""
         return os.path.join(self.metadata_dir, _spack_configure_argsfile)
diff --git a/lib/spack/spack/solver/asp.py b/lib/spack/spack/solver/asp.py
index 5bfbf1a6a0..94cc35d8de 100644
--- a/lib/spack/spack/solver/asp.py
+++ b/lib/spack/spack/solver/asp.py
@@ -10,7 +10,6 @@ import itertools
 import os
 import pprint
 import sys
-import time
 import types
 import warnings
 from six import string_types
@@ -43,7 +42,7 @@ import spack.repo
 import spack.bootstrap
 import spack.variant
 import spack.version
-
+import spack.util.timer
 
 if sys.version_info >= (3, 3):
     from collections.abc import Sequence  # novm
@@ -51,27 +50,6 @@ else:
     from collections import Sequence
 
 
-class Timer(object):
-    """Simple timer for timing phases of a solve"""
-    def __init__(self):
-        self.start = time.time()
-        self.last = self.start
-        self.phases = {}
-
-    def phase(self, name):
-        last = self.last
-        now = time.time()
-        self.phases[name] = now - last
-        self.last = now
-
-    def write(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))
-
-
 def issequence(obj):
     if isinstance(obj, string_types):
         return False
@@ -331,7 +309,7 @@ class PyclingoDriver(object):
             self, solver_setup, specs, dump=None, nmodels=0,
             timers=False, stats=False, tests=False
     ):
-        timer = Timer()
+        timer = spack.util.timer.Timer()
 
         # Initialize the control object for the solver
         self.control = clingo.Control()
@@ -428,7 +406,7 @@ class PyclingoDriver(object):
                 result.cores.append(core_symbols)
 
         if timers:
-            timer.write()
+            timer.write_tty()
             print()
         if stats:
             print("Statistics:")
diff --git a/lib/spack/spack/test/cmd/install.py b/lib/spack/spack/test/cmd/install.py
index 4808ea2b9d..328323b1af 100644
--- a/lib/spack/spack/test/cmd/install.py
+++ b/lib/spack/spack/test/cmd/install.py
@@ -201,26 +201,28 @@ def test_install_overwrite(
 
     install('libdwarf')
 
+    # Ignore manifest and install times
     manifest = os.path.join(spec.prefix, spack.store.layout.metadata_dir,
                             spack.store.layout.manifest_file_name)
+    ignores = [manifest, spec.package.times_log_path]
 
     assert os.path.exists(spec.prefix)
-    expected_md5 = fs.hash_directory(spec.prefix, ignore=[manifest])
+    expected_md5 = fs.hash_directory(spec.prefix, ignore=ignores)
 
     # Modify the first installation to be sure the content is not the same
     # as the one after we reinstalled
     with open(os.path.join(spec.prefix, 'only_in_old'), 'w') as f:
         f.write('This content is here to differentiate installations.')
 
-    bad_md5 = fs.hash_directory(spec.prefix, ignore=[manifest])
+    bad_md5 = fs.hash_directory(spec.prefix, ignore=ignores)
 
     assert bad_md5 != expected_md5
 
     install('--overwrite', '-y', 'libdwarf')
 
     assert os.path.exists(spec.prefix)
-    assert fs.hash_directory(spec.prefix, ignore=[manifest]) == expected_md5
-    assert fs.hash_directory(spec.prefix, ignore=[manifest]) != bad_md5
+    assert fs.hash_directory(spec.prefix, ignore=ignores) == expected_md5
+    assert fs.hash_directory(spec.prefix, ignore=ignores) != bad_md5
 
 
 def test_install_overwrite_not_installed(
@@ -254,16 +256,19 @@ def test_install_overwrite_multiple(
                                spack.store.layout.metadata_dir,
                                spack.store.layout.manifest_file_name)
 
+    ld_ignores = [ld_manifest, libdwarf.package.times_log_path]
+
     assert os.path.exists(libdwarf.prefix)
     expected_libdwarf_md5 = fs.hash_directory(libdwarf.prefix,
-                                              ignore=[ld_manifest])
+                                              ignore=ld_ignores)
 
     cm_manifest = os.path.join(cmake.prefix,
                                spack.store.layout.metadata_dir,
                                spack.store.layout.manifest_file_name)
 
+    cm_ignores = [cm_manifest, cmake.package.times_log_path]
     assert os.path.exists(cmake.prefix)
-    expected_cmake_md5 = fs.hash_directory(cmake.prefix, ignore=[cm_manifest])
+    expected_cmake_md5 = fs.hash_directory(cmake.prefix, ignore=cm_ignores)
 
     # Modify the first installation to be sure the content is not the same
     # as the one after we reinstalled
@@ -272,8 +277,8 @@ def test_install_overwrite_multiple(
     with open(os.path.join(cmake.prefix, 'only_in_old'), 'w') as f:
         f.write('This content is here to differentiate installations.')
 
-    bad_libdwarf_md5 = fs.hash_directory(libdwarf.prefix, ignore=[ld_manifest])
-    bad_cmake_md5 = fs.hash_directory(cmake.prefix, ignore=[cm_manifest])
+    bad_libdwarf_md5 = fs.hash_directory(libdwarf.prefix, ignore=ld_ignores)
+    bad_cmake_md5 = fs.hash_directory(cmake.prefix, ignore=cm_ignores)
 
     assert bad_libdwarf_md5 != expected_libdwarf_md5
     assert bad_cmake_md5 != expected_cmake_md5
@@ -282,8 +287,8 @@ def test_install_overwrite_multiple(
     assert os.path.exists(libdwarf.prefix)
     assert os.path.exists(cmake.prefix)
 
-    ld_hash = fs.hash_directory(libdwarf.prefix, ignore=[ld_manifest])
-    cm_hash = fs.hash_directory(cmake.prefix, ignore=[cm_manifest])
+    ld_hash = fs.hash_directory(libdwarf.prefix, ignore=ld_ignores)
+    cm_hash = fs.hash_directory(cmake.prefix, ignore=cm_ignores)
     assert ld_hash == expected_libdwarf_md5
     assert cm_hash == expected_cmake_md5
     assert ld_hash != bad_libdwarf_md5
diff --git a/lib/spack/spack/test/install.py b/lib/spack/spack/test/install.py
index 77810ff0e3..6a533bb8b1 100644
--- a/lib/spack/spack/test/install.py
+++ b/lib/spack/spack/test/install.py
@@ -15,6 +15,7 @@ import spack.patch
 import spack.repo
 import spack.store
 from spack.spec import Spec
+import spack.util.spack_json as sjson
 from spack.package import (_spack_build_envfile, _spack_build_logfile,
                            _spack_configure_argsfile)
 
@@ -161,6 +162,32 @@ def test_install_dependency_symlinks_pkg(
     assert os.path.isdir(dependency_dir)
 
 
+def test_install_times(
+        install_mockery, mock_fetch, mutable_mock_repo):
+    """Test install times added."""
+    spec = Spec('dev-build-test-install-phases')
+    spec.concretize()
+    pkg = spec.package
+    pkg.do_install()
+
+    # Ensure dependency directory exists after the installation.
+    install_times = os.path.join(pkg.prefix, ".spack", 'install_times.json')
+    assert os.path.isfile(install_times)
+
+    # Ensure the phases are included
+    with open(install_times, 'r') as timefile:
+        times = sjson.load(timefile.read())
+
+    # 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
+
+
 def test_flatten_deps(
         install_mockery, mock_fetch, mutable_mock_repo):
     """Explicitly test the flattening code for coverage purposes."""
diff --git a/lib/spack/spack/util/timer.py b/lib/spack/spack/util/timer.py
new file mode 100644
index 0000000000..077b81222f
--- /dev/null
+++ b/lib/spack/spack/util/timer.py
@@ -0,0 +1,60 @@
+# Copyright 2013-2021 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)
+
+"""Debug signal handler: prints a stack trace and enters interpreter.
+
+``register_interrupt_handler()`` enables a ctrl-C handler that prints
+a stack trace and drops the user into an interpreter.
+
+"""
+import spack.util.spack_json as sjson
+import time
+import sys
+
+
+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
+
+    @property
+    def total(self):
+        """Return the total time
+        """
+        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):
+        """
+        Write a json object with times to file
+        """
+        phases = [{"name": p, "seconds": s} for p, s in self.phases.items()]
+        times = {"phases": phases, "total": {"seconds": self.total}}
+        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))