Re: Performance regression on NFS with new manifest version

[Roel Janssen <roel@gnu.org>]

Ludovic Courtès writes:

> Hello,
>
> Roel Janssen <roel@gnu.org> skribis:
>
>> I couldn't install *all* R packages, but I used it on our shared R
>> profile:
>>
>> $ guixr package --list-installed -p /gnu/profiles/per-language/r
>> ncurses	6.0	out	/gnu/store/djvxj8r1xwvrm89xqjrd44wwaxc02i74-ncurses-6.0
>> coreutils	8.27	out	/gnu/store/ps92fz5p6l3mz9ddi388p1891r2q3fva-coreutils-8.27
>> grep	3.0	out	/gnu/store/bxnxmg6vamnlp95skrgdqw7s86ag1f51-grep-3.0
>> sed	4.4	out	/gnu/store/673v5pxadfdj1zkmpm90s6j89367w4af-sed-4.4
>> r-sparql	1.16	out	/gnu/store/5qhr4va0af65a0jrpj6nc7xdnw9s4345-r-sparql-1.16
>
> Unfortunately most of these packages are not in Guix proper AFAICS.
> Could you come up with a simple way for me to reproduce the issue on
> Guix master?

Just install a lot of R packages in a profile, including R itself would
be sufficient to reproduce it.


>
>> $ strace -c guixr package --search-paths -p /gnu/profiles/per-language/r                       
>> export PATH="/gnu/profiles/per-language/r/bin"
>> export R_LIBS_SITE="/gnu/profiles/per-language/r/site-library/"
>> export TERMINFO_DIRS="/gnu/profiles/per-language/r/share/terminfo"
>> % time     seconds  usecs/call     calls    errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>>  98.31    0.139510       11626        12         6 wait4
>>   0.77    0.001087          36        30         9 open
>>   0.43    0.000615          21        29         8 stat
>
> I think you’re tracing ‘guixr’, which forks and just waits for ‘guix’
> and other commands, no?

Indeed, here's a new strace, without using 'guixr', but instead using
'guix' with 'guix-daemon' listening on a TCP port:

$ time strace -c guix package --search-paths -p /gnu/profiles/per-language/r                                                                                                                                              
export PATH="/gnu/profiles/per-language/r/bin"
export R_LIBS_SITE="/gnu/profiles/per-language/r/site-library/"
export TERMINFO_DIRS="/gnu/profiles/per-language/r/share/terminfo"
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.15    0.010014          30       334       162 open
 24.38    0.008100           5      1518      1285 stat
 23.29    0.007738          90        86           read
 11.21    0.003723          12       314        74 futex
  2.99    0.000994           5       220           mmap
  2.49    0.000826           5       175           mprotect
  1.23    0.000407           2       175           close
  0.72    0.000238           4        66           fstat
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.033219                  3335      1535 total

real    1m12.196s
user    1m10.090s
sys     0m0.377s

So, I don't think the real issue is on display here, because strace only
thinks the command took 0.033219 seconds, but it actually too 78.196
seconds.

What worries me is that almost all stat calls are erroneous, and
I think the number of calls to "open" is a bit high for this command.

So I stripped my Bash environment (unset LD_LIBRARY_PATH, only put the
path to 'guix' in PATH), and ran the strace again:

$ /usr/bin/strace -c guix package --search-paths -p /gnu/profiles/per-language/r                                                                                                                                       
export PATH="/gnu/profiles/per-language/r/bin"
export R_LIBS_SITE="/gnu/profiles/per-language/r/site-library/"
export TERMINFO_DIRS="/gnu/profiles/per-language/r/share/terminfo"
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 35.75    0.011242           7      1510      1279 stat
 34.08    0.010718          35       305       135 open
  8.45    0.002659           8       336        83 futex
  5.24    0.001649          20        83           read
  3.94    0.001238           6       220           mmap
  2.99    0.000941           5       175           mprotect
  1.85    0.000582         582         1           readlink
  1.43    0.000450           7        64         2 lstat
  1.41    0.000445           3       170           close
  1.02    0.000320           5        64           fstat
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.031449                  3283      1509 total

Even though the number of calls to "stat" and "open" are slightly lower
now, it's still a lot.

>
> TIA!
>
> Ludo’.