CI Timing Statistics

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
@@ -1813,10 +1814,11 @@ def _tar_strip_component(tar: tarfile.TarFile, prefix: str):
                 m.linkname = m.linkname[result.end() :]
 
 
-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)
@@ -1896,7 +1898,9 @@ def extract_tarball(spec, download_result, unsigned=False, force=False):
 
     os.remove(tarfile_path)
     os.remove(specfile_path)
+    timer.stop("extract")
 
+    timer.start("relocate")
     try:
         relocate_package(spec)
     except Exception as e:
@@ -1917,6 +1921,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 _ensure_common_prefix(tar: tarfile.TarFile) -> str:

lib/spack/spack/cmd/ci.py

@@ -19,6 +19,7 @@
 import spack.hash_types as ht
 import spack.mirror
 import spack.util.gpg as gpg_util
+import spack.util.timer as timer
 import spack.util.url as url_util
 import spack.util.web as web_util
 
@@ -253,6 +254,8 @@ def ci_rebuild(args):
     check a single spec against the remote mirror, and rebuild it from source if the mirror does
     not contain the hash
     """
+    rebuild_timer = timer.Timer()
+
     env = spack.cmd.require_active_env(cmd_name="ci rebuild")
 
     # Make sure the environment is "gitlab-enabled", or else there's nothing
@@ -736,6 +739,14 @@ def ci_rebuild(args):
 
         print(reproduce_msg)
 
+    rebuild_timer.stop()
+    try:
+        with open("install_timers.json", "w") as timelog:
+            extra_attributes = {"name": "ci-rebuild"}
+            rebuild_timer.write_json(timelog, extra_attributes=extra_attributes)
+    except Exception as e:
+        tty.debug(str(e))
+
     # Tie job success/failure to the success/failure of building the spec
     return install_exit_code
 

lib/spack/spack/cmd/install.py

@@ -66,6 +66,7 @@ def install_kwargs_from_args(args):
         "unsigned": args.unsigned,
         "install_deps": ("dependencies" in args.things_to_install),
         "install_package": ("package" in args.things_to_install),
+        "timer_summary_file": args.timer_summary_file,
     }
 
 
@@ -87,6 +88,7 @@ def setup_parser(subparser):
         default=None,
         help="phase to stop after when installing (default None)",
     )
+    subparser.add_argument("--timer-summary-file", type=str, default=None, help=argparse.SUPPRESS)
     arguments.add_common_arguments(subparser, ["jobs"])
     subparser.add_argument(
         "--overwrite",

lib/spack/spack/installer.py

@@ -90,6 +90,16 @@
 STATUS_REMOVED = "removed"
 
 
+def _write_timer_json(pkg, timer, cache):
+    extra_attributes = {"name": pkg.name, "cache": cache, "hash": pkg.spec.dag_hash()}
+    try:
+        with open(pkg.times_log_path, "w") as timelog:
+            timer.write_json(timelog, extra_attributes=extra_attributes)
+    except Exception as e:
+        tty.debug(str(e))
+        return
+
+
 class InstallAction:
     #: Don't perform an install
     NONE = 0
@@ -399,6 +409,8 @@ def _install_from_cache(
         return False
     t.stop()
     tty.debug("Successfully extracted {0} from binary cache".format(pkg_id))
+
+    _write_timer_json(pkg, t, True)
     _print_timer(pre=_log_prefix(pkg.name), pkg_id=pkg_id, timer=t)
     _print_installed_pkg(pkg.spec.prefix)
     spack.hooks.post_install(pkg.spec, explicit)
@@ -481,7 +493,7 @@ def _process_binary_cache_tarball(
 
     with timer.measure("install"), 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=timer
         )
 
         pkg.installed_from_binary_cache = True
@@ -2009,11 +2021,14 @@ def install(self) -> None:
         # enabled, so that the output does not get cluttered.
         term_status = TermStatusLine(enabled=sys.stdout.isatty() and not tty.is_debug())
 
+        t = timer.Timer()
+
         while self.build_pq:
             task = self._pop_task()
             if task is None:
                 continue
 
+            t.start("task")
             spack.hooks.on_install_start(task.request.pkg.spec)
             install_args = task.request.install_args
             keep_prefix = install_args.get("keep_prefix")
@@ -2059,6 +2074,7 @@ def install(self) -> None:
             # some package likely depends on it.
             if not task.explicit:
                 if _handle_external_and_upstream(pkg, False):
+                    t.stop("task")
                     term_status.clear()
                     self._flag_installed(pkg, task.dependents)
                     continue
@@ -2078,6 +2094,7 @@ def install(self) -> None:
                 if self.fail_fast:
                     raise InstallError(fail_fast_err, pkg=pkg)
 
+                t.stop("task")
                 continue
 
             # Attempt to get a write lock.  If we can't get the lock then
@@ -2086,18 +2103,20 @@ def install(self) -> None:
             # other process may be hung).
             install_status.set_term_title("Acquiring lock for {0}".format(pkg.name))
             term_status.add(pkg_id)
+            t.start("acquire_lock")
             ltype, lock = self._ensure_locked("write", pkg)
             if lock is None:
                 # Attempt to get a read lock instead.  If this fails then
                 # another process has a write lock so must be (un)installing
                 # the spec (or that process is hung).
                 ltype, lock = self._ensure_locked("read", pkg)
-
+            t.stop("acquire_lock")
             # Requeue the spec if we cannot get at least a read lock so we
             # can check the status presumably established by another process
             # -- failed, installed, or uninstalled -- on the next pass.
             if lock is None:
                 self._requeue_task(task, install_status)
+                t.stop("task")
                 continue
 
             term_status.clear()
@@ -2116,7 +2135,9 @@ def install(self) -> None:
                 # Downgrade to a read lock to preclude other processes from
                 # uninstalling the package until we're done installing its
                 # dependents.
+                t.start("acquire_lock")
                 ltype, lock = self._ensure_locked("read", pkg)
+                t.stop("acquire_lock")
                 if lock is not None:
                     self._update_installed(task)
                     path = spack.util.path.debug_padded_filter(pkg.prefix)
@@ -2137,6 +2158,7 @@ def install(self) -> None:
                     # or uninstalled -- on the next pass.
                     self.installed.remove(pkg_id)
                     self._requeue_task(task, install_status)
+                t.stop("task")
                 continue
 
             # Having a read lock on an uninstalled pkg may mean another
@@ -2150,10 +2172,12 @@ def install(self) -> None:
             if ltype == "read":
                 lock.release_read()
                 self._requeue_task(task, install_status)
+                t.stop("task")
                 continue
 
             # Proceed with the installation since we have an exclusive write
             # lock on the package.
+            t.start("install")
             install_status.set_term_title("Installing {0}".format(pkg.name))
             try:
                 action = self._install_action(task)
@@ -2173,6 +2197,7 @@ def install(self) -> None:
                 keep_prefix = keep_prefix or (stop_before_phase is None and last_phase is None)
 
             except KeyboardInterrupt as exc:
+                t.stop("install")
                 # The build has been terminated with a Ctrl-C so terminate
                 # regardless of the number of remaining specs.
                 err = "Failed to install {0} due to {1}: {2}"
@@ -2181,6 +2206,7 @@ def install(self) -> None:
                 raise
 
             except binary_distribution.NoChecksumException as exc:
+                t.stop("install")
                 if task.cache_only:
                     raise
 
@@ -2191,9 +2217,11 @@ def install(self) -> None:
                 # this overrides a full method, which is ugly.
                 task.use_cache = False  # type: ignore[misc]
                 self._requeue_task(task, install_status)
+                t.stop("task")
                 continue
 
             except (Exception, SystemExit) as exc:
+                t.stop("install")
                 self._update_failed(task, True, exc)
                 spack.hooks.on_install_failure(task.request.pkg.spec)
 
@@ -2223,6 +2251,7 @@ def install(self) -> None:
                     failed_explicits.append((pkg, pkg_id, str(exc)))
 
             finally:
+                t.stop("install")
                 # Remove the install prefix if anything went wrong during
                 # install.
                 if not keep_prefix and not action == InstallAction.OVERWRITE:
@@ -2236,6 +2265,7 @@ def install(self) -> None:
             # Perform basic task cleanup for the installed spec to
             # include downgrading the write to a read lock
             self._cleanup_task(pkg)
+            t.stop("task")
 
         # Cleanup, which includes releasing all of the read locks
         self._cleanup_all_tasks()
@@ -2248,6 +2278,18 @@ def install(self) -> None:
             if request.install_args.get("install_package") and request.pkg_id not in self.installed
         ]
 
+        t.stop()
+
+        if self.build_requests:
+            timer_summary_file = self.build_requests[0].install_args.get("timer_summary_file")
+            if timer_summary_file:
+                phases = ["{}: {}.".format(p.capitalize(), _hms(t.duration(p))) for p in t.phases]
+                phases.append("Total: {}".format(_hms(t.duration())))
+                tty.msg("Installer time summary", "  ".join(phases))
+
+                with open(timer_summary_file, "w") as fd:
+                    t.write_json(out=fd, extra_attributes={"name": "install_all"})
+
         if failed_explicits or missing:
             for _, pkg_id, err in failed_explicits:
                 tty.error("{0}: {1}".format(pkg_id, err))
@@ -2372,8 +2414,7 @@ def run(self) -> bool:
 
             # Stop the timer and save results
             self.timer.stop()
-            with open(self.pkg.times_log_path, "w") as timelog:
-                self.timer.write_json(timelog)
+            _write_timer_json(self.pkg, self.timer, False)
 
         print_install_test_log(self.pkg)
         _print_timer(pre=self.pre, pkg_id=self.pkg_id, timer=self.timer)

lib/spack/spack/test/util/timer.py

@@ -126,8 +126,8 @@ def test_timer_write():
 
     deserialized = json.loads(json_buffer.getvalue())
     assert deserialized == {
-        "phases": [{"name": "timer", "seconds": 1.0}],
-        "total": {"seconds": 3.0},
+        "phases": [{"name": "timer", "path": "timer", "seconds": 1.0, "count": 1}],
+        "total": 3.0,
     }