From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp12.migadu.com ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms5.migadu.com with LMTPS id UGDvD+CDlGLvUwEAbAwnHQ (envelope-from ) for ; Mon, 30 May 2022 10:44:16 +0200 Received: from aspmx1.migadu.com ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp12.migadu.com with LMTPS id GFPQD+CDlGJXBQEAauVa8A (envelope-from ) for ; Mon, 30 May 2022 10:44:16 +0200 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 95E293D866 for ; Mon, 30 May 2022 10:44:15 +0200 (CEST) Received: from localhost ([::1]:44798 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1nvb0X-0000nn-WB for larch@yhetil.org; Mon, 30 May 2022 04:44:14 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:48514) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nvb0M-0000nL-Ie for bug-guix@gnu.org; Mon, 30 May 2022 04:44:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:48801) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1nvb0M-0002MF-9Q for bug-guix@gnu.org; Mon, 30 May 2022 04:44:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1nvb0M-0000wA-4h for bug-guix@gnu.org; Mon, 30 May 2022 04:44:02 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#55721: Low cache usage in the presence of grafts Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Mon, 30 May 2022 08:44:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: report 55721 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: 55721@debbugs.gnu.org X-Debbugs-Original-To: bug-guix@gnu.org Received: via spool by submit@debbugs.gnu.org id=B.16539002343579 (code B ref -1); Mon, 30 May 2022 08:44:01 +0000 Received: (at submit) by debbugs.gnu.org; 30 May 2022 08:43:54 +0000 Received: from localhost ([127.0.0.1]:42698 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1nvb0E-0000vf-4i for submit@debbugs.gnu.org; Mon, 30 May 2022 04:43:54 -0400 Received: from lists.gnu.org ([209.51.188.17]:52280) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1nvb09-0000vV-K8 for submit@debbugs.gnu.org; Mon, 30 May 2022 04:43:53 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:48462) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nvb09-0000mo-Ci for bug-guix@gnu.org; Mon, 30 May 2022 04:43:49 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:33520) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nvb08-0002KY-Ih for bug-guix@gnu.org; Mon, 30 May 2022 04:43:49 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:Date:Subject:To:From:in-reply-to: references; bh=jEeq2IgyuhlSL6RWD794ydlSYbLNcQTY2rf8zffEoDo=; b=F2MBNz9mlZbOPY BrkDsWVlubQzAMK8tks8DW5FiKf+Wekjuotm1963n4+AF2TFSx1yCn4z0fVRb1rJqP6+I92JsiYCM blp9U4SqVkgYQloHH1u7WlV7l0uxnShxPuXAgpCCAKkGGKShR0SEh0rgyxsSLyVBAkEbAKUJdFhAW vv6+lf0mNBEcu3SmbAWXe0324opi9fJSn56alh+Pi+cj8zEGhLHdcC0XJxsp8HnN/DVEwbs3o5Wj/ uuqUW8mt22gzLFEpc2GC0AQ0V1a7NtIFJ/afRT4YOwpkKya3BEMFZkyiasiRXfDNjlDScDQutxjgm Q9HT6eQV+eSKknw5heFw==; Received: from [193.50.110.143] (port=37288 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nvb08-0003Su-1h for bug-guix@gnu.org; Mon, 30 May 2022 04:43:48 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= X-URL: http://www.fdn.fr/~lcourtes/ X-Revolutionary-Date: Primidi 11 Prairial an 230 de la =?UTF-8?Q?R=C3=A9volution, ?= jour de la Fraise X-PGP-Key-ID: 0x090B11993D9AEBB5 X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4 0CFB 090B 1199 3D9A EBB5 X-OS: x86_64-pc-linux-gnu Date: Mon, 30 May 2022 10:43:46 +0200 Message-ID: <87y1yj5s1p.fsf@inria.fr> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.1 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable 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 X-Migadu-To: larch@yhetil.org X-Migadu-Country: US ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1653900255; 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=jEeq2IgyuhlSL6RWD794ydlSYbLNcQTY2rf8zffEoDo=; b=EkOkw4G8ONdShE5OUAMxPEM6/BkQru9ou3+B8KYaaSu3mQftdOPOpZJQaIB+NwCPVAQTto ON0W32Uy+4zIntJ7NfYMdUi+DwXKq4f4SNZUaQauyzPQT5+2Exg54lGl2AXiUm/+Q20yCZ OY3lIi9NFAtsgx3GWtprOPDF7IlvZpU4uo697Cd3STKNBK/PqAdPsznRGmRoiIIx0HfDc8 lrBm3MRKB+8MFPcORwH0iO0nwB76suspMaCBr92hk75CIELKMGvmAtcazymo0/Daki9pvO uQdTOxHgcqGQ9MINVvMcQpDmvDWRllCqr+bYSQDEzVzGkz/pFZoSNc7daeA0hw== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1653900255; a=rsa-sha256; cv=none; b=PBEPvKH8Erlm9s9bkc5N3AgzbmhSPgsDiEkEn85j/DT5w97aLdd+fNPNOhl67agugCZtJg LNKjAh8BDW5cu+S1gugyelzSb9OUP+xGLFcAP2uOMElKJtxxiXT1tTNlZ+8A7dh2Y0AT74 +eKoBHqlvYfihaKIJ1yDez4HTS7o0nksdxiYbFtWLwmqJ5wnN5JNnezW623rJvhNNRk7n9 2wmOjLmHFkKIQl4rrErEaDNAJGxJ6PJnOO6taYVMuGcMiYQ/ezlCMlZiSDr7KVmJQleC9Y JUj9UZ/zK2JlZlPm6y0Eqzc9jilDqVlkggMn3OyRlovYmrzmNA8kGPGv8VIokw== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=F2MBNz9m; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Spam-Score: -4.23 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=F2MBNz9m; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Queue-Id: 95E293D866 X-Spam-Score: -4.23 X-Migadu-Scanner: scn0.migadu.com X-TUID: q+Ro6Y2nBwOf The use of per-session caches in the presence of grafts is low=E2=80=94specifically when =E2=80=9Cbuild handlers=E2=80=9D are invoked. This is illustrated by the example below: =E2=80=A2 the first run invokes the build handler of =E2=80=98map/accumul= ate-builds=E2=80=99 to download polkit (which has a =E2=80=98replacement=E2=80=99) and then= proceeds (the end result was already in store), taking no less than 6m of CPU time; =E2=80=A2 the second run doesn=E2=80=99t have to hop through the build ha= ndler since everything is already in store and its takes 24s of CPU time. --8<---------------cut here---------------start------------->8--- $ guix gc -D $(guix build polkit --no-grafts) finding garbage collector roots... [0 MiB] deleting '/gnu/store/8vsfk8312m5p461wl4dq5lxjagfbwfhz-polkit-0.121' deleting `/gnu/store/trash' deleting unused links... note: currently hard linking saves 72385.53 MiB $ time GUIX_PROFILING=3D"rpc reference-cache derivation-graft-cache" ./pre-= inst-env guix system vm gnu/system/examples/desktop.tmpl=20 0.2 MB will be downloaded polkit-0.121 198KiB = 1.4MiB/s 00:00 [##################] 100.0% /gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh Reference Cache: fresh caches: 8 lookups: 77581 hits: 52890 (68.2%) cache size: 838 entries Derivation graft cache: fresh caches: 39 lookups: 704635 hits: 627819 (89.1%) cache size: 2946 entries Remote procedure call summary: 33071 RPCs built-in-builders ... 1 query-substitutable-path-infos ... 2 build-things ... 2 add-to-store/tree ... 56 valid-path? ... 59 add-to-store ... 373 add-text-to-store ... 7887 query-references ... 24691 real 5m6.727s user 6m59.438s sys 0m1.633s $ time GUIX_PROFILING=3D"rpc reference-cache derivation-graft-cache" ./pre-= inst-env guix system vm gnu/system/examples/desktop.tmpl=20 /gnu/store/sk1571rnh5jl2ilp0v1k8bqwsdrngwxy-run-vm.sh Reference Cache: fresh caches: 1 lookups: 2988 hits: 2150 (72.0%) cache size: 838 entries Derivation graft cache: fresh caches: 5 lookups: 28323 hits: 25376 (89.6%) cache size: 2946 entries Remote procedure call summary: 9159 RPCs query-substitutable-path-infos ... 1 build-things ... 1 built-in-builders ... 1 valid-path? ... 2 add-to-store/tree ... 56 add-to-store ... 373 query-references ... 838 add-text-to-store ... 7887 real 0m17.304s user 0m24.620s sys 0m0.273s $ git log |head commit acb08304c862d65679086a9f160240bfd598289d Author: Wiktor Zelazny Date: Wed May 18 16:20:30 2022 +0000 gnu: Add python-gpy. =20=20=20=20 * gnu/packages/python-science.scm (python-gpy): New variable. =20=20=20=20 Signed-off-by: Ludovic Court=C3=A8s --8<---------------cut here---------------end--------------->8--- >From the first run we can see that the reference cache (used by =E2=80=98references/cached=E2=80=99, itself called form (guix grafts)) is a= lmost unused since we end up making 24K =E2=80=98query-references=E2=80=99 RPCs for only= 838 entries in that cache, meaning the same work is done ~29 times. My hypothesis is that this is a regression introduced by the switch to =E2=80=9Cfunctional caches=E2=80=9D in =E2=80=98core-updates=E2=80=99 back = in 9e5812ac59b01ff011ec0c5b0f437dfe85d6fcc7. Ludo=E2=80=99.