Subject: computing derivations through inferior takes twice as long

From: Ricardo Wurmus <[email-masked]>
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