* Performance regression on NFS with new manifest version
@ 2017-08-08 11:19 Roel Janssen
2017-08-09 20:39 ` Ricardo Wurmus
0 siblings, 1 reply; 11+ messages in thread
From: Roel Janssen @ 2017-08-08 11:19 UTC (permalink / raw)
To: guix-devel
Dear Guix,
On our cluster, the following command took less than a second to run:
guix package --search-paths
At some point, the same command took 30 seconds to run.
So, I tried previous versions of the profile and found generation 15
returned the search paths very quickly (as before), and generation 16
returned the search paths only after about 30 seconds (the regression).
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..)
Thanks for your time!
Kind regards,
Roel Janssen
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-08-08 11:19 Performance regression on NFS with new manifest version Roel Janssen
@ 2017-08-09 20:39 ` Ricardo Wurmus
2017-08-10 13:02 ` Roel Janssen
0 siblings, 1 reply; 11+ messages in thread
From: Ricardo Wurmus @ 2017-08-09 20:39 UTC (permalink / raw)
To: Roel Janssen; +Cc: guix-devel
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.
--
Ricardo
GPG: BCA6 89B6 3655 3801 C3C6 2150 197A 5888 235F ACAC
https://elephly.net
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-08-09 20:39 ` Ricardo Wurmus
@ 2017-08-10 13:02 ` Roel Janssen
2017-08-21 15:49 ` Ludovic Courtès
0 siblings, 1 reply; 11+ messages in thread
From: Roel Janssen @ 2017-08-10 13:02 UTC (permalink / raw)
To: Ricardo Wurmus; +Cc: guix-devel
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..
Anyway, I worked around it by using the $PROFILE/etc/profile file and
unset the environment variables before setting them, which takes less
than a second.
Kind regards,
Roel Janssen
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-08-10 13:02 ` Roel Janssen
@ 2017-08-21 15:49 ` Ludovic Courtès
2017-08-22 15:32 ` Roel Janssen
0 siblings, 1 reply; 11+ messages in thread
From: Ludovic Courtès @ 2017-08-21 15:49 UTC (permalink / raw)
To: Roel Janssen; +Cc: guix-devel
Hi,
Roel Janssen <roel@gnu.org> 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?
That could be a quadratic thing that popped up somewhere in that commit.
Ludo’.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-08-21 15:49 ` Ludovic Courtès
@ 2017-08-22 15:32 ` Roel Janssen
2017-09-22 9:55 ` Ludovic Courtès
0 siblings, 1 reply; 11+ messages in thread
From: Roel Janssen @ 2017-08-22 15:32 UTC (permalink / raw)
To: Ludovic Courtès; +Cc: guix-devel
Ludovic Courtès writes:
> Hi,
>
> Roel Janssen <roel@gnu.org> 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.
>
> That could be a quadratic thing that popped up somewhere in that commit.
>
> Ludo’.
Thanks for looking at this message.
Kind regards,
Roel Janssen
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-08-22 15:32 ` Roel Janssen
@ 2017-09-22 9:55 ` Ludovic Courtès
2017-09-22 12:09 ` Roel Janssen
0 siblings, 1 reply; 11+ messages in thread
From: Ludovic Courtès @ 2017-09-22 9:55 UTC (permalink / raw)
To: Roel Janssen; +Cc: guix-devel
Hello Roel,
I’m finally going back to this issue…
Roel Janssen <roel@gnu.org> skribis:
> Ludovic Courtès writes:
>
>> Hi,
>>
>> Roel Janssen <roel@gnu.org> 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’.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-09-22 9:55 ` Ludovic Courtès
@ 2017-09-22 12:09 ` Roel Janssen
2017-10-05 14:54 ` Ludovic Courtès
0 siblings, 1 reply; 11+ messages in thread
From: Roel Janssen @ 2017-09-22 12:09 UTC (permalink / raw)
To: Ludovic Courtès; +Cc: guix-devel
Ludovic Courtès writes:
> Hello Roel,
>
> I’m finally going back to this issue…
>
> Roel Janssen <roel@gnu.org> skribis:
>
>> Ludovic Courtès writes:
>>
>>> Hi,
>>>
>>> Roel Janssen <roel@gnu.org> 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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-09-22 12:09 ` Roel Janssen
@ 2017-10-05 14:54 ` Ludovic Courtès
2017-10-05 15:13 ` Ricardo Wurmus
2017-11-08 10:32 ` Roel Janssen
0 siblings, 2 replies; 11+ messages in thread
From: Ludovic Courtès @ 2017-10-05 14:54 UTC (permalink / raw)
To: Roel Janssen; +Cc: guix-devel
Hello,
Roel Janssen <roel@gnu.org> 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?
> $ 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?
TIA!
Ludo’.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-10-05 14:54 ` Ludovic Courtès
@ 2017-10-05 15:13 ` Ricardo Wurmus
2017-11-08 10:32 ` Roel Janssen
1 sibling, 0 replies; 11+ messages in thread
From: Ricardo Wurmus @ 2017-10-05 15:13 UTC (permalink / raw)
To: Ludovic Courtès; +Cc: guix-devel
Ludovic Courtès <ludo@gnu.org> writes:
>> $ 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?
@Roel: Try “strace -f” to follow spawned commands.
--
Ricardo
GPG: BCA6 89B6 3655 3801 C3C6 2150 197A 5888 235F ACAC
https://elephly.net
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-10-05 14:54 ` Ludovic Courtès
2017-10-05 15:13 ` Ricardo Wurmus
@ 2017-11-08 10:32 ` Roel Janssen
2017-11-09 9:58 ` Ludovic Courtès
1 sibling, 1 reply; 11+ messages in thread
From: Roel Janssen @ 2017-11-08 10:32 UTC (permalink / raw)
To: Ludovic Courtès; +Cc: guix-devel
Ludovic Courtès writes:
> Hello,
>
> Roel Janssen <roel@gnu.org> 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’.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Performance regression on NFS with new manifest version
2017-11-08 10:32 ` Roel Janssen
@ 2017-11-09 9:58 ` Ludovic Courtès
0 siblings, 0 replies; 11+ messages in thread
From: Ludovic Courtès @ 2017-11-09 9:58 UTC (permalink / raw)
To: Roel Janssen; +Cc: guix-devel
Roel Janssen <roel@gnu.org> skribis:
> 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.
The timings above suggest that it’s mostly CPU time, which could be a
computational problem within Guix.
Unfortunately, I cannot reproduce it locally:
--8<---------------cut here---------------start------------->8---
$ guix package -p foo -i r $(guix package -A '^r-' |cut -f1|grep -v bsgenome|head -100)
[...]
Creating manual page database for 4 packages... done in 0.038 s
pakoj 101 en profilo
La jenaj medi-variablaj difinoj povos esti necesaj:
export PATH="foo/bin${PATH:+:}$PATH"
export R_LIBS_SITE="foo/site-library/${R_LIBS_SITE:+:}$R_LIBS_SITE"
$ time guix package -p foo --search-paths
export PATH="foo/bin"
export R_LIBS_SITE="foo/site-library/"
real 0m1.569s
user 0m1.602s
sys 0m0.008s
$ guix package -p foo -I | wc -l
101
--8<---------------cut here---------------end--------------->8---
Could you try to isolate the problem in a way that I can reproduce it?
Maybe you can first try the same profile on a laptop with a local file
system and local guix-daemon.
Also, you may want to use ‘time’ without ‘strace’ to make sure we’re not
measuring the run-time overhead of ‘strace’.
TIA!
Ludo’.
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2017-11-09 9:58 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-08-08 11:19 Performance regression on NFS with new manifest version Roel Janssen
2017-08-09 20:39 ` Ricardo Wurmus
2017-08-10 13:02 ` Roel Janssen
2017-08-21 15:49 ` Ludovic Courtès
2017-08-22 15:32 ` Roel Janssen
2017-09-22 9:55 ` Ludovic Courtès
2017-09-22 12:09 ` Roel Janssen
2017-10-05 14:54 ` Ludovic Courtès
2017-10-05 15:13 ` Ricardo Wurmus
2017-11-08 10:32 ` Roel Janssen
2017-11-09 9:58 ` Ludovic Courtès
Code repositories for project(s) associated with this public inbox
https://git.savannah.gnu.org/cgit/guix.git
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).