New resolver: Build automated testing to check for acceptable performance

[brainwane]

Our new dependency resolver may make pip a bit slower than it used to be.

Therefore I believe we need to pull together some extremely rough speed tests and decide what level of speed is acceptable, then build some automated testing to check whether we are meeting those marks.

I just ran a few local tests (on a not-particularly-souped-up laptop) to do a side-by-side comparison:

$ time pip install --upgrade pip
Requirement already up-to-date: pip in [path]/python3.7/site-packages (20.2)

real	0m0.867s
user	0m0.680s
sys	0m0.076s

$ time pip install --upgrade pip --use-feature=2020-resolver
Requirement already satisfied: pip in [path]/python3.7/site-packages (20.2)

real	0m1.243s
user	0m0.897s
sys	0m0.060s

Or, in 2 different virtualenvs:

$ time pip install --upgrade chardet
Requirement already up-to-date: chardet in [path].virtualenvs/form990/lib/python3.7/site-packages (3.0.4)

real	0m0.616s
user	0m0.412s
sys	0m0.053s

$ time pip install --upgrade chardet --use-feature=2020-resolver
Requirement already satisfied: chardet in [path].virtualenvs/ical3/lib/python3.7/site-packages (3.0.4)

real	0m1.137s
user	0m0.404s
sys	0m0.053s

These numbers will add up with more complicated processes, dealing with lots of packages at a time.

Related to #6536 and #988.

---

Edit by @brainwane: As of November 2020 we have defined some speed goals and the new resolver has acceptable performance, so I've switched this issue to be about building automated testing to ensure that we continue to meet our goals in the future.

---

Edit by @uranusjr: Some explanation for people landing here. The new resolver is generally slower because it checks the dependency between packages more rigorously, and tries to find alternative solutions when dependency specifications do not meet. The legacy resolver, on the other hand, just picks the one specification it likes best without verifying, which of course is faster but also irresponsible.

Feel free to post examples here if the new resolver runs slowly for your project. We are very interested in reviewing all of them to identify possible improvements. When doing so, however, please make sure to also include the pip install output, not just your requirements.txt. The output is important for us to identify what pip is spending time for, and suggest workarounds if possible.

[stefanv]

For SkyPortal, we use pip to verify that all required Python packages are present. This takes about 2 seconds on the old pip, and 20 with the resolver enabled.

Will it be possible to revert to the old behavior in the future (i.e., switch off the resolver?).

pip install -r requirements.txt  1.16s user 0.20s system 54% cpu 2.492 total
pip install -r requirements.txt --use-feature=2020-resolver  16.67s user 0.26s system 84% cpu 20.057 total

Perhaps it would be possible to do a quick "first check" to see if all packages just happen to satisfy requirements, and if they don't to only then enable the resolver?

Our requirements.txt:

supervisor>=4
numpy>=1.12.1
scipy>=0.16.0
pandas>=0.17.0
dask>=0.15.0
joblib>=0.11
seaborn>=0.10.0
bokeh==0.12.9
pytest-randomly>=2.1.1
factory-boy==2.11.1
astropy>=4.0
aplpy>=1.1.1
reproject>=0.7
avro-python3==1.8.2
fastavro==0.21.7
tqdm>=4.23.2
matplotlib>=3
astroquery>=0.4
sqlalchemy-utils
apispec>=3.2.0
marshmallow>=3.4.0
marshmallow-sqlalchemy>=0.21.0
marshmallow-enum>=1.5.1
Pillow>=6
sncosmo>=2.1.0
tdtax>=0.1.1
healpix-alchemy>=0.1.2
jsonschema
jsonpath_ng>=1.5.1
pytest-rerunfailures>=9.0
astroplan>=0.6

[uranusjr]

I believe both resolvers already do a scan to check whether packages are already satisfied. The problem is the new resolver is slower to determine what are needed to satisfy the dependencies, since the checks are much more involved than the naive legacy logic.

In your particular use case, if you always list all requirements (instead of relying on pip to discover transient dependencies), you can use the --no-deps option to skip the dependency discovery part entirely, which would make the operation lightning fast in both implementations. (OK, that’s an exaggeration, nothing in pip is lightning fast. But it’ll be a lot faster.)

[sbidoul]

I reported a similar performance issue in #8675.

[minusf]

i have simplifed the test case a bit and measure only the pip running time. download times are not included as prefer binary is used. requirements:

