Re: Performance regression on NFS with new manifest version

[ludo@gnu.org (Ludovic Courtès)]

Hello Roel,

I’m finally going back to this issue…

Roel Janssen <roel@gnu.org> skribis:

> Ludovic Courtès writes:
>
>> Hi,
>>
>> Roel Janssen <roel@gnu.org> skribis:
>>
>>> Ricardo Wurmus writes:
>>>
>>>> Hi Roel,
>>>>
>>>>> Looking into the manifests ($GENERATION_15/manifest and
>>>>> $GENERATION_16/manifest), I noticed that generation 15 uses manifest
>>>>> version 2, and generation 16 uses manifest version 3.
>>>>>
>>>>> What has changed, so that it takes a lot longer to run the same command
>>>>> as before?  (this is probably disk-related, because that is a known
>>>>> cause for trouble on network-mounted stores..)
>>>>
>>>> Commit 55b4715fd4c03e46501f123c5c9bc6072edf12a4 bumped the manifest
>>>> version to 3.  The goal was to represent propagated inputs as manifest
>>>> entries so that we can anticipate conflicts from propagated inputs and
>>>> refuse to build a profile when there would be conflicts.
>>>
>>> Thanks for pointing to that commit.  It's much better this way. :-)
>>>
>>> So, what makes 'guix package --search-paths' so slow?  It doesn't have
>>> to check for conflicts because that's already done on profile creation
>>> time.  All it has to do is combine the search-path data and output
>>> that..
>>
>> Could it be that you have lots of propagated inputs in your profile
>> (Python, etc.)?  Are you sure (per ‘strace’) that it has to do with file
>> system accesses?
>
> Yes, I have lots of propagated inputs in that profile (R packages..).
>
> I haven't checked with strace, but everything else on this machine is
> fast and plenty (24 cores, 128GB ram).  The only troublesome thing is
> the NFS-mounted store.

I tried to reproduce the problem like this:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guix package -p foo -i r $(guix package -A '^r-a'|cut -f1)
guix package: warning: Your Guix installation is 10 days old.
guix package: warning: Consider running 'guix pull' followed by
'guix package -u' to get up-to-date packages and security updates.

The following packages will be installed:
   r	3.4.1	/gnu/store/k0q4b6nq1cdyfh3267nmgkwspf7hv6pb-r-3.4.1
   r-acepack	1.4.1	/gnu/store/2lnpmwk5n3g2567q0rj1cz2hfwmcaj4v-r-acepack-1.4.1
   r-acsnminer	0.16.8.25	/gnu/store/dv7mrnh8nm0cga5caqay5hmx4cc5355a-r-acsnminer-0.16.8.25
   r-adaptivesparsity	1.4	/gnu/store/vkiq4knbqm1rm6hsnbkq4ad0pgdsr653-r-adaptivesparsity-1.4
   r-ade4	1.7-8	/gnu/store/3455karydz6sfn5d78r088f812w5z99y-r-ade4-1.7-8
   r-affy	1.54.0	/gnu/store/zv5fj0c5gdw27carm7mdvyisdnrnirl9-r-affy-1.54.0
   r-affyio	1.46.0	/gnu/store/xgd50xlbq6nsjjk628y1n8scf4hwrrd8-r-affyio-1.46.0
   r-annotate	1.54.0	/gnu/store/qbbwjr7k12ss32d7545pwr31lhg1ng07-r-annotate-1.54.0
   r-annotationdbi	1.38.2	/gnu/store/vcmxw3plg8yygp58q4crr85710hr9mqk-r-annotationdbi-1.38.2
   r-annotationfilter	1.0.0	/gnu/store/w2n1lz9051fhchc8v2c6yyq7dv7bsxgh-r-annotationfilter-1.0.0
   r-annotationforge	1.18.1	/gnu/store/9vmr1lfx4g6v3h85d8jgaqn7cs2by8wy-r-annotationforge-1.18.1
   r-annotationhub	2.8.2	/gnu/store/xyanxcl5dgj8fq415dr4ihm1prlsrz03-r-annotationhub-2.8.2
   r-ape	4.1	/gnu/store/0cy2kw2vifirbhp399db8lndfkyqgjva-r-ape-4.1
   r-aroma-light	3.6.0	/gnu/store/rq0xawz5l9nq07cxz9kisk63yxasfcnl-r-aroma-light-3.6.0
   r-assertthat	0.2.0	/gnu/store/dqq16x94nwkgyrliavf0w6gnhp1vxbha-r-assertthat-0.2.0
   r-auc	0.3.0	/gnu/store/fmzah3jzzy756sh4dir78nb8kcrn25pn-r-auc-0.3.0

[...]

The following environment variable definitions may be needed:
   export PATH="foo/bin${PATH:+:}$PATH"
   export R_LIBS_SITE="foo/site-library/${R_LIBS_SITE:+:}$R_LIBS_SITE"
ludo@ribbon ~/src/guix$ time ./pre-inst-env guix package --search-paths -p foo
export PATH="foo/bin"
export R_LIBS_SITE="foo/site-library/"

real	0m0.170s
user	0m0.107s
sys	0m0.016s
ludo@ribbon ~/src/guix$ time ./pre-inst-env guix package --search-paths -p foo
export PATH="foo/bin"
export R_LIBS_SITE="foo/site-library/"

real	0m0.158s
user	0m0.097s
sys	0m0.021s
ludo@ribbon ~/src/guix$ ./pre-inst-env strace -c guix package --search-paths -p foo
export PATH="foo/bin"
export R_LIBS_SITE="foo/site-library/"
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 69.68    0.005729           2      3516      3292 stat
 14.96    0.001230          40        31         1 futex
  4.14    0.000340           1       271       121 open
  2.96    0.000243           1       182           mmap
  2.89    0.000238           2       156           mprotect
  1.14    0.000094           1       150           close
  1.06    0.000087           1       110         3 lseek
  0.91    0.000075           1        74           read
  0.63    0.000052          10         5           clone
  0.46    0.000038           1        28           brk
  0.28    0.000023           1        46           fstat
  0.19    0.000016           5         3           pipe2
  0.18    0.000015           1        16           lstat
  0.15    0.000012           2         5         1 ioctl
  0.09    0.000007           1         7           clock_gettime
  0.07    0.000006           1         7           rt_sigprocmask
  0.06    0.000005           2         3           write
  0.06    0.000005           2         3           fcntl
  0.04    0.000003           2         2           getcwd
  0.02    0.000002           0         5           rt_sigaction
  0.02    0.000002           2         1           getrandom
  0.00    0.000000           0         2           munmap
  0.00    0.000000           0         2         2 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         1           readlink
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         2           sched_getaffinity
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         3           prlimit64
------ ----------- ----------- --------- --------- ----------------
100.00    0.008222                  4636      3420 total
--8<---------------cut here---------------end--------------->8---

Everything looks OK here, but it could be that I did not pick the right
set of packages to reproduce the problem.

Could you come up with a simple way for me to reproduce it?

TIA!

Ludo’.