From mboxrd@z Thu Jan 1 00:00:00 1970 From: Roel Janssen Subject: Re: Performance regression on NFS with new manifest version Date: Fri, 22 Sep 2017 14:09:02 +0200 Message-ID: References: <873790o4q1.fsf@elephly.net> <87mv6ssyy0.fsf@gnu.org> <87377fukfl.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]:48657) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1dvMlj-0002Fe-Vb for guix-devel@gnu.org; Fri, 22 Sep 2017 08:09:21 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1dvMlh-0000TI-Ue for guix-devel@gnu.org; Fri, 22 Sep 2017 08:09:19 -0400 In-reply-to: <87377fukfl.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, > > I’m finally going back to this issue… > > Roel Janssen skribis: > >> Ludovic Courtès writes: >> >>> Hi, >>> >>> Roel Janssen skribis: >>> >>>> Ricardo Wurmus writes: >>>> >>>>> Hi Roel, >>>>> >>>>>> Looking into the manifests ($GENERATION_15/manifest and >>>>>> $GENERATION_16/manifest), I noticed that generation 15 uses manifest >>>>>> version 2, and generation 16 uses manifest version 3. >>>>>> >>>>>> What has changed, so that it takes a lot longer to run the same command >>>>>> as before? (this is probably disk-related, because that is a known >>>>>> cause for trouble on network-mounted stores..) >>>>> >>>>> Commit 55b4715fd4c03e46501f123c5c9bc6072edf12a4 bumped the manifest >>>>> version to 3. The goal was to represent propagated inputs as manifest >>>>> entries so that we can anticipate conflicts from propagated inputs and >>>>> refuse to build a profile when there would be conflicts. >>>> >>>> Thanks for pointing to that commit. It's much better this way. :-) >>>> >>>> So, what makes 'guix package --search-paths' so slow? It doesn't have >>>> to check for conflicts because that's already done on profile creation >>>> time. All it has to do is combine the search-path data and output >>>> that.. >>> >>> Could it be that you have lots of propagated inputs in your profile >>> (Python, etc.)? Are you sure (per ‘strace’) that it has to do with file >>> system accesses? >> >> Yes, I have lots of propagated inputs in that profile (R packages..). >> >> I haven't checked with strace, but everything else on this machine is >> fast and plenty (24 cores, 128GB ram). The only troublesome thing is >> the NFS-mounted store. > > I tried to reproduce the problem like this: > > --8<---------------cut here---------------start------------->8--- > $ ./pre-inst-env guix package -p foo -i r $(guix package -A '^r-a'|cut -f1) > guix package: warning: Your Guix installation is 10 days old. > guix package: warning: Consider running 'guix pull' followed by > 'guix package -u' to get up-to-date packages and security updates. > > The following packages will be installed: > r 3.4.1 /gnu/store/k0q4b6nq1cdyfh3267nmgkwspf7hv6pb-r-3.4.1 > r-acepack 1.4.1 /gnu/store/2lnpmwk5n3g2567q0rj1cz2hfwmcaj4v-r-acepack-1.4.1 > r-acsnminer 0.16.8.25 /gnu/store/dv7mrnh8nm0cga5caqay5hmx4cc5355a-r-acsnminer-0.16.8.25 > r-adaptivesparsity 1.4 /gnu/store/vkiq4knbqm1rm6hsnbkq4ad0pgdsr653-r-adaptivesparsity-1.4 > r-ade4 1.7-8 /gnu/store/3455karydz6sfn5d78r088f812w5z99y-r-ade4-1.7-8 > r-affy 1.54.0 /gnu/store/zv5fj0c5gdw27carm7mdvyisdnrnirl9-r-affy-1.54.0 > r-affyio 1.46.0 /gnu/store/xgd50xlbq6nsjjk628y1n8scf4hwrrd8-r-affyio-1.46.0 > r-annotate 1.54.0 /gnu/store/qbbwjr7k12ss32d7545pwr31lhg1ng07-r-annotate-1.54.0 > r-annotationdbi 1.38.2 /gnu/store/vcmxw3plg8yygp58q4crr85710hr9mqk-r-annotationdbi-1.38.2 > r-annotationfilter 1.0.0 /gnu/store/w2n1lz9051fhchc8v2c6yyq7dv7bsxgh-r-annotationfilter-1.0.0 > r-annotationforge 1.18.1 /gnu/store/9vmr1lfx4g6v3h85d8jgaqn7cs2by8wy-r-annotationforge-1.18.1 > r-annotationhub 2.8.2 /gnu/store/xyanxcl5dgj8fq415dr4ihm1prlsrz03-r-annotationhub-2.8.2 > r-ape 4.1 /gnu/store/0cy2kw2vifirbhp399db8lndfkyqgjva-r-ape-4.1 > r-aroma-light 3.6.0 /gnu/store/rq0xawz5l9nq07cxz9kisk63yxasfcnl-r-aroma-light-3.6.0 > r-assertthat 0.2.0 /gnu/store/dqq16x94nwkgyrliavf0w6gnhp1vxbha-r-assertthat-0.2.0 > r-auc 0.3.0 /gnu/store/fmzah3jzzy756sh4dir78nb8kcrn25pn-r-auc-0.3.0 > > [...] > > The following environment variable definitions may be needed: > export PATH="foo/bin${PATH:+:}$PATH" > export R_LIBS_SITE="foo/site-library/${R_LIBS_SITE:+:}$R_LIBS_SITE" > ludo@ribbon ~/src/guix$ time ./pre-inst-env guix package --search-paths -p foo > export PATH="foo/bin" > export R_LIBS_SITE="foo/site-library/" > > real 0m0.170s > user 0m0.107s > sys 0m0.016s > ludo@ribbon ~/src/guix$ time ./pre-inst-env guix package --search-paths -p foo > export PATH="foo/bin" > export R_LIBS_SITE="foo/site-library/" > > real 0m0.158s > user 0m0.097s > sys 0m0.021s > ludo@ribbon ~/src/guix$ ./pre-inst-env strace -c guix package --search-paths -p foo > export PATH="foo/bin" > export R_LIBS_SITE="foo/site-library/" > % time seconds usecs/call calls errors syscall > ------ ----------- ----------- --------- --------- ---------------- > 69.68 0.005729 2 3516 3292 stat > 14.96 0.001230 40 31 1 futex > 4.14 0.000340 1 271 121 open > 2.96 0.000243 1 182 mmap > 2.89 0.000238 2 156 mprotect > 1.14 0.000094 1 150 close > 1.06 0.000087 1 110 3 lseek > 0.91 0.000075 1 74 read > 0.63 0.000052 10 5 clone > 0.46 0.000038 1 28 brk > 0.28 0.000023 1 46 fstat > 0.19 0.000016 5 3 pipe2 > 0.18 0.000015 1 16 lstat > 0.15 0.000012 2 5 1 ioctl > 0.09 0.000007 1 7 clock_gettime > 0.07 0.000006 1 7 rt_sigprocmask > 0.06 0.000005 2 3 write > 0.06 0.000005 2 3 fcntl > 0.04 0.000003 2 2 getcwd > 0.02 0.000002 0 5 rt_sigaction > 0.02 0.000002 2 1 getrandom > 0.00 0.000000 0 2 munmap > 0.00 0.000000 0 2 2 access > 0.00 0.000000 0 1 execve > 0.00 0.000000 0 1 uname > 0.00 0.000000 0 1 readlink > 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 prlimit64 > ------ ----------- ----------- --------- --------- ---------------- > 100.00 0.008222 4636 3420 total > --8<---------------cut here---------------end--------------->8--- > > Everything looks OK here, but it could be that I did not pick the right > set of packages to reproduce the problem. > > Could you come up with a simple way for me to reproduce it? > > TIA! > > Ludo’. 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 r-blob 1.1.0 out /gnu/store/g17llpsbppkq7bkdibfmfkna9hdssfbv-r-blob-1.1.0 r-dexseq 1.22.0 out /gnu/store/hsc2pgcz51sf3sq1n7yl7jwhpnz7jg5n-r-dexseq-1.22.0 r-ripseeker 1.14.0 out /gnu/store/sh5q8r0v05r854i9p62prpgiw08q60n7-r-ripseeker-1.14.0 r-bsgenome-celegans-ucsc-ce10 1.4.0 out /gnu/store/bmgapxyiqldlq4xa0a5sfariay6swa1h-r-bsgenome-celegans-ucsc-ce10-1.4.0 r-bsgenome-hsapiens-ucsc-hg19 1.4.0 out /gnu/store/dq28v4mncd8a5rqnc5f3lq3lrmas1p8m-r-bsgenome-hsapiens-ucsc-hg19-1.4.0 r-bsgenome-hsapiens-1000genomes-hs37d5 0.99.1 out /gnu/store/smv43q5p0fgiy1kyz9yaiw01q6zz5c9n-r-bsgenome-hsapiens-1000genomes-hs37d5-0.99.1 r-bsgenome-mmusculus-ucsc-mm10 1.4.0 out /gnu/store/95k6r8c7sz66z51hc0x059fv7090qk1d-r-bsgenome-mmusculus-ucsc-mm10-1.4.0 r-qdnaseq 1.10.0 out /gnu/store/7r9wazsllnflgpwbcwkcpb1wgl5vpvvv-r-qdnaseq-1.10.0 r-pracma 2.0.7 out /gnu/store/ikwdwfqp9hf35iwc31bp9mswwnzyjs05-r-pracma-2.0.7 r-biomart 2.32.1 out /gnu/store/5r3nwc4nawh4ldr5inrbys11cprbg442-r-biomart-2.32.1 r-rngtools 1.2.4 out /gnu/store/4awn9jy8yp8xr0ma7izsww4b4i6av4yv-r-rngtools-1.2.4 r-pkgmaker 0.22 out /gnu/store/mjfrgggip6jl4bx6i6ypbgqvbab91l50-r-pkgmaker-0.22 r-gridextra 2.3 out /gnu/store/s618pfbmzcv405s730namha638ynpf8p-r-gridextra-2.3 r 3.4.1 out /gnu/store/2a8igkn9f5n4ag8ym9ysrmki2msnifyn-r-3.4.1 r-biocviews 1.44.0 out /gnu/store/0cwz2zyj6h4pv7mhi26sx8r7p2xyj5zz-r-biocviews-1.44.0 r-bioccheck 1.12.0 out /gnu/store/6d3wwas1xzs9g3msdilacy7xisj39dc0-r-bioccheck-1.12.0 r-ggplot2 2.2.1 out /gnu/store/0v9g3p95scbq1wm0qvpv24d0308l78cm-r-ggplot2-2.2.1 r-gplots 3.0.1 out /gnu/store/jba92jjlzq7xgvw4ac5n5lyr8k224k0v-r-gplots-3.0.1 r-pastecs 1.3-18 out /gnu/store/0fb5329ipb76ggfj10csv4d3p3af81yn-r-pastecs-1.3-18 r-funcisnp 1.18.0 out /gnu/store/6667xikkpdqp8cbn9q0v5zrq2s0b7i28-r-funcisnp-1.18.0 r-diffbind 2.2.12 out /gnu/store/8mc3yl9j5s3brn63r34s3krg4xkdbayl-r-diffbind-2.2.12 r-edger 3.18.0 out /gnu/store/96wqf9pcw0ikiwqqyx6w952svyv7h0ca-r-edger-3.18.0 r-rbgl 1.52.0 out /gnu/store/25rkm6fc3abbw7ak77yxks46bd9fmxjd-r-rbgl-1.52.0 r-biocstyle 2.4.1 out /gnu/store/zj5v2iwrcvm9vczbdpcw0mcr304j8j00-r-biocstyle-2.4.1 r-rcurl 1.95-0.1.2 out /gnu/store/bk0yriz89j5arhz2qky3757zmpivnn1k-r-rcurl-1.95-0.1.2 r-s4vectors 0.14.3 out /gnu/store/k41y6gp8sk4p4mfhkpq3yh5di79qap9b-r-s4vectors-0.14.3 r-xvector 0.16.0 out /gnu/store/7an3mc6qpr9xprcwv944gaq9xn09syk5-r-xvector-0.16.0 r-xml2 1.1.1 out /gnu/store/60zmc0hk9z5shi5s4k3j8yp8vfklw2ik-r-xml2-1.1.1 r-iranges 2.10.2 out /gnu/store/3hs9r87zsxnaq837rka8bsjm9gv1419p-r-iranges-2.10.2 r-biostrings 2.44.2 out /gnu/store/rr2j9sf3dg24qy93jzwl84a09mscpw7y-r-biostrings-2.44.2 r-devtools 1.13.3 out /gnu/store/xi3kjaif2vxk0c1wggraajsblakh5r4l-r-devtools-1.13.3 r-nmf 0.20.6 out /gnu/store/pbp6pk8di5h8rdql8rfmv9kqbd0b03nl-r-nmf-0.20.6 r-reshape2 1.4.2 out /gnu/store/yd8pngfm523fr8nnpnh27qb4q79zvzzi-r-reshape2-1.4.2 r-variantannotation 1.22.3 out /gnu/store/nlz40rw5gic8s1zqy8r5xqyg6lv2px0y-r-variantannotation-1.22.3 r-mutationalpatterns 1.2.1 out /gnu/store/v3654hh4k291q429b0wvfyb7vw7f4ihn-r-mutationalpatterns-1.2.1 r-deseq2 1.16.1 out /gnu/store/say07f2m9ixb6lvp7hqpy1yfr4nks648-r-deseq2-1.16.1 r-openssl 0.9.7 out /gnu/store/qn7qn0dp5ff8bf2649g8s9i32pjlrfgh-r-openssl-0.9.7 r-curl 2.8.1 out /gnu/store/fwyfhhyn253vqny4yxsc0568l8qcps5c-r-curl-2.8.1 r-git2r 0.19.0 out /gnu/store/2j74yg2znd6mz059mw0lv15wpjr7i13j-r-git2r-0.19.0 r-jsonlite 1.5 out /gnu/store/004h1v4wy3hvjqms0bm8x114qmk1dl0b-r-jsonlite-1.5 r-rcpp 0.12.12 out /gnu/store/fgm16p6pyxyjswzzh0xcaqzln7bilw86-r-rcpp-0.12.12 r-mime 0.5 out /gnu/store/ba5nx5mx4ji0mfdv4g8l40fjbcjjgi8m-r-mime-0.5 r-plyr 1.8.4 out /gnu/store/5dyby97wd6lg2n04gndcn0k7rm30k8fp-r-plyr-1.8.4 r-ggdendro 0.1-20 out /gnu/store/lfj04k9p2hnma733qib54vapv0whrgbp-r-ggdendro-0.1-20 r-cowplot 0.8.0 out /gnu/store/5y1f266cf9lfd7a8vk2in190fmz1j90m-r-cowplot-0.8.0 r-testthat 1.0.2 out /gnu/store/02fp185nf106c5i4pz9jmkx7j8kkpxx1-r-testthat-1.0.2 r-bit64 0.9-7 out /gnu/store/f7fpax2g3pniv5n6y3ysm50kmyskr0a2-r-bit64-0.9-7 r-rlang 0.1.2 out /gnu/store/gvhx5rsd13fv30n7wfiwclrrhirzdwgw-r-rlang-0.1.2 r-biocinstaller 1.26.0 out /gnu/store/pizcmi2k44v4vsk8m0bb4hh6n2qrw6fs-r-biocinstaller-1.26.0 r-motifbreakr 1.6.0 out /gnu/store/cic9h7rdkk5w8810khna32bf5kjlpzl4-r-motifbreakr-1.6.0 Here's my timings: $ time 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" real 1m3.771s user 1m3.745s sys 0m0.145 And the strace: $ 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 0.10 0.000144 24 6 clone 0.07 0.000095 5 19 mmap 0.05 0.000076 4 21 read 0.05 0.000064 2 26 close 0.04 0.000058 3 20 fstat 0.03 0.000049 5 9 1 access 0.03 0.000045 45 1 lstat 0.03 0.000039 1 48 rt_sigprocmask 0.02 0.000028 5 6 mprotect 0.01 0.000013 0 28 rt_sigaction 0.01 0.000008 2 4 lseek 0.01 0.000008 2 5 brk 0.01 0.000008 1 9 getuid 0.01 0.000008 1 9 getgid 0.01 0.000008 1 9 geteuid 0.01 0.000008 1 9 getegid 0.00 0.000007 1 6 rt_sigreturn 0.00 0.000007 1 8 1 fcntl 0.00 0.000005 3 2 pipe 0.00 0.000005 5 1 execve 0.00 0.000003 1 4 3 ioctl 0.00 0.000003 1 3 dup2 0.00 0.000003 3 1 arch_prctl 0.00 0.000002 1 2 prlimit64 0.00 0.000000 0 1 write 0.00 0.000000 0 2 getpid 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 sysinfo 0.00 0.000000 0 1 getppid 0.00 0.000000 0 1 getpgrp 0.00 0.000000 0 1 faccessat ------ ----------- ----------- --------- --------- ---------------- 100.00 0.141906 335 28 total I don't understand why the numbers are so low on my end. Note, this is /gnu served over NFS. We recently upgraded to SSDs in our storage system, which caused reads to be faster. In the case of the --search-paths, it is still very slow. Kind regards, Roel Janssen