diff --git a/src/ci/stage-build.py b/src/ci/stage-build.py index c373edfcf46a2..662c9e36694c6 100644 --- a/src/ci/stage-build.py +++ b/src/ci/stage-build.py @@ -15,10 +15,9 @@ import time import traceback import urllib.request -from collections import OrderedDict from io import StringIO from pathlib import Path -from typing import Callable, Dict, Iterable, List, Optional, Union +from typing import Callable, Dict, Iterable, Iterator, List, Optional, Tuple, Union PGO_HOST = os.environ["PGO_HOST"] @@ -204,48 +203,105 @@ def supports_bolt(self) -> bool: return False +def get_timestamp() -> float: + return time.time() + + +Duration = float +TimerSection = Union[Duration, "Timer"] + + +def iterate_sections(section: TimerSection, name: str, level: int = 0) -> Iterator[Tuple[int, str, Duration]]: + """ + Hierarchically iterate the sections of a timer, in a depth-first order. + """ + if isinstance(section, Duration): + yield (level, name, section) + elif isinstance(section, Timer): + yield (level, name, section.total_duration()) + for (child_name, child_section) in section.sections: + yield from iterate_sections(child_section, child_name, level=level + 1) + else: + assert False + + class Timer: - def __init__(self): - # We want this dictionary to be ordered by insertion. - # We use `OrderedDict` for compatibility with older Python versions. - self.stages = OrderedDict() + def __init__(self, parent_names: Tuple[str, ...] = ()): + self.sections: List[Tuple[str, TimerSection]] = [] + self.section_active = False + self.parent_names = parent_names @contextlib.contextmanager - def stage(self, name: str): - assert name not in self.stages + def section(self, name: str) -> "Timer": + assert not self.section_active + self.section_active = True - start = time.time() + start = get_timestamp() exc = None + + child_timer = Timer(parent_names=self.parent_names + (name, )) + full_name = " > ".join(child_timer.parent_names) try: - LOGGER.info(f"Stage `{name}` starts") - yield + LOGGER.info(f"Section `{full_name}` starts") + yield child_timer except BaseException as exception: exc = exception raise finally: - end = time.time() + end = get_timestamp() duration = end - start - self.stages[name] = duration + + if child_timer.has_children(): + self.sections.append((name, child_timer)) + else: + self.sections.append((name, duration)) if exc is None: - LOGGER.info(f"Stage `{name}` ended: OK ({duration:.2f}s)") + LOGGER.info(f"Section `{full_name}` ended: OK ({duration:.2f}s)") + else: + LOGGER.info(f"Section `{full_name}` ended: FAIL ({duration:.2f}s)") + self.section_active = False + + def total_duration(self) -> Duration: + duration = 0 + for (_, section) in self.sections: + if isinstance(section, Duration): + duration += section else: - LOGGER.info(f"Stage `{name}` ended: FAIL ({duration:.2f}s)") + duration += section.total_duration() + return duration + + def has_children(self) -> bool: + return len(self.sections) > 0 def print_stats(self): - total_duration = sum(self.stages.values()) + rows = [] + for (child_name, child_section) in self.sections: + for (level, name, duration) in iterate_sections(child_section, child_name, level=0): + label = f"{' ' * level}{name}:" + rows.append((label, duration)) - # 57 is the width of the whole table - divider = "-" * 57 + # Empty row + rows.append(("", "")) + + total_duration_label = "Total duration:" + total_duration = self.total_duration() + rows.append((total_duration_label, humantime(total_duration))) + + space_after_label = 2 + max_label_length = max(16, max(len(label) for (label, _) in rows)) + space_after_label + + table_width = max_label_length + 23 + divider = "-" * table_width with StringIO() as output: print(divider, file=output) - for (name, duration) in self.stages.items(): - pct = (duration / total_duration) * 100 - name_str = f"{name}:" - print(f"{name_str:<34} {duration:>12.2f}s ({pct:>5.2f}%)", file=output) - - total_duration_label = "Total duration:" - print(f"{total_duration_label:<34} {total_duration:>12.2f}s", file=output) + for (label, duration) in rows: + if isinstance(duration, Duration): + pct = (duration / total_duration) * 100 + value = f"{duration:>12.2f}s ({pct:>5.2f}%)" + else: + value = f"{duration:>{len(total_duration_label) + 7}}" + print(f"{label:<{max_label_length}} {value}", file=output) print(divider, file=output, end="") LOGGER.info(f"Timer results\n{output.getvalue()}") @@ -265,6 +321,21 @@ def change_cwd(dir: Path): os.chdir(cwd) +def humantime(time_s: float) -> str: + hours = time_s // 3600 + time_s = time_s % 3600 + minutes = time_s // 60 + seconds = time_s % 60 + + result = "" + if hours > 0: + result += f"{int(hours)}h " + if minutes > 0: + result += f"{int(minutes)}m " + result += f"{round(seconds)}s" + return result + + def move_path(src: Path, dst: Path): LOGGER.info(f"Moving `{src}` to `{dst}`") shutil.move(src, dst) @@ -585,15 +656,16 @@ def execute_build_pipeline(timer: Timer, pipeline: Pipeline, final_build_args: L pipeline.build_rustc_perf() # Stage 1: Build rustc + PGO instrumented LLVM - with timer.stage("Build rustc (LLVM PGO)"): - build_rustc(pipeline, args=[ - "--llvm-profile-generate" - ], env=dict( - LLVM_PROFILE_DIR=str(pipeline.llvm_profile_dir_root() / "prof-%p") - )) + with timer.section("Stage 1 (LLVM PGO)") as stage1: + with stage1.section("Build rustc and LLVM"): + build_rustc(pipeline, args=[ + "--llvm-profile-generate" + ], env=dict( + LLVM_PROFILE_DIR=str(pipeline.llvm_profile_dir_root() / "prof-%p") + )) - with timer.stage("Gather profiles (LLVM PGO)"): - gather_llvm_profiles(pipeline) + with stage1.section("Gather profiles"): + gather_llvm_profiles(pipeline) clear_llvm_files(pipeline) final_build_args += [ @@ -602,14 +674,15 @@ def execute_build_pipeline(timer: Timer, pipeline: Pipeline, final_build_args: L ] # Stage 2: Build PGO instrumented rustc + LLVM - with timer.stage("Build rustc (rustc PGO)"): - build_rustc(pipeline, args=[ - "--rust-profile-generate", - pipeline.rustc_profile_dir_root() - ]) + with timer.section("Stage 2 (rustc PGO)") as stage2: + with stage2.section("Build rustc and LLVM"): + build_rustc(pipeline, args=[ + "--rust-profile-generate", + pipeline.rustc_profile_dir_root() + ]) - with timer.stage("Gather profiles (rustc PGO)"): - gather_rustc_profiles(pipeline) + with stage2.section("Gather profiles"): + gather_rustc_profiles(pipeline) clear_llvm_files(pipeline) final_build_args += [ @@ -619,14 +692,15 @@ def execute_build_pipeline(timer: Timer, pipeline: Pipeline, final_build_args: L # Stage 3: Build rustc + BOLT instrumented LLVM if pipeline.supports_bolt(): - with timer.stage("Build rustc (LLVM BOLT)"): - build_rustc(pipeline, args=[ - "--llvm-profile-use", - pipeline.llvm_profile_merged_file(), - "--llvm-bolt-profile-generate", - ]) - with timer.stage("Gather profiles (LLVM BOLT)"): - gather_llvm_bolt_profiles(pipeline) + with timer.section("Stage 3 (LLVM BOLT)") as stage3: + with stage3.section("Build rustc and LLVM"): + build_rustc(pipeline, args=[ + "--llvm-profile-use", + pipeline.llvm_profile_merged_file(), + "--llvm-bolt-profile-generate", + ]) + with stage3.section("Gather profiles"): + gather_llvm_bolt_profiles(pipeline) clear_llvm_files(pipeline) final_build_args += [ @@ -635,7 +709,7 @@ def execute_build_pipeline(timer: Timer, pipeline: Pipeline, final_build_args: L ] # Stage 4: Build PGO optimized rustc + PGO/BOLT optimized LLVM - with timer.stage("Final build"): + with timer.section("Stage 4 (final build)"): cmd(final_build_args)