bug#27097: Performance on NFS

[Ludovic Courtès]

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?)))