Re: Performance on NFS

[Roel Janssen]

Hello!

Ludovic Courtès writes:

> Hello!
>
> I just pushed another improvement:
> d27cc3bfaafe6b5b0831e88afb1c46311d382a0b significantly reduces the
> number of ‘stat’ calls when discovering .scm files.  I’d be curious to
> see what impact it has on NFS.
>
> Commit cbee955901b3e252ebdeb8066a2196055149198a also reduces the number
> of ‘stat’ calls.
>
> After that I have:
>
> --8<---------------cut here---------------start------------->8---
> $ ./pre-inst-env strace -c  guix environment --ad-hoc coreutils -- true 
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  27.03    0.006916           1     13585           read
>  24.64    0.006306           1      9701      8029 stat
>  21.25    0.005438           1     10698           write
>  11.05    0.002828        2828         1           wait4
>   3.60    0.000922           1      1598       122 open
>   2.88    0.000738           4       203        28 futex
>   1.79    0.000458           1       670           mmap
>   1.75    0.000448           1       642           mprotect
>   1.64    0.000419           0      1476           close
>   1.36    0.000347           0      1411         3 lseek
>   0.74    0.000190           2       107           sendfile
>   0.70    0.000180           4        51           getdents
>   0.62    0.000159           0       886           fstat
>   0.54    0.000137           1       196           lstat
>   0.22    0.000057           1        99           brk
>   0.09    0.000024           4         6           clone
>   0.02    0.000005           1         5           munmap
>   0.02    0.000005           0        19           rt_sigprocmask
>   0.02    0.000004           0        27           clock_gettime
>   0.01    0.000003           3         1           getrandom
>   0.01    0.000002           2         1           connect
>   0.01    0.000002           1         3           prlimit64
>   0.00    0.000001           1         2         2 access
>   0.00    0.000001           1         1           socket
>   0.00    0.000000           0         5           rt_sigaction
>   0.00    0.000000           0         7         1 ioctl
>   0.00    0.000000           0         1           madvise
>   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           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           pipe2
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.025590                 41417      8185 total
> $ git describe
> v0.13.0-804-gf4453df9a
> --8<---------------cut here---------------end--------------->8---
>
> The number of ‘stat’ calls is a function of the number of entries in
> ‘GUILE_LOAD_PATH’ and ‘GUILE_LOAD_COMPILED_PATH’.  I can’t think of any
> easy way to reduce it further.
>
> The many ‘read’ and ‘write’ are due to the unbuffered port used for
> RPCs, and definitely not great when talking to a remote store.  I’ve
> tried to add some buffering but that turned out to be trickier than I
> had hoped for.
>
> To be continued!
>
> Ludo’.

I applied the patch, and here are the results:

address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure -- true
The following derivations will be built:
   /gnu/store/0hz8g844432b5h9zbqr9cpsjy0brg15h-profile.drv
   /gnu/store/wkksb7bbx3jr0p6p5cj4kkphbwday0yd-info-dir.drv
   /gnu/store/cd2mwx9qprdy23p7j3pik2zs14nifn36-manual-database.drv
Creating manual page database for 1 packages... done in 1.816 s

real    1m14.686s
user    0m5.761s
sys     0m0.498s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure -- true

real    0m34.100s
user    0m5.599s
sys     0m0.414s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure -- true

real    0m33.821s
user    0m5.140s
sys     0m0.432s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-substitutes --no-grafts -- true
The following derivations will be built:
   /gnu/store/rvh0imjdimwm90nzr0fmr5gmp97lyiix-profile.drv
   /gnu/store/5hm3v4afjf9gix92ixqzv9bwc11a608s-fonts-dir.drv

real    0m37.200s
user    0m3.408s
sys     0m0.284s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-substitutes --no-grafts -- true

real    0m19.415s
user    0m3.466s
sys     0m0.306s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-substitutes --no-grafts -- true

real    0m18.850s
user    0m3.536s
sys     0m0.346s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-grafts -- true

real    0m16.003s
user    0m3.246s
sys     0m0.301s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-grafts -- true

real    0m18.205s
user    0m3.470s
sys     0m0.314s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-substitutes -- true

real    0m33.731s
user    0m5.111s
sys     0m0.428s
address@hidden guix]$ time guixr environment --ad-hoc coreutils --pure 
--no-substitutes -- true

real    0m30.993s
user    0m5.049s
sys     0m0.458s

Why is grafting so slow, even if it doesn't have to graft anything?

So, because grafting is disk-intensive rather than CPU-intensive, it might
be a good idea to be able to globally disable grafting.  (it would
reduce the after-we-build-it-time considerably for our cluster.)

Kind regards,
Roel Janssen