Long running "Scheduling: Building N requirement for ..."

[TalAmuyal]

I’m trying to find the source of the slowness I'm having in some frequent cases by reading the output of pants test ::.

Specifically, I get the following output:

131.75s Scheduling:  Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
130.75s Scheduling:  Building 18 requirements for requirements.pex from the pants.lock resolve: [reducted]

I also see:

91.27s  Resolve transitive targets
124.93s Resolve transitive targets
160.03s Resolve transitive targets

Pants version: 2.16.0rc7.
Repo languages: Python.
Test files: ~1,500 (find . -type f -name 'test_*.py' | grep -v venv | wc -l).
Dependencies: ~330 (counted entries on the lockfile).
Machine: AWS' c6i.12xlarge (48 cores, 96 GiB of RAM) with EBS set to max IOPS and throughput.

I see that the EBS is hard at work (has 1-minutes long spikes of 100% utilization).

[benjyw]

Have you debugged on the machine? Looked at top, swap performance etc? Have you tried running on an entirely different machine class (different hardware family etc) to rule out anything specific to this arch?

[benjyw]

Some interesting options to play with:

https://www.pantsbuild.org/docs/reference-global#process_execution_local_parallelism

https://www.pantsbuild.org/docs/reference-global#process_total_child_memory_usage

https://www.pantsbuild.org/docs/reference-global#process_per_child_memory_usage

What is happening on the system? Is swap thrashing, for example?

[TalAmuyal]

Thanks, I've also noted that the line Starting: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest is printed twice in a single run, as well as its completion.

Do you think it means Pants runs more jobs than it ought to?

Here are all of the lines in that run that contain Building 1 requirement for requirements.pex from the pants.lock resolve: pytest: (sorted chronologically, but there were many other logs in between)

[2023-07-13T07:20:41.049Z] 07:20:29.39 [INFO] Starting: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:33.233Z]   78.18s	Remote cache lookup for: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:43.856Z] 07:21:42.26 [INFO] Starting: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:45.759Z]   74.70s	Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:45.761Z]   108.31s	Remote cache lookup for: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:49.982Z] 07:21:49.96 [INFO] Completed: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest
[2023-07-13T07:21:50.884Z] 07:21:50.83 [INFO] Completed: Building 1 requirement for requirements.pex from the pants.lock resolve: pytest

[benjyw]

I'm not sure why that appears to be happening twice, but my best bet is that these are non-identical processes that happen to have identical short descriptions (not all process input params affect that description)

[TalAmuyal]

Oh, that makes sense...
Could be 2 different versions of Python? (because we do test with both 3.9 and 3.10)

[benjyw]

Definitely could be

[benjyw]

That doesn't explain why they're so slow though. Just to try, see what happens when you run for just one Python version.