From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp0 ([2001:41d0:2:4a6f::]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id 6FU/D72IhGApZwAAgWs5BA (envelope-from ) for ; Sat, 24 Apr 2021 23:08:13 +0200 Received: from aspmx1.migadu.com ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp0 with LMTPS id mHnyCr2IhGCPHQAA1q6Kng (envelope-from ) for ; Sat, 24 Apr 2021 21:08:13 +0000 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id 7D72B8853 for ; Sat, 24 Apr 2021 23:08:12 +0200 (CEST) Received: from localhost ([::1]:47656 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1laPVa-000545-6t for larch@yhetil.org; Sat, 24 Apr 2021 17:08:10 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:43560) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1laPVS-00053u-Lc for bug-guix@gnu.org; Sat, 24 Apr 2021 17:08:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:58286) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1laPVS-00060V-DM for bug-guix@gnu.org; Sat, 24 Apr 2021 17:08:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1laPVS-000808-7G for bug-guix@gnu.org; Sat, 24 Apr 2021 17:08:02 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#48007: computing derivations through inferior takes twice as long Resent-From: Ricardo Wurmus Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Sat, 24 Apr 2021 21:08:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: report 48007 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: 48007@debbugs.gnu.org X-Debbugs-Original-To: bug-guix@gnu.org Received: via spool by submit@debbugs.gnu.org id=B.161929845230718 (code B ref -1); Sat, 24 Apr 2021 21:08:02 +0000 Received: (at submit) by debbugs.gnu.org; 24 Apr 2021 21:07:32 +0000 Received: from localhost ([127.0.0.1]:41599 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1laPUx-0007zN-Vb for submit@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 ) id 1laPUt-0007zE-VT for submit@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 ) id 1laPUt-00051o-R5 for bug-guix@gnu.org; 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 ) id 1laPUr-0005c6-EB for bug-guix@gnu.org; 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@elephly.net; dmarc=pass header.from= header.from= DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; t=1619298438; s=zoho; d=elephly.net; i=rekado@elephly.net; 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 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@elephly.net> 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@elephly.net; 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-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=2; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1619298493; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:mime-version:mime-version: content-type:content-type: content-transfer-encoding:content-transfer-encoding:resent-cc: resent-from:resent-sender:resent-message-id:list-id:list-help: list-unsubscribe:list-subscribe:list-post:dkim-signature; bh=9qBBAAr+tRTZNB+gK0gY2h6OelR7KIfexvApyGh0bnw=; b=UhvEDMidf7mMTD7mmDY/IAnkq3fRJ6GWMpIus1jeOZsAQ7TPQnKNOVij7IopmLnx11KMmg sK2kD2WHWGKMZWKNTMl8eaNafnw8a2XYcJ+XPDo1vdTONmzM0ZqpVjeYqdOGDEEaqc7pWU X9crdflKMjHMIkMFtq4GcRH3Wr4aklayhP7i77fQpVXv9AYeRAQqazI+Kx4JF11pSHrtxV ZlQxG4vrx5drNthZUFKl0jPUs6QVKQb4aiJWcBE+Q43HDF5NMtDdYQ2ngsBgqOHCpEoTfG kpCWRCu9VFz1dQMw92HG1ac1zq4QoYK8/gS5BFHlZhUTqoQaLeCj7VS5aVV+0Q== ARC-Seal: i=2; s=key1; d=yhetil.org; t=1619298493; a=rsa-sha256; cv=fail; b=N8auKxglzdplcLFlUcrS009MsT3955NqrRHiHCNmh702MgdOSDScA462BAsqaQdkQxjOkm YnQxd2bKu4pL7ykmze8f7NXfVBxUW8/K6rwp/Q/u2skPZ+jwCvWNN6o/pfBljGKr+3hz03 Imazkgab7Gy+e8v/mrnjLBd6UqT3e+vRqJzi6fignoH56BZKlbY+bGfAQjozlkYsbofP98 z+J74MCasxfz3Ek2UbWOyyUZiIuqCESIK0tCEpMvq8+whx1mbWQwwuMN+e/rJPvErfF9Rd u2tFvBWAogigUZ4ykC1iwJteuq3ybbBPXgu+K3ENH9eOPp7X23L8wCA5R3EMWw== ARC-Authentication-Results: i=2; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=elephly.net header.s=zoho header.b=Hn9hmuCa; arc=reject ("signature check failed: fail, {[1] = sig:zohomail.com:reject}"); dmarc=none; spf=pass (aspmx1.migadu.com: domain of bug-guix-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=bug-guix-bounces@gnu.org X-Migadu-Spam-Score: 0.56 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=elephly.net header.s=zoho header.b=Hn9hmuCa; arc=reject ("signature check failed: fail, {[1] = sig:zohomail.com:reject}"); dmarc=none; spf=pass (aspmx1.migadu.com: domain of bug-guix-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=bug-guix-bounces@gnu.org X-Migadu-Queue-Id: 7D72B8853 X-Spam-Score: 0.56 X-Migadu-Scanner: scn0.migadu.com X-TUID: ZXI7PCVMdpyL 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