GNU bug report logs - #48007
computing derivations through inferior takes twice as long

Previous Next

Full log

View this message in rfc822 format

From: help-debbugs <at> gnu.org (GNU bug Tracking System)
To: Ricardo Wurmus <rekado <at> elephly.net>
Subject: bug#48007: closed (Re: bug#48007: computing derivations through
 inferior takes twice as long)
Date: Thu, 27 Jan 2022 13:34:02 +0000

[Message part 1 (text/plain, inline)]

Your bug report

#48007: computing derivations through inferior takes twice as long

which was filed against the guix package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to 48007 <at> debbugs.gnu.org.

-- 
48007: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=48007
GNU Bug Tracking System
Contact help-debbugs <at> gnu.org with problems

[Message part 2 (message/rfc822, inline)]

From: Ludovic Courtès <ludo <at> gnu.org>
To: Ricardo Wurmus <rekado <at> elephly.net>
Cc: 48007-done <at> debbugs.gnu.org
Subject: Re: bug#48007: computing derivations through inferior takes twice
 as long
Date: Thu, 27 Jan 2022 14:33:27 +0100

Ricardo Wurmus <rekado <at> elephly.net> skribis:

> These patches look great to me and they work.
> My real-world test case is now down to about 12 seconds.

Good!  Fixed the typo you mentioned on IRC and pushed as
e778910bdfc68c60a5be59aac93049d32feae904.

To summarize, the INFERIOR=y case still takes about twice as long as the
INFERIOR=n case (before that it was actually 9 times slower).

I suppose this is mostly due to the round trips between the inferior and
the parent (one per package).  We’d have to analyze more closely, for
example with ‘perf timechart’, where the wait times are.  It’ll always
be slower than without an inferior though.

Last, we should improve the baseline (4s here for the manifest you
gave).  That’s the tricky part.

Thanks,
Ludo’.

[Message part 3 (message/rfc822, inline)]

From: Ricardo Wurmus <rekado <at> elephly.net>
To: bug-guix <at> gnu.org
Subject: computing derivations through inferior takes twice as long
Date: Sat, 24 Apr 2021 23:07:14 +0200

This bug report might be related to bug #48005.

In the Guix Workflow Language we are always looking up packages 
through an inferior Guix.  That Guix will in most cases be just 
the current Guix.  As I was looking for ways to speed the GWL up, 
I noticed that the use of inferiors itself contributes to a 
significant loss in performance.

Here is a simple manifest to demonstrate this:

--8<---------------cut here---------------start------------->8---
(use-modules (guix inferior)
            (ice-9 match))

(define inferior
 (open-inferior (format #false "~a/.config/guix" (getenv 
 "HOME"))))

(define packages
 (list "bash-minimal"
       "r-corrplot"
       "r-crosstalk"
       "r-data-table"
       "r-deseq2"
       "r-dt"
       "r-genomicalignments"
       "r-genomicranges"
       "r-ggplot2"
       "r-ggrepel"
       "r-gprofiler"
       "r-knitr"
       "r-minimal"
       "r-pheatmap"
       "r-plotly"
       "r-reshape2"
       "r-rmarkdown"
       "r-rsamtools"
       "r-rtracklayer"
       "r-s4vectors"
       "r-scales"
       "r-summarizedexperiment"
       "r-tximport"))

(match (getenv "INFERIOR")
 ("y"
  (packages->manifest
   (map (lambda (specification)
          (match (lookup-inferior-packages inferior 
          specification)
            ((first . rest) first)))
        packages)))
 (_
  (specifications->manifest packages)))
--8<---------------cut here---------------end--------------->8---

When INFERIOR is set to “y”, each package specification will be 
looked up in the current Guix via an inferior.  For any other 
values of INFERIOR the specifications are resolved with the 
current Guix (the very same Guix) directly.

Here are the timings:

