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

Please note: This is a static page, with minimal formatting, updated once a day.
Click here to see this page with the latest information and nicer formatting.

Package: guix; Severity: important; Reported by: Ricardo Wurmus <rekado@HIDDEN>; dated Sat, 24 Apr 2021 21:08:02 UTC; Maintainer for guix is bug-guix@HIDDEN.
Severity set to 'important' from 'normal' Request was from Ludovic Courtès <ludo@HIDDEN> to control <at> debbugs.gnu.org. Full text available.

Message received at submit <at> debbugs.gnu.org:


Received: (at submit) by debbugs.gnu.org; 24 Apr 2021 21:07:32 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Sat Apr 24 17:07:32 2021
Received: from localhost ([127.0.0.1]:41599 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1laPUx-0007zN-Vb
	for submit <at> debbugs.gnu.org; Sat, 24 Apr 2021 17:07:32 -0400
Received: from lists.gnu.org ([209.51.188.17]:49268)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <rekado@HIDDEN>) id 1laPUt-0007zE-VT
 for submit <at> debbugs.gnu.org; Sat, 24 Apr 2021 17:07:31 -0400
Received: from eggs.gnu.org ([2001:470:142:3::10]:43508)
 by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
 (Exim 4.90_1) (envelope-from <rekado@HIDDEN>)
 id 1laPUt-00051o-R5
 for bug-guix@HIDDEN; Sat, 24 Apr 2021 17:07:27 -0400
Received: from sender4-of-o51.zoho.com ([136.143.188.51]:21173)
 by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
 (Exim 4.90_1) (envelope-from <rekado@HIDDEN>)
 id 1laPUr-0005c6-EB
 for bug-guix@HIDDEN; Sat, 24 Apr 2021 17:07:27 -0400
ARC-Seal: i=1; a=rsa-sha256; t=1619298438; cv=none; 
 d=zohomail.com; s=zohoarc; 
 b=YHovs9S5Y7O4jQNv/rOISC/0cnBGJgLaFBv2J/EdYwqWWT2fgeZRaTuuVlDuUcdO7ApMNt2+YQ8vLzJJUsEVYcvFxOjtMe0EqXscvtoemrvDjJ/YUxq6thKQcS5K/+Cdy44b0tb3W1CxkOH+AFgyvbPbRM1qgnpSiK8a8It/Sek=
ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=zohomail.com;
 s=zohoarc; t=1619298438;
 h=Content-Type:Content-Transfer-Encoding:Date:From:MIME-Version:Message-ID:Subject:To;
 bh=9qBBAAr+tRTZNB+gK0gY2h6OelR7KIfexvApyGh0bnw=; 
 b=fX8+sdXE93nNzxL6di+97F1EMUlhsVatfwf5JQHS7YeigVSv574m9MwFCAEAz7EF/7bRNZ2TPQczFdNZ5EBUT2f01Fgruh2tlf3EI1TWBt6h3oWWZqfHy/GoxCCk8TBQb4h2a5rcU7X2JEmjnnj8VuaBAX/YzWbaspg4E1pRw5Q=
ARC-Authentication-Results: i=1; mx.zohomail.com;
 dkim=pass  header.i=elephly.net;
 spf=pass  smtp.mailfrom=rekado@HIDDEN;
 dmarc=pass header.from=<rekado@HIDDEN> header.from=<rekado@HIDDEN>
DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; t=1619298438; 
 s=zoho; d=elephly.net; i=rekado@HIDDEN;
 h=From:To:Subject:Date:Message-ID:MIME-Version:Content-Type:Content-Transfer-Encoding;
 bh=9qBBAAr+tRTZNB+gK0gY2h6OelR7KIfexvApyGh0bnw=;
 b=Hn9hmuCaPhkGVVDWuYeaMgVFoZB/Qk8G5dkcrOzJ3AvjNYDiQKOUbVn+Tojmd0Bq
 XjxQ1tzecmjtzcUWnsksWcISHovoCWXlK1taokWSEuVnIAzsF0r4Yrp0ClZBdVVIHwj
 UtJmQdXWZLoTbqXeRC439CX5Qn+sY/BcaYUQSZ/I=