Django==3.0.9
django-auth-ldap
django-cors-headers
django-debug-toolbar
django-extensions
django-uwsgi
django-haystack==3.0b2
hyperkitty==1.3.3
mailman
mailman-hyperkitty
postorius
psycopg2-binary==2.8.5
supervisor
uWSGI==2.0.19.1
whoosh

Please find the 2 log files in this gist: https://gist.github.com/minusf/bd0edfeaf5975980917f2d0792677b52

old: sh -x tvenv.sh 2>&1  19.82s user 6.60s system 92% cpu 28.517 total

new: sh -x tvenv.sh 2>&1  59.04s user 7.78s system 95% cpu 1:10.22 total

[stefanv]

@uranusjr I don't see the --no-deps option listed in the help, even when enabling the new resolver. Is this expected?

[pradyunsg]

@stefanv It's the 4th option in pip install --help's "Install Options" section in basically any reasonably new pip (say >= 20.0).

$ pip install --help

Usage:
[snipped for brevity]
Description:
[snipped for brevity]
Install Options:
  --no-clean                  Don't clean up build directories.
  -r, --requirement <file>    Install from the given requirements file. This option can be used multiple times.
  -c, --constraint <file>     Constrain versions using the given constraints file. This option can be used multiple times.
  --no-deps                   Don't install package dependencies.
[snipped for brevity]

[stefanv]

Thanks @pradyunsg! But I see now that this would cause problems too, since it would require us to list all dependencies in our requirements.txt file.

[tlandschoff-scale]

We also tried to enable the new resolver (and actually fixed a number of dependency conflicts by using it, so that's good!)

But the performance is abysmal in the usual developer case where after switching git branches I'll just run pip install -r requirements.txt so ensure everything is at the expected version.

Compare the runtime of the new resolver:

$ /usr/bin/time pip install --use-feature=2020-resolver -r requirements.txt
77.60user 0.75system 3:38.77elapsed 35%CPU (0avgtext+0avgdata 249740maxresident)k
19160inputs+18912outputs (0major+87724minor)pagefaults 0swaps

with the runtime of the old resolver:

$ /usr/bin/time pip install -r requirements.txt
1.75user 0.12system 0:01.87elapsed 100%CPU (0avgtext+0avgdata 41828maxresident)k
40inputs+8outputs (0major+25404minor)pagefaults 0swaps

Granted, this is for 211 installed packages. Many of those are internal and rely on other internal and PyPI packages, so the dependency graph is far from trivial. But a slowdown by a factor of ~100 appears a bit too much.

Interestingly, the new resolver takes 1-2 seconds to check each already installed package and even checks many packages multiple times:

$ cat pip-output.txt | sort | uniq -c | sort -n | tail -n 20
      4 Requirement already satisfied: cython==0.23.4 in ./.../site-packages (from -r etc/requirements/common.txt (line 14)) (0.23.4)
      4 Requirement already satisfied: dynapp==2.7.3 in ./.../site-packages (from -r etc/requirements/common.txt (line 16)) (2.7.3)
      4 Requirement already satisfied: requests==2.21.0+scale1 in ./.../site-packages (from -r etc/requirements/common.txt (line 48)) (2.21.0+scale1)
      4 Requirement already satisfied: scale.toolbelt==0.1.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 69)) (0.1.0)
      5 Requirement already satisfied: enum34 in ./.../site-packages (from cryptography==1.3.4+scale1->-r etc/requirements/common.txt (line 13)) (1.1.6)
      5 Requirement already satisfied: lxml==3.8.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 25)) (3.8.0)
      5 Requirement already satisfied: python-dateutil==2.7.5 in ./.../site-packages (from -r etc/requirements/loco2-common.txt (line 5)) (2.7.5)
      5 Requirement already satisfied: pytz in ./.../site-packages (from spyne==2.9.3+scale5->-r etc/requirements/common.txt (line 94)) (2018.7)
      5 Requirement already satisfied: scale.util.pubsub==1.3.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 78)) (1.3.0)
      6 Requirement already satisfied: cryptography==1.3.4+scale1 in ./.../site-packages (from -r etc/requirements/common.txt (line 13)) (1.3.4+scale1)
      6 Requirement already satisfied: scale.program-manager==1.1.4 in ./.../site-packages (from -r etc/requirements/common.txt (line 64)) (1.1.4)
      6 Requirement already satisfied: scale.util.event==2.0.2 in ./.../site-packages (from -r etc/requirements/common.txt (line 70)) (2.0.2)
      6 Requirement already satisfied: scale.util.progress-monitor==1.3.2 in ./.../site-packages (from -r etc/requirements/common.txt (line 77)) (1.3.2)
      7 Requirement already satisfied: scale.util.threadutil==1.2.1 in ./.../site-packages (from -r etc/requirements/common.txt (line 80)) (1.2.1)
      7 Requirement already satisfied: setuptools>=11.3 in ./.../site-packages (from cryptography==1.3.4+scale1->-r etc/requirements/common.txt (line 13)) (44.1.1)
      8 Requirement already satisfied: pytest==3.7.4 in ./.../site-packages (from -r etc/requirements/common-test.txt (line 18)) (3.7.4)
      8 Requirement already satisfied: scale.util.exception==1.2.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 71)) (1.2.0)
      9 Requirement already satisfied: scale.util.osutils==1.2.3 in ./.../site-packages (from -r etc/requirements/common.txt (line 76)) (1.2.3)
     10 Requirement already satisfied: scale.util.i18n==2.0.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 74)) (2.0.0)
     15 Requirement already satisfied: six==1.12.0 in ./.../site-packages (from -r etc/requirements/common.txt (line 93)) (1.12.0)

