zhangyiss/spack
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

adding save of build times on install (#24350)

Browse Source 
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>
This commit is contained in:
Vanessasaurus 2021-06-22 03:01:15 -06:00 committed by GitHub
parent 726537e01b
commit 8e249c03de
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 153 additions and 44 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

18
lib/spack/spack/installer.py
View File

@ -56,7 +56,7 @@
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

9
lib/spack/spack/package.py
View File

@ -71,6 +71,9 @@
# 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 @@ def __init__(self, spec):
# 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 @@ def configure_args_path(self):
"""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."""

28
lib/spack/spack/solver/asp.py
View File

@ -10,7 +10,6 @@
import os
import pprint
import sys
import time
import types
import warnings
from six import string_types
@ -43,7 +42,7 @@
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 @@
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 @@ def solve(
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 @@ def stringify(x):
result.cores.append(core_symbols)
if timers:
timer.write()
timer.write_tty()
print()
if stats:
print("Statistics:")

25
lib/spack/spack/test/cmd/install.py
View File

@ -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

27
lib/spack/spack/test/install.py
View File

@ -15,6 +15,7 @@
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."""

60
lib/spack/spack/util/timer.py Normal file
View File

@ -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))

30
var/spack/repos/builtin.mock/packages/dev-build-test-install-phases/package.py Normal file
View File

@ -0,0 +1,30 @@
# 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)
from time import sleep
class DevBuildTestInstallPhases(Package):
homepage = "example.com"
url = "fake.com"
version('0.0.0', sha256='0123456789abcdefgh')
phases = ['one', 'two', 'three', 'install']
def one(self, spec, prefix):
sleep(1)
print("One locomoco")
def two(self, spec, prefix):
sleep(2)
print("Two locomoco")
def three(self, spec, prefix):
sleep(3)
print("Three locomoco")
def install(self, spec, prefix):
print("install")