bug#48007: computing derivations through inferior takes twice as long

[Ricardo Wurmus]

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