all messages for Guix-related lists mirrored at yhetil.org
 help / color / mirror / code / Atom feed
* 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 external index

	https://git.savannah.gnu.org/cgit/guix.git

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.