From mboxrd@z Thu Jan 1 00:00:00 1970 From: Roel Janssen Subject: Re: Performance regression on NFS with new manifest version Date: Wed, 08 Nov 2017 11:32:45 +0100 Message-ID: <87fu9pysaa.fsf@gnu.org> References: <873790o4q1.fsf@elephly.net> <87mv6ssyy0.fsf@gnu.org> <87377fukfl.fsf@gnu.org> <87shex4pc9.fsf@gnu.org> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Return-path: Received: from eggs.gnu.org ([2001:4830:134:3::10]:48785) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1eCNfE-0005pA-IP for guix-devel@gnu.org; Wed, 08 Nov 2017 05:32:57 -0500 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1eCNfC-0005Ah-Ab for guix-devel@gnu.org; Wed, 08 Nov 2017 05:32:55 -0500 In-reply-to: <87shex4pc9.fsf@gnu.org> List-Id: "Development of GNU Guix and the GNU System distribution." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guix-devel-bounces+gcggd-guix-devel=m.gmane.org@gnu.org Sender: "Guix-devel" To: Ludovic =?utf-8?Q?Court=C3=A8s?= Cc: guix-devel Ludovic Courtès writes: > Hello, > > Roel Janssen 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’.