Improve concretization performance by tgamblin · Pull Request #14190 · spack/spack

tgamblin · 2019-12-17T01:42:43Z

Fixes #12779.

This addresses two problems:

Checks for deprecated specs (introduced in Features/deprecate #12933) were repeatedly taking out read locks on the database, which can be very slow.
get_platform() is pretty expensive and can be called many times in a spack invocation.

put a read transaction around the deprecation check to avoid repeated locking/reading
memoize get_platform()

@ajw1980 @matz-e: does this improve things for you?

matz-e · 2019-12-17T12:21:06Z

@tgamblin thank you, very instructive! I see a > 3x speedup.

(I also built on top of that to speed-up our own custom commands)

tgamblin · 2019-12-17T15:24:54Z

@matz-e: can you run pyinstrument —show-all $(which spack) <slow command> and paste the output? There may still be more we could improve if you only got 3x.

adamjstewart · 2019-12-17T18:33:07Z

Before

$ time spack spec r-condop
...
real	1m11.689s
user	1m1.083s
sys	0m4.075s

After

$ time spack spec r-condop
...
real	0m12.434s
user	0m10.675s
sys	0m0.547s

Great job!

tgamblin · 2019-12-17T20:51:55Z

@adamjstewart @ajw1980: try now.

tgamblin · 2019-12-17T20:52:17Z

@ajw1980: let's move the conversation from #12779 here.

adamjstewart · 2019-12-17T21:18:18Z

@tgamblin now things are slightly slower than the previous commit (ran it twice just to make sure):

$ time spack spec r-condop
...
real	0m17.480s
user	0m14.182s
sys	0m0.921s

ajw1980 · 2019-12-17T21:20:46Z

Yes, now I think we're looking good.
pyinstrument output:
spack-pyinstrument2.txt

Profile:

         32521324 function calls (28879768 primitive calls) in 14.944 seconds

   Ordered by: cumulative time
   List reduced from 1620 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   14.944   14.944 /shared/spack/lib/spack/spack/main.py:450(_invoke_command)
        1    0.000    0.000   14.944   14.944 /shared/spack/lib/spack/spack/cmd/spec.py:48(spec)
        1    0.004    0.004   11.112   11.112 /shared/spack/lib/spack/spack/spec.py:2119(concretize)
        8    0.000    0.000    5.015    0.627 /shared/spack/lib/spack/spack/spec.py:2570(normalize)
   2834/8    0.018    0.000    4.567    0.571 /shared/spack/lib/spack/spack/spec.py:2527(_normalize_helper)
 2826/118    0.112    0.000    4.525    0.038 /shared/spack/lib/spack/spack/spec.py:2427(_merge_dependency)
        2    0.000    0.000    3.831    1.915 /shared/spack/lib/spack/spack/spec.py:3807(tree)
   1434/4    0.007    0.000    3.301    0.825 /shared/spack/lib/spack/spack/spec.py:1956(_concretize_helper)
        2    0.001    0.001    2.840    1.420 /shared/spack/lib/spack/spack/spec.py:3814(_tree)
        4    0.002    0.000    2.720    0.680 /shared/spack/lib/spack/spack/spec.py:2017(_expand_virtual_packages)
      147    0.001    0.000    2.694    0.018 /shared/spack/lib/spack/spack/spec.py:3787(install_status)
      146    0.000    0.000    2.693    0.018 /shared/spack/lib/spack/spack/database.py:84(converter)
      146    0.000    0.000    2.693    0.018 /shared/spack/lib/spack/spack/database.py:948(get_record)
      146    0.001    0.000    2.692    0.018 /shared/spack/lib/spack/spack/database.py:937(_get_matching_spec_key)
      146    0.001    0.000    2.688    0.018 /shared/spack/lib/spack/spack/spec.py:3783(__str__)
      146    0.000    0.000    2.645    0.018 /shared/spack/lib/spack/spack/spec.py:3780(dep_string)
   113981    0.129    0.000    2.604    0.000 /shared/spack/lib/spack/spack/spec.py:1197(traverse)
628232/118177    1.163    0.000    2.534    0.000 /shared/spack/lib/spack/spack/spec.py:1212(traverse_edges)
   310686    0.126    0.000    2.200    0.000 /shared/spack/lib/spack/spack/spec.py:1167(virtual)
   310686    0.381    0.000    2.074    0.000 /shared/spack/lib/spack/spack/spec.py:1178(is_virtual)

tgamblin · 2019-12-17T21:31:08Z

@adamjstewart: does the previous commit still run in 12s for you?

ajw1980 · 2019-12-17T21:34:32Z

"spack find" is still a little slow for the python3 environment I have. It takes around 34 seconds. Here is the pyinstrument for that.
spack-find-pyinstrument.txt

Running outside of the environment is fast -- about 1.5 seconds real time.

adamjstewart · 2019-12-17T21:53:58Z

@adamjstewart: does the previous commit still run in 12s for you?

Previous commit is consistently 12 seconds, current commit is 13-20 seconds.

adamjstewart · 2019-12-18T00:52:04Z

I think there's still a lot of room for improvement within Spack Environments. Concretization seems pretty fast now. After concretization, I see thousands of comments like:

==> [2019-12-17-18:39:33.057440] Installing /Users/Adam/spack/var/spack/repos/builtin/packages/bash/package.py to /Users/Adam/.spack/darwin/.spack-env/repos/builtin/packages/bash

These debug messages show that we're installing the same files dozens of times. After this finishes, I see messages like:

==> [2019-12-17-18:50:04.540219] READ LOCK: /Users/Adam/spack/opt/spack/.spack-db/lock[0:0] [Acquiring]
==> [2019-12-17-18:50:04.541389] READ LOCK: /Users/Adam/spack/opt/spack/.spack-db/lock[0:0] [Acquired]
==> [2019-12-17-18:50:04.873852] READ LOCK: /Users/Adam/spack/opt/spack/.spack-db/lock[0:0] [Released]

thousands of times. This step lasts around 15 minutes for a partially installed environment. If you don't run spack install with --debug, this means you see Spack doing nothing for 15 minutes, which is not good. It also means SSH connections usually timeout due to inactivity.

`get_platform()` is pretty expensive and can be called many times in a spack invocation. - [x] memoize `get_platform()`

Checks for deprecated specs were repeatedly taking out read locks on the database, which can be very slow. - [x] put a read transaction around the deprecation check

tgamblin · 2019-12-18T22:18:20Z

@adamjstewart: see if the latest commits have the same issue. Turns out the transaction really belongs in spack spec, and only when -I is used. Spec.tree() doesn't need to know anything about the DB like it did in my previous version.

tgamblin · 2019-12-18T22:27:03Z

@ajw1980: I pushed another commit that should speed up spack find. See if you see an improvement.

adamjstewart · 2019-12-18T22:43:04Z

@tgamblin latest commit has a bug:

$ spack -d spec zlib
==> [2019-12-18-16:42:29.249939] Reading config file /Users/Adam/spack/etc/spack/defaults/modules.yaml
==> [2019-12-18-16:42:29.264306] Reading config file /Users/Adam/spack/etc/spack/defaults/darwin/modules.yaml
==> [2019-12-18-16:42:29.272395] Reading config file /Users/Adam/.spack/darwin/modules.yaml
==> [2019-12-18-16:42:29.274251] Reading config file /Users/Adam/spack/etc/spack/defaults/config.yaml
==> [2019-12-18-16:42:29.299837] Imported spec from built-in commands
==> [2019-12-18-16:42:29.300868] Imported spec from built-in commands
Traceback (most recent call last):
  File "/Users/Adam/spack/bin/spack", line 64, in <module>
    sys.exit(spack.main.main())
  File "/Users/Adam/spack/lib/spack/spack/main.py", line 715, in main
    return _invoke_command(command, parser, args, unknown)
  File "/Users/Adam/spack/lib/spack/spack/main.py", line 457, in _invoke_command
    return_val = command(parser, args)
  File "/Users/Adam/spack/lib/spack/spack/cmd/spec.py", line 92, in spec
    with tree_context:
AttributeError: __enter__

`spack spec -I` queries the database for installation status and should use a read transaction around calls to `Spec.tree()`.

`Environment.added_specs()` has a loop around calls to `Package.installed()`, which can result in repeated DB queries. Optimize this with a read transaction in `Environment`.

tgamblin · 2019-12-18T22:49:52Z

@adamjstewart: oops try now

adamjstewart · 2019-12-18T23:33:57Z

On the latest commit, spack spec in my home directory is the fastest time yet:

$ time spack spec r-condop
...
real	0m11.816s
user	0m10.789s
sys	0m0.512s

However, if I run spack install on an already installed environment, it's still prohibitively slow:

$ time spack install
...
real	29m57.196s
user	27m50.154s
sys	1m20.027s

The environment in question is pretty big:

spack:
  specs:
  - bash
  - graphviz
  - watch
  - wget
  - automake
  - autoconf
  - libtool
  - m4
  - cmake
  - ninja
  - patchelf
  - mercurial
  - subversion
  - gnupg
  - python
  - py-codecov
  - py-flake8
  - py-matplotlib
  - py-numpy
  - py-pandas
  - py-pytest
  - py-pytest-cov
  - py-pytest-mock
  - py-pytest-runner
  - py-setuptools
  - py-scikit-learn
  - py-scipy
  - py-sphinx
  - py-sphinx-rtd-theme
  - py-sphinxcontrib-programoutput
  - py-tables
  - py-torch
  - py-torchvision
  - py-twine
  - gdal

  concretization: together

If you run spack -d install, you'll see that we are still acquiring and releasing locks on the database tens of thousands of times. Do you want to try to resolve this in this PR, or do you want me to open a separate issue?

tgamblin · 2019-12-19T00:07:19Z

@adamjstewart: go ahead and open another issue for that one as I can't reproduce it right now. I do want to stamp that out, though.

matz-e · 2019-12-19T08:19:08Z

@matz-e: can you run pyinstrument —show-all $(which spack) <slow command> and paste the output? There may still be more we could improve if you only got 3x.

I able to revisit this only just now. After locking the database a bit more, I observe a 10x speed-up, seems in-line with the other results. I think that's fine. I've attached some results pyinstrument_filter.txt for our custom command (based on Scitas)

Thank you for the speed-up!

tgamblin added concretization platform-support performance labels Dec 17, 2019

tgamblin requested review from adamjstewart, alalazo and becker33 December 17, 2019 01:42

tgamblin mentioned this pull request Dec 17, 2019

Spack is very slow with a large number of packages #12779

Closed

matz-e mentioned this pull request Dec 17, 2019

core: add more transactional locks BlueBrain/spack#637

Merged

adamjstewart approved these changes Dec 17, 2019

View reviewed changes

tgamblin force-pushed the bugfix/deprecation-and-platform-performance branch from 793616d to b610fd1 Compare December 17, 2019 21:10

tgamblin added 2 commits December 18, 2019 09:55

performance: memoize spack.architecture.get_platform()

d5a278a

`get_platform()` is pretty expensive and can be called many times in a spack invocation. - [x] memoize `get_platform()`

concretization: improve performance by avoiding database locks

8a3069c

Checks for deprecated specs were repeatedly taking out read locks on the database, which can be very slow. - [x] put a read transaction around the deprecation check

tgamblin force-pushed the bugfix/deprecation-and-platform-performance branch 2 times, most recently from 1b33c6a to 80d42ae Compare December 18, 2019 22:17

tgamblin force-pushed the bugfix/deprecation-and-platform-performance branch from d152f8f to 54328be Compare December 18, 2019 22:27

performance: spack spec should use a read transacction with -I

9900686

`spack spec -I` queries the database for installation status and should use a read transaction around calls to `Spec.tree()`.

performance: speed up spack find in environments

421d4e4

`Environment.added_specs()` has a loop around calls to `Package.installed()`, which can result in repeated DB queries. Optimize this with a read transaction in `Environment`.

tgamblin force-pushed the bugfix/deprecation-and-platform-performance branch from 54328be to 421d4e4 Compare December 18, 2019 22:49

tgamblin merged commit a3799b2 into develop Dec 19, 2019

adamjstewart deleted the bugfix/deprecation-and-platform-performance branch December 20, 2019 22:43

aweits mentioned this pull request Feb 10, 2020

performance: add a verification file to the database #14693

Merged

Conversation

tgamblin commented Dec 17, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

matz-e commented Dec 17, 2019

Uh oh!

tgamblin commented Dec 17, 2019

Uh oh!

adamjstewart commented Dec 17, 2019

Before

After

Uh oh!

tgamblin commented Dec 17, 2019

Uh oh!

tgamblin commented Dec 17, 2019

Uh oh!

adamjstewart commented Dec 17, 2019

Uh oh!

ajw1980 commented Dec 17, 2019

Uh oh!

tgamblin commented Dec 17, 2019

Uh oh!

ajw1980 commented Dec 17, 2019

Uh oh!

adamjstewart commented Dec 17, 2019

Uh oh!

adamjstewart commented Dec 18, 2019

Uh oh!

tgamblin commented Dec 18, 2019

Uh oh!

tgamblin commented Dec 18, 2019

Uh oh!

adamjstewart commented Dec 18, 2019

Uh oh!

tgamblin commented Dec 18, 2019

Uh oh!

adamjstewart commented Dec 18, 2019

Uh oh!

tgamblin commented Dec 19, 2019

Uh oh!

matz-e commented Dec 19, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

tgamblin commented Dec 17, 2019 •

edited

Loading

matz-e commented Dec 19, 2019 •

edited

Loading