--8<---------------cut here---------------start------------->8---
$ [env] export GUIX_PROFILING="object-cache 
add-data-to-store-cache rpc"
$ [env] time INFERIOR=n guix build -m manifest-test.scm -d
/gnu/store/mwg47gbmi98bbrywk07y5l2h9p6d1hz5-bash-minimal-5.0.16.drv
/gnu/store/kcjk6z128fa07pzp8irp6lbbyl3g16nr-r-corrplot-0.84.drv
/gnu/store/s6hflcww9gaq87g5vaaydd4lphw63xjm-r-crosstalk-1.1.1.drv
/gnu/store/qrjgag94sv9lq12028y9iv12j75bva6c-r-data-table-1.14.0.drv
/gnu/store/v6xw6pg33xa8pg19nw0cxhz9b7ps26v7-r-deseq2-1.30.1.drv
/gnu/store/q1achql92wnij108msymr9mkr8pv2z1h-r-dt-0.17.drv
/gnu/store/iym2kzpjiqch22yrhg5lnv9sfazdfphn-r-genomicalignments-1.26.0.drv
/gnu/store/k913mn4q11pchgi63xrm8lb3svvqjcix-r-genomicranges-1.42.0.drv
/gnu/store/zkpabp1qx6m5yam3f9kninnsxagsgwqh-r-ggplot2-3.3.3.drv
/gnu/store/b6w1p6rhbk8shz1ydc2yqb38ypm0ijq9-r-ggrepel-0.9.1.drv
/gnu/store/bwmmls5qkf9cfs9m73qzabnr7w5jc8ra-r-gprofiler-0.7.0.drv
/gnu/store/j1m8hb4449rkfh3ij1l4379j1lngjr06-r-knitr-1.31.drv
/gnu/store/7ig30kf3i65s3rdcw1qik7vsjvspkjxy-r-minimal-4.0.4.drv
/gnu/store/mwg8c42sfsvcrbjhbw7mbdcphhz9hq3x-r-pheatmap-1.0.12.drv
/gnu/store/xjg40q7a7yl3l9v99kqapjylfjwapwk7-r-plotly-4.9.3.drv
/gnu/store/fhs8as885izfb1r6as07sn6jpjgfbl58-r-reshape2-1.4.4.drv
/gnu/store/6bcny1hhf83k85js6x3w7h1w3660ii8m-r-rmarkdown-2.7.drv
/gnu/store/87pr587bk9rzfkrjmrm4bcfjz95p1n9c-r-rsamtools-2.6.0.drv
/gnu/store/l3ibbpd4h7gm565vidbpyamdnhb0czhp-r-rtracklayer-1.50.0.drv
/gnu/store/8rf8d204kavcxkw6z71kxd2mzzqzxsk1-r-s4vectors-0.28.1.drv
/gnu/store/4nxw4lhcvj3q9j5v6mq9ri4v4vwmxd6h-r-scales-1.1.1.drv
/gnu/store/vpf3vkj58vwz92nxcpppil6580c84bb1-r-summarizedexperiment-1.20.0.drv
/gnu/store/cx3cl0nxwvzpaj484q2xcnz3v7zc1015-r-tximport-1.18.0.drv
Store object cache:
 fresh caches:     2
 lookups:       4540
 hits:          3568 (78.6%)
 cache size:     971 entries

'add-data-to-store' cache:
 lookups:       3450
 hits:           492 (14.3%)
 .drv files:    2087 (60.5%)
 Scheme files:  1347 (39.0%)
Remote procedure call summary: 3412 RPCs
 built-in-builders              ...     1
 add-to-store/tree              ...    16
 add-to-store                   ...   177
 query-references               ...   260
 add-text-to-store              ...  2958

real	0m3.970s
user	0m4.055s
sys	0m0.173s
$ [env] time INFERIOR=y guix build -m manifest-test.scm -d
/gnu/store/mwg47gbmi98bbrywk07y5l2h9p6d1hz5-bash-minimal-5.0.16.drv
/gnu/store/hmk49rhbfqw2ss55392a7kq34xqg18i7-r-corrplot-0.84.drv
/gnu/store/sg8a3pvzxaq2qd4z918mdb2y0vq6w8mg-r-crosstalk-1.1.1.drv
/gnu/store/n3vk2kkq7zza7pfrjqqbv6xaxhnzdn2x-r-data-table-1.14.0.drv
/gnu/store/44fqdg0s6bcmcgafvgafycf2x82rfl7y-r-deseq2-1.30.1.drv
/gnu/store/03snyvyp9fr3nchrln6qhdca00i7lrsz-r-dt-0.17.drv
/gnu/store/rl48alwm40sl4b04rnk4cck2h4crr8gc-r-genomicalignments-1.26.0.drv
/gnu/store/ryl6hjflgpb72xl91jvp0ab6sl5cblc4-r-genomicranges-1.42.0.drv
/gnu/store/1hbg746cvi8s7vn03glzx46m0pdih5pw-r-ggplot2-3.3.3.drv
/gnu/store/nwvkjb314hh7z7vag0mk870isynp0hda-r-ggrepel-0.9.1.drv
/gnu/store/kvvygkc7vnznrqp4n2rvgsbz9z2jd6ns-r-gprofiler-0.7.0.drv
/gnu/store/0jv2zf34b2p1ddpxnzv5smq4717i4hfq-r-knitr-1.31.drv
/gnu/store/zgi8sfw54jv7wb33q9cs18ff1vlfy0fm-r-minimal-4.0.4.drv
/gnu/store/7w4jp2skqy0vn8i4pr26l94mw8vs8knc-r-pheatmap-1.0.12.drv
/gnu/store/xshkhmd8gpjkmi7npz0bw02wgb8mkysg-r-plotly-4.9.3.drv
/gnu/store/5jqkb3khygfc2y96nff92hfslc2c53yz-r-reshape2-1.4.4.drv
/gnu/store/x0fzqyjg1hq7a4n0wglr9sl71bzxwz0q-r-rmarkdown-2.7.drv
/gnu/store/3v78408vx5x28nb3cf42jarr7fy3b16v-r-rsamtools-2.6.0.drv
/gnu/store/qp4hjddv5sjxiiss0m55q4cv88k520gd-r-rtracklayer-1.50.0.drv
/gnu/store/pgfahjz3wfnppc07z0qbcsdc6mmpri0l-r-s4vectors-0.28.1.drv
/gnu/store/aq317mqb3rbc2rnq2y15k781q5qvf9ia-r-scales-1.1.1.drv
/gnu/store/w9dirjkx523398mhkjw0v4hxgq7x0b8s-r-summarizedexperiment-1.20.0.drv
/gnu/store/rfmzii8xsc3fk63s332ix2qgxpvdvrgf-r-tximport-1.18.0.drv
Store object cache:
 fresh caches:     1
 lookups:         23
 hits:             0 (0.0%)
 cache size:      23 entries

