Troubleshooting a (very) slow pex build

[jake-normal]

I'm troubleshooting a PEX performance issue. The following build step is taking about 15 minutes in our Github Actions-based CI runner:

Building 34 requirements for requirements.pex from the 3rdparty/python/default.lock resolve: ...

My guess is that there is a dependency without a wheel matching our CI environment, but I'm having trouble figuring out 1) if that is the issue and 2) if so, which dependency it is. To start, I've been looking to produce more verbose output. (Nothing is emitted during the entire 15 minute build.) I tried PEX_VERBOSE=100 pants --level=debug --no-pantsd, but that didn't quite do it. @lilatomic pointed me at this option, but that didn't do it either.

I can't tell if the issue is within pants or pex. I tried grepping for Buildint .* requirements for .* in both repos, but didn't come up with anything promising.

Any suggestions? It would be nice if there was more output during that build process.

[jsirois]

I can't speak for Pants here, but I can for Pex. You should be able to determine which dependencies might be building from sdist by just inspecting your lock file. If you know the root requirements of that long build step, that could help narrow down things more quickly, but is not absolutely necessary. Can you provide a copy of your lock file and the interpreter version you think a Pex is being built for as well as the GitHub runner OS (Ubuntu 22.04 or is it something else)?

[jsirois]

@jake-normal its simply by inspection. For any given locked project, look at its artifacts:

1. only sdist - build needs to occur
2. various wheels, but none match the tags of the interpreter you're targeting - build needs to occur
3. otherwise: compatible wheel is selected for download.

As to your lock file experiments - you cannot edit the lockfile naively as I suspect you are. The lock is read only. IFF you specified --no-build on the pex3 lock create command line, then the resulting lock file would not only contain "allow_builds": false, but it would also contain 0 sdist artifacts since you disallowed them. If you also disallowed wheels, the lock generation would fail with:

Cannot both disallow builds and disallow wheels. Please allow one of these or both so that some distributions can be resolved.

To be more on point - your idea with 1 was great. But Pants gets in the way here. Unless things have changed there is likely no way to tell Pants to generate the lock with --no-build - it hides alot from you to make things "easy" here.

[jsirois]

Ok, @jake-normal I think I can stop the investigation right here:

:; time pex --python python3.11 --disable-cache --lock lock.json -r requirements.txt --layout packed -o requirements.pex

real    7m3.711s
user    5m26.257s
sys     0m29.178s

Where lock.json is the file you posted (but with the damn invalid JSON header Pants adds removed) and requirements.txt matches your reported Building 34 requirements for requirements.pex from the 3rdparty/python/default.lock resolve: ... line:
lock.json
requirements.txt

If this takes 7 minutes on my laptop, which has 64GB ram and 8 hyper-threaded cores then it taking 2x as long on a GitHub provided runner is totally expected, but you did not disclose what your CI environment. I realize I assumed it was GH actions.

Here are the assumptions I've used:

1. You don't use a beefed up runner in CI; its has less horsepower than my laptop.
2. You don't cache ~/.cache/pants/... in CI (I simulated this using --disable-cache).

[jsirois]

To explain the slowness I add a flag here which maybe bleeding edge Pants does, but I'm not sure:

:; time pex --python python3.11 --disable-cache --lock lock.json -r requirements.txt --layout packed -o requirements.pex --no-pre-install-wheels

real    3m45.332s
user    1m30.191s
sys     0m18.366s

That flag is --no-pre-install-wheels and was added recently by Pex. See:

• https://github.com/pex-tool/pex/releases/tag/v2.1.154
• https://github.com/pex-tool/pex/releases/tag/v2.1.155

It was specifically introduced to do with monster wheels - which you have when you wade into torch / nvidia land as your requirements.pex does:

# ~/support/pants/discussions-20832 via  v3.10.12
:; du -sh requirements.pex/
2.8G    requirements.pex/

