From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp0 ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id JP2PArwdNmErYAAAgWs5BA (envelope-from ) for ; Mon, 06 Sep 2021 15:55:08 +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 EIs6ObsdNmH7aQAA1q6Kng (envelope-from ) for ; Mon, 06 Sep 2021 13:55:07 +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 8EA1D1261C for ; Mon, 6 Sep 2021 15:55:07 +0200 (CEST) Received: from localhost ([::1]:41784 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mNF5W-0002Be-LC for larch@yhetil.org; Mon, 06 Sep 2021 09:55:06 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:38786) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mNF5S-0002BU-Ii for guix-patches@gnu.org; Mon, 06 Sep 2021 09:55:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:40920) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mNF5S-0002RV-Ax for guix-patches@gnu.org; Mon, 06 Sep 2021 09:55:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mNF5S-00041r-9M for guix-patches@gnu.org; Mon, 06 Sep 2021 09:55:02 -0400 X-Loop: help-debbugs@gnu.org Subject: [bug#50040] [PATCH 0/2] publish: Always render nar/narinfo during backing. Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: guix-patches@gnu.org Resent-Date: Mon, 06 Sep 2021 13:55:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 50040 X-GNU-PR-Package: guix-patches X-GNU-PR-Keywords: patch To: Mathieu Othacehe Cc: 50040@debbugs.gnu.org Received: via spool by 50040-submit@debbugs.gnu.org id=B50040.163093647415443 (code B ref 50040); Mon, 06 Sep 2021 13:55:02 +0000 Received: (at 50040) by debbugs.gnu.org; 6 Sep 2021 13:54:34 +0000 Received: from localhost ([127.0.0.1]:52462 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mNF50-000411-AP for submit@debbugs.gnu.org; Mon, 06 Sep 2021 09:54:34 -0400 Received: from eggs.gnu.org ([209.51.188.92]:50820) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mNF4y-00040p-Cc for 50040@debbugs.gnu.org; Mon, 06 Sep 2021 09:54:32 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:40584) by eggs.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mNF4t-0001xr-4k for 50040@debbugs.gnu.org; Mon, 06 Sep 2021 09:54:27 -0400 Received: from [2001:660:6102:320:e120:2c8f:8909:cdfe] (port=47208 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mNF4s-0006f2-R4; Mon, 06 Sep 2021 09:54:27 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= References: <20210813102800.805-1-othacehe@gnu.org> <87sfz2j5ls.fsf@gnu.org> <87r1eaa7gu.fsf_-_@gnu.org> Date: Mon, 06 Sep 2021 15:54:23 +0200 In-Reply-To: <87r1eaa7gu.fsf_-_@gnu.org> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Tue, 31 Aug 2021 00:33:21 +0200") Message-ID: <87tuix7qsw.fsf_-_@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (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: guix-patches@gnu.org List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guix-patches-bounces+larch=yhetil.org@gnu.org Sender: "Guix-patches" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1630936507; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type: content-transfer-encoding:content-transfer-encoding:resent-cc: resent-from:resent-sender:resent-message-id:in-reply-to:in-reply-to: references:references:list-id:list-help:list-unsubscribe: list-subscribe:list-post; bh=c27D9JCtSZ5exDLHdkee/n5g8v06Pg45NCkT7815VmA=; b=rgUdvj2Ka+ExeZaer7KE2WrdAGh3m7JPHL66bgt5HH5eVMLBIgnxFseNMmHsKL37AwKwwr ruQtK3pezm3HC9m38QfrovHLpmUorDmOrMMW3UntgKdWEj3xOQzdt2TCSXDKrlXn8HhRWT EJk6E7hBNbC13rzIUY9MFkSUB/EjYoxRMsTEdpnwLzjEkh7A3Nb+6sXp4r+1Z2MPK8Ru+I pAkybViNUf+l3pOhkZgfq5/c4VJ1RVVB40qD60Hf7OIJCIaz6Kfog4xD66ERyNRdoX5rG1 2r5SyeHbfJRt8HAAdYGAshrmo7OUYJnvAHtNsyy53IYnbeD3nQiHymZZs9esKA== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1630936507; a=rsa-sha256; cv=none; b=d848xKahHbDmKmIMf3lEUGXyFfG12j5+dN0UAFDHsA/GkI320O4oC1/CI/2D2CxNbUiYAq RzXNLg1lfCOp8hwAU4tQApwgvTRuOMJHg6iPwTvZX67BNon2GHrOLsaLfwsF1qQpCiTKH/ 1LRPfig2Mies49dqNQ97qDtwWiYkfsjLHjjYzc0B7CSU+oN5USv83aq5ypGDeZLF97arBw K5ALo8g4YSLNAkLtINBFzdTBaE+60a9I907Qu9gUIx2PAg2TQ2x3CH3jk6WdJMLL21Z0B4 G84FJOo5gWNo7/ZGtiQcPCQdsDTW+ypWKQwR7vyzDtB43tboqisxSANdWN0vHg== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=none; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of guix-patches-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=guix-patches-bounces@gnu.org X-Migadu-Spam-Score: -2.92 Authentication-Results: aspmx1.migadu.com; dkim=none; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of guix-patches-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=guix-patches-bounces@gnu.org X-Migadu-Queue-Id: 8EA1D1261C X-Spam-Score: -2.92 X-Migadu-Scanner: scn0.migadu.com X-TUID: yN8VBcQ4rI0d Hi Mathieu, An additional data point: while stracing =E2=80=98guix publish=E2=80=99 on = berlin just now, I saw read(2) calls taking several seconds (!) to complete: --8<---------------cut here---------------start------------->8--- 14:22:07 openat(AT_FDCWD, "/var/cache/guix/publish/hashes/wcd9bci97i2zi52ay= 4vddvr1jx9w50kz", O_RDONLY) =3D 33 <0.000032> 14:22:07 fstat(33, {st_mode=3DS_IFREG|0666, st_size=3D60, ...}) =3D 0 <0.00= 0007> 14:22:07 lseek(33, 0, SEEK_CUR) =3D 0 <0.000006> 14:22:07 read(33, "/gnu/store/wcd9bci97i2zi52ay4vdd"..., 4096) =3D 60 <2.54= 0400> 14:22:10 read(33, "", 4096) =3D 0 <0.000014> 14:22:10 close(33) =3D 0 <0.000008> --8<---------------cut here---------------end--------------->8--- The load is indeed high right now: --8<---------------cut here---------------start------------->8--- ludo@berlin ~$ uptime 14:24:18 up 265 days 21:09, 1 user, load average: 10.61, 8.42, 8.00 --8<---------------cut here---------------end--------------->8--- There are a few ongoing builds, which could partly explain the high load (=E2=80=98guix-daemon=E2=80=99 shows up at the top in iotop): --8<---------------cut here---------------start------------->8--- ludo@berlin ~$ sudo guix processes|grep -C3 LockHeld SessionPID: 43868 ClientPID: 43515 ClientCommand: /gnu/store/6l9rix46ydxyldf74dvpgr60rf5ily0c-guile-3.0.7/bin/= guile --no-auto-compile /gnu/store/7rqj61dy660k0nw97w7657zbxnbdvg1g-update-= guix.gnu.org LockHeld: /gnu/store/srim97jxlxgyiday0j3hbq2z0w03iy3k-guix-web-site.lock ChildPID: 49648 ChildCommand: : /gnu/store/p9di786py35m4kxszf466wcla6jvq96h-guix-1.3.0-3.50= dfbbf/libexec/guix/guile \ /gnu/store/p9di786py35m4kxszf466wcla6jvq96h-guix= -1.3.0-3.50dfbbf/bin/guix substitute --query -- SessionPID: 61372 ClientPID: 58620 ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/= guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrp= vrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=3Dcuirass hos= t=3D/tmp 14259 LockHeld: /gnu/store/xdvzddg84by15s1c17k543b39c03jp8i-isl-0.23.drv.lock SessionPID: 61373 ClientPID: 58620 ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/= guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrp= vrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=3Dcuirass hos= t=3D/tmp 14259 LockHeld: /gnu/store/2wm7b9g07nxxhrnfcggw6ibdry65fpwb-xfce4-panel-4.16.3-bu= ilder.lock SessionPID: 61374 ClientPID: 58620 ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/= guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrp= vrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=3Dcuirass hos= t=3D/tmp 14259 LockHeld: /gnu/store/1jmidz4i70w3lczn99wgn19dksb0pzhv-pkg-config-0.29.2-bui= lder.lock SessionPID: 61375 ClientPID: 58620 ClientCommand: /gnu/store/hkyxill7pdyyrrqfxl4sydq5db0ljw17-guile-3.0.7/bin/= guile --no-auto-compile -e main -s /gnu/store/cm7hy2mpvk3av2gfg0gpfli11fgrp= vrs-cuirass-1.1.0-3.91e8b2e/bin/.cuirass-real evaluate dbname=3Dcuirass hos= t=3D/tmp 14259 LockHeld: /gnu/store/4j7s86xp7w5jgm84lr18szln1zpw36zd-static-binaries-tarba= ll-0.drv.lock --8<---------------cut here---------------end--------------->8--- The =E2=80=98mumi worker=E2=80=99 process also seems to be doing a lot of I= /O and using quite a bit of CPU (presumably allocating a lot). Its =E2=80=98perf=E2=80= =99 profile is like this: --8<---------------cut here---------------start------------->8--- 2.62% .mumi-real libguile-3.0.so.1.1.1 [.] scm_ilength 1.20% .mumi-real libguile-3.0.so.1.1.1 [.] scm_getc 1.12% .mumi-real libgc.so.1.4.3 [.] GC_add_to_black_list_norma= l.part.4 1.06% .mumi-real libgc.so.1.4.3 [.] GC_build_fl 0.98% .mumi-real libgc.so.1.4.3 [.] GC_reclaim_clear 0.97% .mumi-real libguile-3.0.so.1.1.1 [.] get_callee_vcode 0.91% .mumi-real libgc.so.1.4.3 [.] GC_generic_malloc_many 0.90% .mumi-real libguile-3.0.so.1.1.1 [.] peek_byte_or_eof 0.78% .mumi-real [JIT] tid 62601 [.] 0x00007f886964804d --8<---------------cut here---------------end--------------->8--- Food for thought=E2=80=A6 Ludo=E2=80=99.