Dependency calculation performance poor even with cache warm cache

[jriddy]

Describe the bug
When running ./pants dependees $something (or ./pants dependencies :: which is broadly equivalent in terms of the work Pants needs to do), I get poor performance on my repo. This would be more bearable, except that it seems to persist even with a warm cache. Just killing pantsd or running with --no-pantsd is enough to make it take ~40s to get a full dep calculation, even if all inferences should be cached recently.

My repo has ~4500 python files, with another ~3000 non-inferrable targets. It's big and has a complex import graph, but not crazy.

What's weirder is that this problem gets demonstrably worse with --no-python-infer-imports on. So it seems to be more a problem with how Pants is dealing with my repo than with an issue with dependency inference per se.

This is probably "fine" for CI but we have more and more devs interacting with Pants (which is a good thing!) but they're hitting this wall and wondering what's up, with good reason. I can write a pretty naive import scanner in Python that outperforms Pants with a cache, so something must be off.

Slack link: https://pantsbuild.slack.com/archives/C046T6T9U/p1683234968526959

Pants version
2.15.0

OS
Linux. Unsure if it's affecting MacOS users.

Additional info
I've attached some py-spy recordings of this. These were run with --no-pantsd.

With inference on:

pants-dependencies-inference.speedscope.zip

With no-python-infer-imports:

pants-dependencies.speedscope.zip

[jriddy]

Anecdotally looking at the speedscope data, it looks like the 6 worker threads are used extremely sparsely

[jriddy]

Tried this with 2.16.0rc1 and I'm getting similar results.

For the record, with a cold cache it took nearly 5 min, which is just absurd. Stuff is just taking far longer to run than makes any sense at all. There's clearly something wrong here.

I've tried messing with various toggles, and the main thing that has a difference is [python-infer].content_only, setting it to "never" seems to drastically improve the performance with a warm cache.

With a cold cache or --no-local-cache, perf is still abysmal for me. (4-5 min)

I feel like there's something up with the scheduler here, I don't know how else this could perform so poorly.

[stuhood]

Will take a look at this today.

Anecdotally looking at the speedscope data, it looks like the 6 worker threads are used extremely sparsely

That's not too surprising, due to the GIL. Only one thread can actually be running Python @rule code at a time... and py-spy will only show you Python frames, and no Rust frames.

For the record, with a cold cache it took nearly 5 min, which is just absurd. Stuff is just taking far longer to run than makes any sense at all. There's clearly something wrong here.

The only difference between cold cache and warm cache is the number of processes that run: in the cold cache case, ~4500 Python interpreters will need to be spawned... at least until #18854 lands.

Also: how often are users seeing pantsd restart? Keeping it up for long periods is really important, so should check .pants.d/pants.log to ensure that users aren't seeing frequent restarts.

I've tried messing with various toggles, and the main thing that has a difference is [python-infer].content_only, setting it to "never" seems to drastically improve the performance with a warm cache.

That sounds like #16122, which is still open.

Are you still using a single large BUILD file, or have you switched away? As a quick datapoint, can you try deleting your existing BUILD file in a branch, and then running ./pants tailor and seeing how long warm ./pants dependencies :: takes on the result?

[jriddy]

That's not too surprising, due to the GIL. Only one thread can actually be running Python @rule code at a time... and py-spy will only show you Python frames, and no Rust frames.

That makes sense. I don't know why I thought py-spy might give rust frames, but that doesn't make sense now. Is there a way to spy on the rust frames, or do I need to use a debug build?

The only difference between cold cache and warm cache is the number of processes that run: in the cold cache case, ~4500 Python interpreters will need to be spawned... at least until #18854 lands.

Spawning the interpreters is a lot but I don't think it accounts for the wait time. Naively running the inferences script in a bash for loop yields better results. I've got to imagine that setting up the process execution dir is part of the issue here? #18854 would help but the lower limit there can't be much better than the warm-cache, no-pantsd case, which is still suprisingly slow.

That sounds like #16122, which is still open.

Are you still using a single large BUILD file, or have you switched away? As a quick datapoint, can you try deleting your existing BUILD file in a branch, and then running ./pants tailor and seeing how long warm ./pants dependencies :: takes on the result?

We've switched away from single BUILD file quite a while ago. I don't have a good way of comparing the single BUILD file case any more.

[jriddy]

I realize now I was complaining about this about a year ago with #16122. I think this is just some of the challenges with our massive repo.

But it is a major pain point for us. Even with a 2 GiB pantsd memory limit, it restarts a lot, so we hit this all the time in CI and devs who try to use Pants hit it frequently. The reason I tried with --no-python-infer-imports was to see if it would be theoretically possible to store dependencies in BUILD files in the repo and avoid these issues. But I was shocked when that took even longer. So it just seems to me that there's some fundamental slowness in just reading metadata into Pants that I don't really understand. Maybe because it's really easy to gloss over the underlying complexity of the system and think how you would do it in a degenerate case, whereas Pants handles these things in a very generic set of cases.

[jriddy]

FWIW pants --no-pantsd dependencies :: takes a similar amount of time on the Pants repo on my machine with a warm cache (~30 s), so perhaps we have an expectation misalignment here.

[thejcannon]

But I was shocked when that took even longer.

Turns out I was half-right, and half-wrong we do short-circuit but we also do some other weirdness. The latter might explain the slowerness

[stuhood]

There are a few egregious spots in the profiles which can be fixed fairly easily for, hopefully, 10-20% gain.

But if I'm being honest: we probably should have ported a lot of these types like Target and FieldSet to Rust a long time ago, before they grew to 390 and 80 lines, respectively. The Target constructor is 8% for a few of those threads.

[jriddy]

I'm comparing on the Pants repo itself and i'm just getting the impression that Pants is totally reliant on pantsd for responsive performance on a large-ish repo.

Even pants --no-pantsd lint :: takes ~30s with a fully loaded cache (on the Pants repo itself).

This probably hasn't come up because most of the intended use cases don't cause Pantsd to self-kill because of the memory limit. But I'm hitting that constantly, and I can't really justify bumping the memory limit too much more because we need that for running code.

[jriddy]

The Target constructor is 8% for a few of those threads.

But wasn't most of the time in the speedscopes I linked above spent in Rust?

If anything perhaps the amount of Python being memoized contributes to memory bloat, which makes Pantsd restarts more common.

[stuhood]

The Target constructor is 8% for a few of those threads.

But wasn't most of the time in the speedscopes I linked above spent in Rust?

Doubtful. I've never seen the Rust code take more than about 30% of the runtime (using macOS Instruments, similar to Linux perf). And the key thing to remember is, again: the GIL. Very rarely is Rust code holding locks that prevent other Rust code from running (all of the locks that we directly control have been highly optimized), but when some Python code is slow, it prevents any other Python code from running.

EDIT: With one exception: Rule Graph solving is very slow in the pants repo, because we have all rule sets enabled at once. See #18905 on that topic.

If anything perhaps the amount of Python being memoized contributes to memory bloat, which makes Pantsd restarts more common.

This is definitely possible. We could almost certainly be memoizing fewer things, but right now disabling memoization for a @rule involves changing how it is called. #18905 would help with that somewhat, but we could also experiment with adding flags to enable/disable memoization of individual @rules.