[adamchainz]

I benchmarked on a medium-sized Django project and found the slowdown was from 1.6 seconds to 41 seconds (again when all packages are already installed locally at the correct versions):

$ wc -l requirements.txt
     171 requirements.txt
$ time python -m pip install --no-deps -r requirements.txt
Requirement already satisfied: ...
python -m pip install --no-deps -r requirements.txt  0.65s user 0.10s system 92% cpu 0.809 total
$ time python -m pip install -r requirements.txt
Requirement already satisfied: ...
python -m pip install -r requirements.txt  1.52s user 0.12s system 99% cpu 1.646 total
$ time python -m pip install --use-feature=2020-resolver -r requirements.txt
Requirement already satisfied: ...
python -m pip install --use-feature=2020-resolver -r   37.05s user 0.69s system 91% cpu 41.121 total

I profiled the project with py-spy:

$ sudo py-spy record --threads --idle --rate 1000 --format speedscope --output pip-install.speedscope /path/to/project/venv/bin/pip install -- --use-feature=2020-resolver -r requirements.txt

This resulted in a speedscope file - see attached. It can be used at https://www.speedscope.app/ to investigate the profile.

pip-install-redacted.speedscope.zip

Most of the time - 93,547 out of 99,225 frames - was unsurprisingly under Resolver.resolve():

Tracing it down I noticed there are a lot of invocations of parse_links. From this I surmised that the new resolver is hitting parsing HTML a lot.

Indeed when I turned off my internet connection and tried again, using --no-deps or the old resolver, pip install can succeed entirely with the local set of information. But the new resolver makes requests that fail almost immediately - trying to get the PyPI page for a requirement after already printing that it has been satisfied:

$ time python -m pip install --use-feature=2020-resolver -r requirements.txt
Requirement already satisfied: aiohttp==3.6.2 in ./venv/lib/python3.8/site-packages (from -r requirements.txt (line 7)) (3.6.2)
WARNING: Retrying (Retry(total=4, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<pip._vendor.urllib3.connection.HTTPSConnection object at 0x104ccd940>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known')': /simple/aiohttp/
WARNING: Retrying (Retry(total=3, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<pip._vendor.urllib3.connection.HTTPSConnection object at 0x104ccd820>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known')': /simple/aiohttp/
WARNING: Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<pip._vendor.urllib3.connection.HTTPSConnection object at 0x104ccda00>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known')': /simple/aiohttp/
WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<pip._vendor.urllib3.connection.HTTPSConnection object at 0x104ccd580>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known')': /simple/aiohttp/
WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<pip._vendor.urllib3.connection.HTTPSConnection object at 0x104ccd6a0>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known')': /simple/aiohttp/
Requirement already satisfied: aioredis==1.3.1 in ./venv/lib/python3.8/site-packages (from -r requirements.txt (line 8)) (1.3.1)

These requests don't seem necessary as the resolution continues just fine (although I didn't wait until the end)... I hope this can help.