computing derivations through inferior takes twice as long

OpenSubmitted by Ricardo Wurmus.
Details
2 participants
  • Ludovic Courtès
  • Ricardo Wurmus
Owner
unassigned
Severity
important
R
R
Ricardo Wurmus wrote on 24 Apr 23:07 +0200
(address . bug-guix@gnu.org)
87wnsrpf25.fsf@elephly.net
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:
Toggle snippet (44 lines)(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)))
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:
Toggle snippet (89 lines)$ [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.drvStore 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.970suser 0m4.055ssys 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.drvStore 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.951suser 0m2.191ssys 0m0.240s
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:
Toggle snippet (100 lines)$ [env] time INFERIOR=n guix package -m manifest-test.scm -p /tmp/fooThe 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 doneStore 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.697suser 0m15.873ssys 0m0.197s$ [env] time INFERIOR=y guix package -m manifest-test.scm -p /tmp/fooThe 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 doneStore 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.504suser 0m4.014ssys 0m0.411s
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
L
L
Ludovic Courtès wrote on 30 Apr 17:45 +0200
control message for bug #48007
(address . control@debbugs.gnu.org)
87mttfbwt1.fsf@gnu.org
severity 48007 importantquit
?
Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send email to 48007@debbugs.gnu.org