Received: from localhost (p4fd5ab0c.dip0.t-ipconnect.de [79.213.171.12]) by
 mx.zohomail.com with SMTPS id 161929843743942.68504151230297;
 Sat, 24 Apr 2021 14:07:17 -0700 (PDT)
User-agent: mu4e 1.4.15; emacs 27.2
From: Ricardo Wurmus <rekado@HIDDEN>
To: bug-guix@HIDDEN
Subject: computing derivations through inferior takes twice as long
X-URL: https://elephly.net
X-PGP-Key: https://elephly.net/rekado.pubkey
X-PGP-Fingerprint: BCA6 89B6 3655 3801 C3C6  2150 197A 5888 235F ACAC
Date: Sat, 24 Apr 2021 23:07:14 +0200
Message-ID: <87wnsrpf25.fsf@HIDDEN>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: quoted-printable
X-ZohoMailClient: External
Received-SPF: pass client-ip=136.143.188.51; envelope-from=rekado@HIDDEN;
 helo=sender4-of-o51.zoho.com
X-Spam_score_int: -20
X-Spam_score: -2.1
X-Spam_bar: --
X-Spam_report: (-2.1 / 5.0 requ) BAYES_00=-1.9, DKIM_SIGNED=0.1,
 DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1,
 RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H3=0.001, RCVD_IN_MSPIKE_WL=0.001,
 SPF_HELO_NONE=0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no
X-Spam_action: no action
X-Spam-Score: -1.3 (-)
X-Debbugs-Envelope-To: submit
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -2.3 (--)

This bug report might be related to bug #48005.

In the Guix Workflow Language we are always looking up packages=20
through an inferior Guix.  That Guix will in most cases be just=20
the current Guix.  As I was looking for ways to speed the GWL up,=20
I noticed that the use of inferiors itself contributes to a=20
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=20
  "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=20
           specification)
             ((first . rest) first)))
         packages)))
  (_
   (specifications->manifest packages)))
--8<---------------cut here---------------end--------------->8---

When INFERIOR is set to =E2=80=9Cy=E2=80=9D, each package specification wil=
l be=20
looked up in the current Guix via an inferior.  For any other=20
values of INFERIOR the specifications are resolved with the=20
current Guix (the very same Guix) directly.

Here are the timings:

--8<---------------cut here---------------start------------->8---
$ [env] export GUIX_PROFILING=3D"object-cache=20
add-data-to-store-cache rpc"
$ [env] time INFERIOR=3Dn 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.d=
rv
/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=3Dy 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.d=
rv
/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=20
existing derivations.  Computing the same derivations through an=20
inferior Guix takes about twice as long.
I=E2=80=99ll note that in the inferior case there are no=20
=E2=80=9Cadd-data-to-store=E2=80=9D calls compared to 2958 calls in the dir=
ect=20
case.  I don=E2=80=99t know what to make of this.  Is that information=20
lost as we cross over to the inferior Guix=E2=80=A6?  Or are there really=20
different / fewer RPCs?

Things look similar when we actually instantiate the manifest:

--8<---------------cut here---------------start------------->8---
$ [env] time INFERIOR=3Dn guix package -m manifest-test.scm -p=20
/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=3Dy guix package -m manifest-test.scm -p=20
/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=20
case (going through the inferior) is much slower with over 19=20
seconds; if we squint this is also close to twice the amount of=20
time compared to the =E2=80=9Cdirect=E2=80=9D computation.

--=20
Ricardo




Acknowledgement sent to Ricardo Wurmus <rekado@HIDDEN>:
New bug report received and forwarded. Copy sent to bug-guix@HIDDEN. Full text available.
Report forwarded to bug-guix@HIDDEN:
bug#48007; Package guix. Full text available.
Please note: This is a static page, with minimal formatting, updated once a day.
Click here to see this page with the latest information and nicer formatting.
Last modified: Fri, 30 Apr 2021 16:00:02 UTC

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