From 8e249c03de44f474cc9efe9380f4fbb15121b317 Mon Sep 17 00:00:00 2001 From: Vanessasaurus <814322+vsoch@users.noreply.github.com> Date: Tue, 22 Jun 2021 03:01:15 -0600 Subject: 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 Co-authored-by: vsoch --- lib/spack/spack/installer.py | 18 ++++++----- lib/spack/spack/package.py | 9 +++++- lib/spack/spack/solver/asp.py | 28 ++--------------- lib/spack/spack/test/cmd/install.py | 25 +++++++++------- lib/spack/spack/test/install.py | 27 +++++++++++++++++ lib/spack/spack/util/timer.py | 60 +++++++++++++++++++++++++++++++++++++ 6 files changed, 123 insertions(+), 44 deletions(-) create mode 100644 lib/spack/spack/util/timer.py (limited to 'lib') 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() @@ -1092,6 +1094,11 @@ class PackageBase(six.with_metaclass(PackageMeta, PackageViewMixin, object)): """Return the configure args file path associated with staging.""" 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.""" 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)) -- cgit v1.2.3-70-g09d2