diff --git a/src/fromager/build_environment.py b/src/fromager/build_environment.py index c8b890b3..57706e50 100644 --- a/src/fromager/build_environment.py +++ b/src/fromager/build_environment.py @@ -13,11 +13,7 @@ from packaging.requirements import Requirement -from . import ( - dependencies, - external_commands, - resolver, -) +from . import dependencies, external_commands, metrics, resolver from .requirements_file import RequirementType if typing.TYPE_CHECKING: @@ -198,6 +194,7 @@ def _createenv(self) -> None: logger.info("installed dependencies into build environment in %s", self.path) +@metrics.timeit(description="prepare build environment") def prepare_build_environment( *, ctx: context.WorkContext, diff --git a/src/fromager/commands/bootstrap.py b/src/fromager/commands/bootstrap.py index 067a8e71..0cf7ff34 100644 --- a/src/fromager/commands/bootstrap.py +++ b/src/fromager/commands/bootstrap.py @@ -9,6 +9,7 @@ clickext, context, dependency_graph, + metrics, progress, requirements_file, resolver, @@ -162,6 +163,8 @@ def bootstrap( f"Could not produce a pip compatible constraints file. Please review {constraints_filename} for more details" ) + metrics.summarize("Bootstrapping") + def write_constraints_file( graph: dependency_graph.DependencyGraph, diff --git a/src/fromager/commands/build.py b/src/fromager/commands/build.py index ecb617ce..08700975 100644 --- a/src/fromager/commands/build.py +++ b/src/fromager/commands/build.py @@ -22,6 +22,7 @@ clickext, context, hooks, + metrics, overrides, progress, server, @@ -191,6 +192,7 @@ def build_sequence( ) ) print(wheel_filename) + metrics.summarize("Building") _summary(wkctx, entries) diff --git a/src/fromager/metrics.py b/src/fromager/metrics.py new file mode 100644 index 00000000..016d95c8 --- /dev/null +++ b/src/fromager/metrics.py @@ -0,0 +1,74 @@ +import functools +import logging +import time +import typing +from collections import defaultdict + +from packaging.requirements import Requirement +from packaging.version import Version + +_time_store: dict[str, dict[str, float]] = defaultdict(dict[str, float]) +_time_description_store: dict[str, str] = {} + + +def timeit(description: str): + def timeit_decorator(func: typing.Callable) -> typing.Callable: + _time_description_store[func.__name__] = description + + @functools.wraps(func) + def wrapper_timeit( + *, req: Requirement | None = None, **kwargs: typing.Any + ) -> typing.Any: + start = time.perf_counter() + ret = func(req=req, **kwargs) + end = time.perf_counter() + # get the logger for the module from which this function was called + logger = logging.getLogger(func.__module__) + version = ( + kwargs.get("version") + or kwargs.get("dist_version") + or kwargs.get("resolved_version") + ) + if not version: + version = _extract_version_from_return(ret) + + runtime = end - start + + if req: + logger.debug(f"{req.name}: took {runtime:.2f} seconds to {description}") + else: + logger.debug(f"took {runtime:.2f} seconds to {description}") + + if req and version: + # store total time spent calling that function for a particular version of that req + _time_store[f"{req.name}=={version}"][func.__name__] = ( + _time_store[f"{req.name}=={version}"].get(func.__name__, 0) + + runtime + ) + + return ret + + return wrapper_timeit + + return timeit_decorator + + +def summarize(prefix: str) -> None: + logger = logging.getLogger(__name__) + for req in sorted(_time_store.keys()): + total_time = sum(_time_store[req].values()) + log = f"{prefix} {req} took {total_time:.2f} seconds total" + for fn_name, time_taken in _time_store[req].items(): + log += f", {time_taken:.2f} seconds to {_time_description_store[fn_name]}" + logger.info(log) + + +def _extract_version_from_return(ret: typing.Any) -> Version | None: + try: + for r in ret: + if isinstance(r, Version): + return r + except Exception: + if isinstance(ret, Version): + return ret + return None diff --git a/src/fromager/sources.py b/src/fromager/sources.py index 3698b987..fea1beac 100644 --- a/src/fromager/sources.py +++ b/src/fromager/sources.py @@ -18,6 +18,7 @@ from . import ( dependencies, external_commands, + metrics, overrides, pyproject, resolver, @@ -45,6 +46,7 @@ def get_source_type(ctx: context.WorkContext, req: Requirement) -> str: return source_type +@metrics.timeit(description="download source") def download_source( *, ctx: context.WorkContext, @@ -70,6 +72,7 @@ def download_source( return source_path +@metrics.timeit(description="resolve source") def resolve_source( *, ctx: context.WorkContext, @@ -204,17 +207,6 @@ def download_url( return outfile -def _sdist_root_name(source_filename: pathlib.Path) -> str: - base_name = pathlib.Path(source_filename).name - if base_name.endswith(".tar.gz"): - ext_to_strip = ".tar.gz" - elif base_name.endswith(".zip"): - ext_to_strip = ".zip" - else: - raise ValueError(f"Do not know how to work with {source_filename}") - return base_name[: -len(ext_to_strip)] - - def _takes_arg(f: typing.Callable, arg_name: str) -> bool: sig = inspect.signature(f) return arg_name in sig.parameters @@ -354,6 +346,7 @@ def read_build_meta(unpack_dir: pathlib.Path) -> dict: return json.load(f) +@metrics.timeit(description="prepare source") def prepare_source( *, ctx: context.WorkContext, @@ -434,6 +427,7 @@ def prepare_new_source( vendor_rust.vendor_rust(req, source_root_dir) +@metrics.timeit(description="build sdist") def build_sdist( *, ctx: context.WorkContext, diff --git a/src/fromager/wheels.py b/src/fromager/wheels.py index d2803d26..1bf2b6ab 100644 --- a/src/fromager/wheels.py +++ b/src/fromager/wheels.py @@ -10,7 +10,6 @@ import textwrap import typing import zipfile -from datetime import datetime from urllib.parse import urlparse import elfdeps @@ -19,12 +18,7 @@ from packaging.utils import canonicalize_name, parse_wheel_filename from packaging.version import Version -from . import ( - external_commands, - overrides, - resolver, - sources, -) +from . import external_commands, metrics, overrides, resolver, sources if typing.TYPE_CHECKING: from . import build_environment, context @@ -115,6 +109,7 @@ def default_add_extra_metadata_to_wheels( raise NotImplementedError +@metrics.timeit(description="add extra metadata to wheels") def add_extra_metadata_to_wheels( *, ctx: context.WorkContext, @@ -235,6 +230,7 @@ def add_extra_metadata_to_wheels( raise FileNotFoundError("Could not locate new wheels file") +@metrics.timeit(description="build wheels") def build_wheel( *, ctx: context.WorkContext, @@ -270,8 +266,6 @@ def build_wheel( ) extra_environ["DIST_EXTRA_CONFIG"] = str(dist_extra_cfg) - # Start the timer - start = datetime.now().replace(microsecond=0) overrides.find_and_invoke( req.name, "build_wheel", @@ -285,7 +279,6 @@ def build_wheel( version=version, ) # End the timer - end = datetime.now().replace(microsecond=0) wheels = list(ctx.wheels_build.glob("*.whl")) if len(wheels) != 1: raise FileNotFoundError("Could not locate built wheels") @@ -298,7 +291,6 @@ def build_wheel( sdist_root_dir=sdist_root_dir, wheel_file=wheels[0], ) - logger.info(f"{req.name}: built wheel '{wheel}' in {end - start}") return wheel @@ -380,6 +372,7 @@ def get_wheel_server_urls(ctx: context.WorkContext, req: Requirement) -> list[st return servers +@metrics.timeit(description="resolve wheel") def resolve_prebuilt_wheel( *, ctx: context.WorkContext,