'add-data-to-store' cache:
 lookups:          0
 hits:             0 (100.0%)
 .drv files:       0 (100.0%)
 Scheme files:     0 (100.0%)
Remote procedure call summary: 0 RPCs

real	0m7.951s
user	0m2.191s
sys	0m0.240s
--8<---------------cut here---------------end--------------->8---

Note that nothing is built.  This is merely to compute already 
existing derivations.  Computing the same derivations through an 
inferior Guix takes about twice as long.
I’ll note that in the inferior case there are no 
“add-data-to-store” calls compared to 2958 calls in the direct 
case.  I don’t know what to make of this.  Is that information 
lost as we cross over to the inferior Guix…?  Or are there really 
different / fewer RPCs?

Things look similar when we actually instantiate the manifest:

--8<---------------cut here---------------start------------->8---
$ [env] time INFERIOR=n guix package -m manifest-test.scm -p 
/tmp/foo
The following packages will be installed:
  bash-minimal           5.0.16
  r-corrplot             0.84
  r-crosstalk            1.1.1
  r-data-table           1.14.0
  r-deseq2               1.30.1
  r-dt                   0.17
  r-genomicalignments    1.26.0
  r-genomicranges        1.42.0
  r-ggplot2              3.3.3
  r-ggrepel              0.9.1
  r-gprofiler            0.7.0
  r-knitr                1.31
  r-minimal              4.0.4
  r-pheatmap             1.0.12
  r-plotly               4.9.3
  r-reshape2             1.4.4
  r-rmarkdown            2.7
  r-rsamtools            2.6.0
  r-rtracklayer          1.50.0
  r-s4vectors            0.28.1
  r-scales               1.1.1
  r-summarizedexperiment 1.20.0
  r-tximport             1.18.0

nothing to be done
Store object cache:
 fresh caches:     2
 lookups:      41381
 hits:         40249 (97.3%)
 cache size:    1131 entries

'add-data-to-store' cache:
 lookups:       6083
 hits:          2950 (48.5%)
 .drv files:    3407 (56.0%)
 Scheme files:  2659 (43.7%)
Remote procedure call summary: 3897 RPCs
 built-in-builders              ...     1
 add-to-store/tree              ...    22
 add-to-store                   ...   178
 query-references               ...   563
 add-text-to-store              ...  3133

real	0m12.697s
user	0m15.873s
sys	0m0.197s
$ [env] time INFERIOR=y guix package -m manifest-test.scm -p 
/tmp/foo
The following packages will be installed:
  bash-minimal           5.0.16
  r-corrplot             0.84
  r-crosstalk            1.1.1
  r-data-table           1.14.0
  r-deseq2               1.30.1
  r-dt                   0.17
  r-genomicalignments    1.26.0
  r-genomicranges        1.42.0
  r-ggplot2              3.3.3
  r-ggrepel              0.9.1
  r-gprofiler            0.7.0
  r-knitr                1.31
  r-minimal              4.0.4
  r-pheatmap             1.0.12
  r-plotly               4.9.3
  r-reshape2             1.4.4
  r-rmarkdown            2.7
  r-rsamtools            2.6.0
  r-rtracklayer          1.50.0
  r-s4vectors            0.28.1
  r-scales               1.1.1
  r-summarizedexperiment 1.20.0
  r-tximport             1.18.0

nothing to be done
Store object cache:
 fresh caches:     2
 lookups:      27162
 hits:         26425 (97.3%)
 cache size:     736 entries

'add-data-to-store' cache:
 lookups:        887
 hits:            52 (5.9%)
 .drv files:     550 (62.0%)
 Scheme files:   331 (37.3%)
Remote procedure call summary: 1011 RPCs
 built-in-builders              ...     1
 add-to-store/tree              ...    11
 query-references               ...    51
 add-to-store                   ...   113
 add-text-to-store              ...   835

real	0m19.504s
user	0m4.014s
sys	0m0.411s
--8<---------------cut here---------------end--------------->8---

The first case with 12 seconds reproduces bug #48005.  The second 
case (going through the inferior) is much slower with over 19 
seconds; if we squint this is also close to twice the amount of 
time compared to the “direct” computation.

-- 
Ricardo

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.