feat: measure time for different steps in bootstrapping and build-sequence

[shubhbapna]

fixes #408

I couldn't find a nice way to measure memory usage for child processes. even using cgroups won't be as straightforward. Anyways measuring time is probably a higher priority than memory so we can discuss how to do memory usage later

For measuring time, instead of wrapping each function call we want to measure individually, I decided it might be better to create a decorator which we can call for whichever function we want to measure. This will make it easy to store metrics in a single store and print it at the end as well. Plus, in the future if we want to measure more functions we simply have to add this decorator

[tiran]

The _extract_req_and_version_from_args involves a lot of hackery and black magic. Let's make it easier and more sustainable for us:

1. Change every function with a timeit() decorator to accept only keyword arguments, e.g. def download_source(*, ctx: context.WorkContext, req: Requirement, version: Version, download_url: str). The lonely * indicates keyword-only for remaining arguments.
2. Change the internal wrapper to def wrapper_timeit(*, ctx: context.WorkContext, req: Requirement, version: Version, **kwargs: typing.Any) -> typing.Any.

Now you have convenient access to the variables without hackery. It makes the timeit function less generic, but that's okay for our purpose. You can also store the timing information on the context instead of a global variable.

[tiran]

You are missing return type annotations.

[shubhbapna]

1. Change every function with a timeit() decorator to accept only keyword arguments, e.g. def download_source(*, ctx: context.WorkContext, req: Requirement, version: Version, download_url: str). The lonely * indicates keyword-only for remaining arguments.

Thats a breaking change for a lot of our APIs and everytime we want to measure a new function we will have to change its API to ensure that it is compatible with our metrics decorators. Plus we won't be able to measure functions like prepare_build_environment . Right now timeit functions allows to measure any function and prints a debug log immediately.

[tiran]

Thats a breaking change for a lot of our APIs and everytime we want to measure a new function we will have to change its API to ensure that it is compatible with our metrics decorators. Plus we won't be able to measure functions like prepare_build_environment . Right now timeit functions allows to measure any function and prints a debug log immediately.

keyword-only argument cause some breakage, but it's not as bad as you think. I would argue that they also improve code for the better. I have implemented keyword-only args for several functions in PR #459.

Do we need to measure any function? I don't think so. We want to measure how long build steps of a requirement are taking. The API functions all take a ctx and a req, most take a version, too. To handle prepare_build_environment, you can make the version argument optional:

def wrapper_timeit(*, ctx: context.WorkContext, req: Requirement, **kwargs: typing.Any) -> typing.Any:
    version = kwargs.get("version", kwargs.get("dist_version"))
    ...

Another approach is to use inspect.signature to create a Signature object for a callable, then bind the signature to *args and **kwargs:

>>> import inspect
>>> from fromager import build_environment
>>> from packaging.requirements import Requirement
>>> import pathlib

>>> sig = inspect.signature(build_environment.prepare_build_environment)
>>> args = ("ctx", Requirement("egg"), pathlib.Path("source"))
>>> kwargs = {}
>>> bound = sig.bind(*args, **kwargs)
>>> bound.apply_defaults()
>>> bound
<BoundArguments (ctx='ctx', req=<Requirement('egg')>, sdist_root_dir=PosixPath('source'))>
>>> bound.arguments
{'ctx': 'ctx', 'req': <Requirement('egg')>, 'sdist_root_dir': PosixPath('source')}

[shubhbapna]

That make sense I like it. What about the resolver functions? They don't take in version but return a version. Should I use the binding the signature approach and then check the return value of the function to extract the version?

[dhellmann]

How much granularity do we need for timing?

[shubhbapna]

How much granularity do we need for timing?

Since we are trying to time some heavy weight functions (almost all of them requiring some sort of IO), I think we can get away with not being as fine grained in measuring them. We might not gain much by optimizing these functions at the micro-second level anyways. So just a blanket measurement for each step might be enough for now?

[dhellmann]

How much granularity do we need for timing?

Since we are trying to time some heavy weight functions (almost all of them requiring some sort of IO), I think we can get away with not being as fine grained in measuring them. We might not gain much by optimizing these functions at the micro-second level anyways. So just a blanket measurement for each step might be enough for now?

So we would time how long it takes to resolve, download, and build?

Should we separate the time spent in plugins vs. the time spent in the core of fromager?

[shubhbapna]

So we would time how long it takes to resolve, download, and build?

And prepare as well

Should we separate the time spent in plugins vs. the time spent in the core of fromager?

I think we can just think of the plugin as some IO fromager is performing that we can't control much

[dhellmann]

Should we separate the time spent in plugins vs. the time spent in the core of fromager?

I think we can just think of the plugin as some IO fromager is performing that we can't control much

That makes sense.

[dhellmann]

I have one formatting suggestion that I think we should address now.

We may also find we want a machine-readable output file in the future. Let's do that later, though, when we have some experience using the log output so we can decide what format to use.

[tiran]

Which function needs this hack?

[shubhbapna]

any of the version resolvers like this one: https://github.com/python-wheel-build/fromager/blob/main/src/fromager/sources.py#L73

[rd4398]

LGTM!

[shubhbapna]

@tiran are anymore changes required for this PR?