unofficial mirror of bug-guix@gnu.org 
 help / color / mirror / code / Atom feed
* bug#48007: computing derivations through inferior takes twice as long
@ 2021-04-24 21:07 Ricardo Wurmus
  2022-01-26 20:51 ` Ludovic Courtès
  0 siblings, 1 reply; 11+ messages in thread
From: Ricardo Wurmus @ 2021-04-24 21:07 UTC (permalink / raw)
  To: 48007

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




^ permalink raw reply	[flat|nested] 11+ messages in thread

end of thread, other threads:[~2022-02-18 11:38 UTC | newest]

Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-04-24 21:07 bug#48007: computing derivations through inferior takes twice as long Ricardo Wurmus
2022-01-26 20:51 ` Ludovic Courtès
2022-01-26 21:32   ` Ricardo Wurmus
2022-01-27  8:50     ` Ludovic Courtès
2022-01-27  9:56       ` Ricardo Wurmus
2022-01-27 13:33         ` Ludovic Courtès
2022-01-27  8:47   ` bug#48007: [PATCH 1/4] inferior: Create the store proxy listening socket only once Ludovic Courtès
2022-01-27  8:47     ` bug#48007: [PATCH 2/4] inferior: Keep the store bridge connected Ludovic Courtès
2022-02-18 11:30       ` bug#48007: computing derivations through inferior takes twice as long Ludovic Courtès
2022-01-27  8:47     ` bug#48007: [PATCH 3/4] inferior: Inferior caches store connections Ludovic Courtès
2022-01-27  8:47     ` bug#48007: [PATCH 4/4] inferior: Move initialization bits away from 'inferior-eval-with-store' 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).