[bug#27097] Performance on NFS

[Roel Janssen]

Ludovic Courtès writes:

> Hi Roel,
>
> Roel Janssen <address@hidden> skribis:
>
>> You should know that we have 'submit' nodes that use the guixr wrapper
>> script to connect to the guix-daemon that runs on the 'hpcguix' node.
>>
>> Both have a /gnu mounted by a storage subsystem.
>>
>> I couldn't run the second command on a 'submit' node.  But I could run
>> it in the 'hpcguix' node.
>
> OK.
>
> Side note: I think you can replace your ‘guixr’ wrapper by just doing:
>
>   export GUIX_DAEMON_SOCKET=guix://hpcguix:1234
>
> See <https://www.gnu.org/software/guix/manual/html_node/The-Store.html>.
>
>> The first command:
>> ------------------
>>
>> address@hidden ~]$ time guixr environment --ad-hoc coreutils --pure -- true
>>
>> real    0m38.415s
>> user    0m6.075s
>> sys     0m0.611s
>>
>> address@hidden ~]$ time guix environment --ad-hoc coreutils --pure -- true
>>
>> real    0m27.054s
>> user    0m4.254s
>> sys     0m0.383s
>>
>>
>> The second command:
>> -------------------
>>
>> address@hidden ~]$ time guix environment --ad-hoc -e '(@ (gnu packages base) 
>> coreutils)' --pure --no-substitutes --no-grafts -- true                      
>>                                                                              
>>    
>> The following derivations will be built:
>>    /gnu/store/9wczighnyz1bz43j4wawf09z180g3ywv-profile.drv
>>    /gnu/store/ffsyhajbdcp1lcq6x65czghya1iydly8-info-dir.drv
>>    /gnu/store/5gyl3l23ps6f8dgay4awybwq7n9j9pzk-fonts-dir.drv
>>    /gnu/store/l2mwj2q4vnq2v5raxz64ra7jyphd2jyd-manual-database.drv
>> Creating manual page database for 1 packages... done in 5.524 s
>>
>> real    1m6.812s
>> user    0m2.969s
>> sys     0m0.325s
>> address@hidden ~]$ time guix environment --ad-hoc -e '(@ (gnu packages base) 
>> coreutils)' --pure --no-substitutes --no-grafts -- true
>>
>> real    0m23.357s
>> user    0m2.802s
>> sys     0m0.340s
>>
>>
>> I suspect that the difference between the two commands is that one only
>> looks for one module, while the other looks in all modules.  Looking at
>> the second run, I suppose the difference is quite small.
>
> Yeah, -e doesn’t seem to be much faster (there are still a lot of
> modules to load anyway.)
>
> At any rate, let’s see what we can do; 23 seconds is not okay.
>
> I did a quick experiment:
>
> --8<---------------cut here---------------start------------->8---
> $ strace -o ,,s -s 123 guix environment --ad-hoc -e '(@ (gnu packages base) 
> coreutils)' --pure --no-substitutes --no-grafts -- true
> $ grep ^open ,,s |wc -l
> 1095
> $ grep '^open.*ENOENT' ,,s |wc -l
> 136
> $ grep -E '^(open|stat|lstat).*patches/gcc-arm-bug' ,,s |wc -l
> 27
> $ grep -E '^(open|stat|lstat).*guix/build/utils' ,,s |wc -l
> 2190
> --8<---------------cut here---------------end--------------->8---
>
> After the patch below, I get:
>
> --8<---------------cut here---------------start------------->8---
> $ grep -E '^(open|stat|lstat).*guix/build/utils' ,,s2 |wc -l
> 14
> $ grep -E '^(open|stat|lstat).*patches/gcc-arm-bug' ,,s2 |wc -l
> 4
> --8<---------------cut here---------------end--------------->8---
>
> Here’s the big picture before and after:
>
> --8<---------------cut here---------------start------------->8---
> $ strace -c guix environment --ad-hoc -e '(@ (gnu packages base) coreutils)' 
> --pure --no-substitutes --no-grafts -- true
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  32.55    0.009781           1     10463      9158 stat
>  15.55    0.004673           1      8780           write
>  11.26    0.003385        3385         1           wait4
>   7.94    0.002387          20       122        12 futex
>   6.38    0.001917           0      5052         4 lstat
>   5.70    0.001713           2      1095       136 open
>   5.54    0.001664           1      2919           read
>   3.02    0.000909           2       525           mmap
>   2.96    0.000889         148         6           clone
>   2.50    0.000751           2       481           mprotect
>   2.00    0.000600           1       959           close
>   1.56    0.000469           1       898         3 lseek
>   1.10    0.000330           3       100           sendfile
>   0.88    0.000264           0       541           fstat
>   0.42    0.000127           1       175           brk
>   0.15    0.000044           2        22           rt_sigaction
>   0.09    0.000026           5         5           munmap
>   0.06    0.000019           1        18           rt_sigprocmask
>   0.06    0.000019           2        10         3 ioctl
>   0.03    0.000010           3         3         3 access
>   0.03    0.000010           2         6         1 fcntl
>   0.03    0.000009           0        23           clock_gettime
>   0.03    0.000008           2         5           prlimit64
>   0.02    0.000006           6         1           statfs
>   0.02    0.000005           2         3           pipe2
>   0.01    0.000004           2         2           getpid
>   0.01    0.000004           4         1           sysinfo
>   0.01    0.000003           3         1           dup2
>   0.01    0.000003           2         2           arch_prctl
>   0.01    0.000003           3         1           set_tid_address
>   0.01    0.000002           1         2           execve
>   0.01    0.000002           1         2           uname
>   0.01    0.000002           2         1           getuid
>   0.01    0.000002           2         1           getgid
>   0.01    0.000002           2         1           geteuid
>   0.01    0.000002           2         1           getegid
>   0.01    0.000002           2         1           getppid
>   0.01    0.000002           2         1           getpgrp
>   0.01    0.000002           2         1           set_robust_list
>   0.00    0.000001           0        16           readlink
>   0.00    0.000000           0         3           madvise
>   0.00    0.000000           0         1           socket
>   0.00    0.000000           0         1           connect
>   0.00    0.000000           0         1           getcwd
>   0.00    0.000000           0         2           sched_getaffinity
>   0.00    0.000000           0         1           getrandom
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.030051                 32256      9320 total
> $ ./pre-inst-env strace -c guix environment --ad-hoc -e '(@ (gnu packages 
> base) coreutils)' --pure --no-substitutes --no-grafts -- true
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  35.19    0.004311           0      9423      8117 stat
>  25.25    0.003094           0      8780           write
>   9.99    0.001224           0      2895           read
>   7.88    0.000965           1      1062       122 open
>   6.39    0.000783           7       117        10 futex
>   3.80    0.000466           1       502           mmap
>   3.34    0.000409           1       474           mprotect
>   2.91    0.000357           0       940           close
>   2.14    0.000262           0       900         3 lseek
>   1.90    0.000233           0       518           fstat
>   0.59    0.000072           1       100           sendfile
>   0.26    0.000032           0       123           lstat
>   0.20    0.000025           0        78           brk
>   0.04    0.000005           0        23           clock_gettime
>   0.02    0.000003           1         5           munmap
>   0.02    0.000003           1         6           clone
>   0.02    0.000002           0         5           rt_sigaction
>   0.02    0.000002           0        15           rt_sigprocmask
>   0.01    0.000001           1         1           wait4
>   0.01    0.000001           1         1           arch_prctl
>   0.01    0.000001           1         2           sched_getaffinity
>   0.01    0.000001           0         3           prlimit64
>   0.00    0.000000           0         7         1 ioctl
>   0.00    0.000000           0         2         2 access
>   0.00    0.000000           0         1           madvise
>   0.00    0.000000           0         1           socket
>   0.00    0.000000           0         1           connect
>   0.00    0.000000           0         1           execve
>   0.00    0.000000           0         1           uname
>   0.00    0.000000           0         3           fcntl
>   0.00    0.000000           0         1           getcwd
>   0.00    0.000000           0         1           statfs
>   0.00    0.000000           0         1           set_tid_address
>   0.00    0.000000           0         1           set_robust_list
>   0.00    0.000000           0         3           pipe2
>   0.00    0.000000           0         1           getrandom
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.012252                 25998      8255 total
> --8<---------------cut here---------------end--------------->8---
>
> So that’s shaving ~20% of the syscalls (notice the number of ‘lstat’
> calls), which may make a difference on NFS.
>
> Could you give it a try and report back?
>
> This patch optimizes the ‘add-to-store’ on the client side.  Until now
> the caching strategy in ‘add-to-store’ was very conservative: at each
> call it would ‘lstat’ the given file and use the stat as a key in
> caching.  Thus, if the file changed, we would notice and reopen it.
>
> The obvious downside is that we’d keep doing ‘lstat’ for a case that’s
> unlikely.  With this patch, we simply use the file name as the key in
> the ‘add-to-store’ cache.
>
> Though as you wrote before, ‘open’ is much more expensive that ‘stat’ on
> NFS, so that’s where we should focus.
>
> Thanks,
> Ludo’.
>
> diff --git a/guix/store.scm b/guix/store.scm
> index c94dfea95..8acde18d0 100644
> --- a/guix/store.scm
> +++ b/guix/store.scm
> @@ -830,10 +830,9 @@ bits are kept.  HASH-ALGO must be a string such as 
> \"sha256\".
>  When RECURSIVE? is true, call (SELECT?  FILE STAT) for each directory entry,
>  where FILE is the entry's absolute file name and STAT is the result of
>  'lstat'; exclude entries for which SELECT? does not return true."
> -      (let* ((st    (false-if-exception (lstat file-name)))
> -             (args  `(,st ,basename ,recursive? ,hash-algo ,select?))
> +      (let* ((args  `(,file-name ,basename ,recursive? ,hash-algo ,select?))
>               (cache (nix-server-add-to-store-cache server)))
> -        (or (and st (hash-ref cache args))
> +        (or (hash-ref cache args)
>              (let ((path (add-to-store server basename recursive?
>                                        hash-algo file-name
>                                        #:select? select?)))

Here are the timings.  The patched version is used with ./pre-inst-env,
and the unpatched version is not invoked using ./pre-inst-env.

With patch:
-----------------------------------------------------------------------------------------------------

address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true
The following derivations will be built:
   /gnu/store/zfyjc6zmhjj19vx4h6z22kjbz75izm2d-profile.drv
   /gnu/store/p9nxlcyhvkiyfxllbb81m8jjnv1hfkhq-ca-certificate-bundle.drv
   /gnu/store/any2b7k23b16xq4pbym21dx0sg6ybmyi-info-dir.drv
   /gnu/store/55mmjkg47n58gql1yys053gl3vqfxlml-fonts-dir.drv
   /gnu/store/s5vinzd4rc9yffigamb5k76r4ipqim6z-manual-database.drv
Creating manual page database for 19 packages... done in 26.220 s
warning: collision encountered: 
/gnu/store/ri56wnmzkgzrajdyl5ydc55lrwy1164k-ld-wrapper-0/bin/ld 
/gnu/store/zq65kpvwwxgc3qqbf9apic8gyss2l0zq-binutils-2.27/bin/ld 
warning: arbitrarily choosing 
/gnu/store/ri56wnmzkgzrajdyl5ydc55lrwy1164k-ld-wrapper-0/bin/ld

real    6m14.571s
user    0m3.702s
sys     0m0.361s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m43.446s
user    0m3.393s
sys     0m0.452s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m22.405s
user    0m3.532s
sys     0m0.336s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m22.361s
user    0m3.356s
sys     0m0.326s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m17.993s
user    0m3.422s
sys     0m0.394s

Without patch:
-----------------------------------------------------------------------------------------------------

address@hidden guix]$ time  guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m41.746s
user    0m3.471s
sys     0m0.552s
address@hidden guix]$ time  guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m26.406s
user    0m3.451s
sys     0m0.523s
address@hidden guix]$ time  guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m37.703s
user    0m3.445s
sys     0m0.579s
address@hidden guix]$ time  guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m27.084s
user    0m3.538s
sys     0m0.428s

On hpcguix with patch:
-----------------------------------------------------------------------------------------------------

address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m42.971s
user    0m3.335s
sys     0m0.386s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m19.428s
user    0m3.239s
sys     0m0.367s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m27.086s
user    0m3.073s
sys     0m0.348s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m33.214s
user    0m3.068s
sys     0m0.296s
address@hidden guix]$ time ./pre-inst-env guix environment --pure coreutils 
--no-substitutes --no-grafts -- true

real    0m22.686s
user    0m3.010s
sys     0m0.305s

On hpcguix without patch:
-----------------------------------------------------------------------------------------------------

address@hidden guix]$ time guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m28.502s
user    0m3.201s
sys     0m0.447s
address@hidden guix]$ time guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m41.693s
user    0m3.061s
sys     0m0.301s
address@hidden guix]$ time guix environment --pure coreutils --no-substitutes 
--no-grafts -- true

real    0m26.178s
user    0m3.034s
sys     0m0.358s



>From these timings, I don't think it has a big impact.  This makes me
wonder, can't we replace the disk-intensive stuff with a database?
If we only have to read the files on disk once, after which we extracted
the information (the hashes?) needed to compute which links have to be
created to make an environment, then actually creating the environment
can be as fast as only creating those links.

Maybe this is too vague, because I don't know what Guix needs to read
exactly here.

Kind regards,
Roel Janssen