Spack is very slow with a large number of packages #12779
Description
I've built python and and R with many packages for each of them and spack becomes very slow to install packages (or also spack spec -I). When I strace spack while it is running, it looks like it repeatedly gets locks and reads the index.json for each package. It seems like maybe the locking and DB read should just be done once.
Here's a couple of seconds of strace on spack spec -I r-caret:
08:29:18 stat("/shared/spack/opt/spack", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
08:29:18 mkdir("/shared/spack/opt/spack/.spack-db", 0777) = -1 EEXIST (File exists)
08:29:18 stat("/shared/spack/opt/spack/.spack-db", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
08:29:18 stat("/shared/spack/opt/spack/.spack-db/lock", {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:18 access("/shared/spack/opt/spack/.spack-db/lock", W_OK) = 0
08:29:18 open("/shared/spack/opt/spack/.spack-db/lock", O_RDWR|O_CREAT, 0777) = 3
08:29:18 fcntl(3, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
08:29:18 fstat(3, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:18 mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f93dc278000
08:29:18 lseek(3, 0, SEEK_CUR) = 0
08:29:18 fstat(3, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:18 fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
08:29:18 stat("/shared/spack/opt/spack/.spack-db/index.json", {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:18 open("/shared/spack/opt/spack/.spack-db/index.json", O_RDONLY) = 4
08:29:18 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:18 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:18 lseek(4, 0, SEEK_CUR) = 0
08:29:18 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:18 mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f93dba78000
08:29:18 lseek(4, 0, SEEK_CUR) = 0
08:29:18 read(4, "{\n \"database\": {\n \"installs\": {"..., 8388608) = 743955
08:29:18 read(4, "", 8388608) = 0
08:29:19 close(4) = 0
08:29:19 munmap(0x7f93dba78000, 8388608) = 0
08:29:19 fcntl(3, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
08:29:19 close(3) = 0
08:29:19 munmap(0x7f93dc278000, 8388608) = 0
08:29:19 stat("/shared/spack/opt/spack", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
08:29:19 mkdir("/shared/spack/opt/spack/.spack-db", 0777) = -1 EEXIST (File exists)
08:29:19 stat("/shared/spack/opt/spack/.spack-db", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
08:29:19 stat("/shared/spack/opt/spack/.spack-db/lock", {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:19 access("/shared/spack/opt/spack/.spack-db/lock", W_OK) = 0
08:29:19 open("/shared/spack/opt/spack/.spack-db/lock", O_RDWR|O_CREAT, 0777) = 3
08:29:19 fcntl(3, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
08:29:19 fstat(3, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:19 mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f93dc278000
08:29:19 lseek(3, 0, SEEK_CUR) = 0
08:29:19 fstat(3, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
08:29:19 fcntl(3, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
08:29:19 stat("/shared/spack/opt/spack/.spack-db/index.json", {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:19 open("/shared/spack/opt/spack/.spack-db/index.json", O_RDONLY) = 4
08:29:19 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:19 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:19 lseek(4, 0, SEEK_CUR) = 0
08:29:19 fstat(4, {st_mode=S_IFREG|0644, st_size=743955, ...}) = 0
08:29:19 mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f93dba78000
08:29:19 lseek(4, 0, SEEK_CUR) = 0
08:29:19 read(4, "{\n \"database\": {\n \"installs\": {"..., 8388608) = 743955
08:29:19 read(4, "", 8388608) = 0
08:29:20 close(4) = 0
With profiling turned on for spack spec -I r-caret:
581360413 function calls (514772064 primitive calls) in 313.928 CPU seconds
Ordered by: internal time
List reduced from 1439 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
32668189/5878144 67.459 0.000 125.206 0.000 /shared/spack/lib/spack/spack/spec.py:1143(traverse_edges)
2017614/369 27.344 0.000 134.369 0.364 /usr/lib64/python2.6/json/decoder.py:162(JSONObject)
19260894/738 20.656 0.000 134.373 0.182 /usr/lib64/python2.6/json/scanner.py:38(iterscan)
18690042/2017980 18.318 0.000 33.818 0.000 /shared/spack/lib/spack/spack/util/spack_json.py:40(_strify)
10570044 14.352 0.000 21.527 0.000 /shared/spack/lib/spack/spack/dependency.py:20(canonical_deptype)
67861316/67861315 11.328 0.000 11.615 0.000 {isinstance}
11881485 8.450 0.000 8.450 0.000 {_json.scanstring}
1838949/1838639 8.174 0.000 24.866 0.000 /usr/lib64/python2.6/json/decoder.py:206(JSONArray)
16638831/16638432 7.953 0.000 8.089 0.000 {sorted}
5487136 6.824 0.000 11.091 0.000 /usr/lib64/python2.6/_abcoll.py:362(items)
18549071 5.592 0.000 5.592 0.000 {built-in method scanner}
5874765 5.221 0.000 131.176 0.000 /shared/spack/lib/spack/spack/spec.py:1128(traverse)
11901204 5.073 0.000 5.073 0.000 {method 'encode' of 'unicode' objects}
4839501 5.044 0.000 10.021 0.000 /usr/lib64/python2.6/json/decoder.py:152(JSONString)
66980134 5.001 0.000 5.003 0.000 {method 'get' of 'dict' objects}
9059595 4.707 0.000 24.955 0.000 /shared/spack/lib/spack/spack/util/spack_json.py:53(<genexpr>)
31707642 4.414 0.000 4.414 0.000 /shared/spack/lib/spack/spack/spec.py:1198(validate)
43138508 4.118 0.000 4.118 0.000 {built-in method end}
10087620 3.348 0.000 3.348 0.000 {built-in method match}
20272794 3.314 0.000 3.314 0.000 /shared/spack/lib/spack/spack/spec.py:1245(<genexpr>)