# ~/support/pants/discussions-20832 via  v3.10.12
:; du -sb requirements.pex/.deps/* | sort -rn | head
731725872       requirements.pex/.deps/nvidia_cudnn_cu12-8.9.2.26-py3-none-manylinux1_x86_64.whl
670196704       requirements.pex/.deps/torch-2.1.1-cp311-cp311-manylinux1_x86_64.whl
410594774       requirements.pex/.deps/nvidia_cublas_cu12-12.1.3.1-py3-none-manylinux1_x86_64.whl
209797524       requirements.pex/.deps/nvidia_nccl_cu12-2.18.1-py3-none-manylinux1_x86_64.whl
195958278       requirements.pex/.deps/nvidia_cusparse_cu12-12.1.0.106-py3-none-manylinux1_x86_64.whl
124161928       requirements.pex/.deps/nvidia_cusolver_cu12-11.4.5.107-py3-none-manylinux1_x86_64.whl
121635161       requirements.pex/.deps/nvidia_cufft_cu12-11.0.2.54-py3-none-manylinux1_x86_64.whl
89234153        requirements.pex/.deps/triton-2.1.0-0-cp311-cp311-manylinux2014_x86_64.manylinux_2_17_x86_64.whl
56467784        requirements.pex/.deps/nvidia_curand_cu12-10.3.2.106-py3-none-manylinux1_x86_64.whl
43802727        requirements.pex/.deps/llvmlite-0.42.0-cp311-cp311-manylinux_2_17_x86_64.manylinux2014_x86_64.whl

Since the introduction of wheel support in Pex many years ago, wheels are downloaded and installed in an individual chroot directory which is then later assembled into a runtime PEX sys.path. That operation requires unzipping the wheels. The creation of the PEX file (or packed directory in this case) then needs to re-zip the required wheels. For things like torch / nvidia, the unzip-rezip time, even with native tools, takes roughly all the time you're seeing. The --no-pre-install-wheels switches Pex into a mode where it does zero processing of the downloaded wheels, and only lazily installs them when the PEX 1st boots. This completely cuts out the re-zipping time which is where the PEX build time savings comes. The cost is the 1st PEX boot is a bit slower since it needs to install wheels that are no-longer "pre-installed" as they are in a traditional PEX.

Note that you may get better results with this flag than I since my setup is weak on the network side compared to the network out on GitHub and with --no-pre-install-wheels the dominant time in creating the packed layout PEX is that spent downloading the wheels.

[jsirois]

Ok, bleeding edge indeed: #20670

@jake-normal my piece here is done unless you have further questions. It appears to be the short answer is you either need to setup caching of ~/.cache/pants/named_caches/pex_root (<- Do your own homework here, I have not used Pants in ~1 year and location may have changed) or else you need to hop on the Pants dev release train to Pick up @huonw's patch asap.

[jake-normal]

This is huge, thank you so much for such a detailed investigation. I just learned a lot from what you wrote here. Going to take a bit to digest it all but yeah, I think this will resolve my issue. Hugely appreciate it!

PS since you're reading, I love the scie ecosystem naming. Laughed out loud when "Ski Jump" clicked for me. (Big skier myself...)

[kaos]

Regarding:

I tried grepping for Buildint .* requirements for .* in both repos, but didn't come up with anything promising.

I think this is what you where grepping for, but the work you're digging for is likely in pip, which is invoked by pex which in turn is invoked by pants.

pants/src/python/pants/backend/python/util_rules/pex.py

Lines 781 to 821 in 0d35991

	async def _build_pex_description(
	request: PexRequest, req_strings: Sequence[str], resolve_to_lockfile: Mapping[str, str]
	) -> str:
	if request.description:
	return request.description
	if isinstance(request.requirements, EntireLockfile):
	lockfile = request.requirements.lockfile
	desc_suffix = f"from {lockfile.url}"
	else:
	if not req_strings:
	return f"Building {request.output_filename}"
	elif isinstance(request.requirements.from_superset, Pex):
	repo_pex = request.requirements.from_superset.name
	return softwrap(
	f"""
	Extracting {pluralize(len(req_strings), 'requirement')}
	to build {request.output_filename} from {repo_pex}:
	{', '.join(req_strings)}
	"""
	)
	elif isinstance(request.requirements.from_superset, Resolve):
	# At this point we know this is a valid user resolve, so we can assume
	# it's available in the dict. Nonetheless we use get() so that any weird error
	# here gives a bad message rather than an outright crash.
	lockfile_path = resolve_to_lockfile.get(request.requirements.from_superset.name, "")
	return softwrap(
	f"""
	Building {pluralize(len(req_strings), 'requirement')}
	for {request.output_filename} from the {lockfile_path} resolve:
	{', '.join(req_strings)}
	"""
	)
	else:
	desc_suffix = softwrap(
	f"""
	with {pluralize(len(req_strings), 'requirement')}:
	{', '.join(req_strings)}
	"""
	)
	return f"Building {request.output_filename} {desc_suffix}"

That said, John asks the more relevant questions to get you closer to an actual answer..