From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp1 ([2001:41d0:2:bcc0::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id uPkMKAbzsmE9QwAAgWs5BA (envelope-from ) for ; Fri, 10 Dec 2021 07:26:14 +0100 Received: from aspmx1.migadu.com ([2001:41d0:2:bcc0::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp1 with LMTPS id sNC1IwbzsmGgfwAAbx9fmQ (envelope-from ) for ; Fri, 10 Dec 2021 06:26:14 +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 40D9F2C58D for ; Fri, 10 Dec 2021 07:26:14 +0100 (CET) Received: from localhost ([::1]:32846 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mvZMC-0004hV-Vs for larch@yhetil.org; Fri, 10 Dec 2021 01:26:13 -0500 Received: from eggs.gnu.org ([209.51.188.92]:36740) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvZL5-0004fd-Gz for bug-guix@gnu.org; Fri, 10 Dec 2021 01:25:04 -0500 Received: from debbugs.gnu.org ([209.51.188.43]:33759) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mvZL4-0005kZ-LU for bug-guix@gnu.org; Fri, 10 Dec 2021 01:25:02 -0500 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mvZL4-0001lU-Br for bug-guix@gnu.org; Fri, 10 Dec 2021 01:25:02 -0500 X-Loop: help-debbugs@gnu.org Subject: bug#51787: GC takes more than 9 hours on berlin Resent-From: Mathieu Othacehe Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Fri, 10 Dec 2021 06:25:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 51787 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Ludovic =?UTF-8?Q?Court=C3=A8s?= Received: via spool by 51787-submit@debbugs.gnu.org id=B51787.16391174666736 (code B ref 51787); Fri, 10 Dec 2021 06:25:02 +0000 Received: (at 51787) by debbugs.gnu.org; 10 Dec 2021 06:24:26 +0000 Received: from localhost ([127.0.0.1]:45305 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mvZKT-0001kZ-LS for submit@debbugs.gnu.org; Fri, 10 Dec 2021 01:24:25 -0500 Received: from eggs.gnu.org ([209.51.188.92]:35826) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mvZKR-0001kM-9z for 51787@debbugs.gnu.org; Fri, 10 Dec 2021 01:24:24 -0500 Received: from [2001:470:142:3::e] (port=43114 helo=fencepost.gnu.org) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvZKL-0005h1-Ta; Fri, 10 Dec 2021 01:24:17 -0500 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:In-Reply-To:Date:References:Subject:To: From; bh=sqmiVqIAwj+IyqMPVIM7phDU/I4q3A1Acdo4zXzSmGo=; b=FLBy/2tkBklCPKlOBVbt dTGTdjLT19OcAJkVJltH8KnFH0PQr1aoYzaxf7fCcBUSnMVlJwL2cewJuxy80wc85E51l+kOUxsf5 0LwjPmQJNVdsK2D3Z8vKiYX+SgxuSztSFfXSlVjmDrhar5ucZBrdBB9CFzQplS54Mjv7C65MdUj3V 4As4Z4BJ6+HINU8r6w5sjbHlUv4hhCSMNd8eFFF/23RGelTjM2WDm5jYDcr61npemGiscMjDSeNvS 52NTpV1kSfHc0nSgnArYWhI5kxXCy8MynbxJtsPfIKtwuUiR6P1VSxizrunHAGjGfxCjx1PY26SEI Myc+yEn3reRQvQ==; Received: from [2a01:e0a:19b:d9a0:2ddb:d3d2:32e8:d31a] (port=33052 helo=meije) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvZKL-0001xQ-R3; Fri, 10 Dec 2021 01:24:18 -0500 From: Mathieu Othacehe References: <87o86pegr3.fsf@gnu.org> <87zgpuhig7.fsf@gnu.org> <87wnkv15k3.fsf@cbaines.net> <87zgpp971n.fsf@gnu.org> <87pmqet419.fsf@gnu.org> Date: Fri, 10 Dec 2021 07:24:15 +0100 In-Reply-To: <87pmqet419.fsf@gnu.org> (Mathieu Othacehe's message of "Fri, 03 Dec 2021 10:45:54 +0100") Message-ID: <87czm57zao.fsf@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain 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: , Cc: 51787@debbugs.gnu.org Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1639117574; 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: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: dkim-signature; bh=sqmiVqIAwj+IyqMPVIM7phDU/I4q3A1Acdo4zXzSmGo=; b=KYVoqSoPm0Mk8Y3KVUHZVhi8IlkCTH+j9qBf8twpD5hswADjwlKQSJRCuqaL/A8nwcWKRI LVhEA79bUCL3nuP/AHWgdJrs2flYQZ3HvXPg0b4j/+27FDVjGMsUBVvgNPblOWG0+zzKyZ B4Mj28O0RqXOKf+w6zjnNJKT3kUMSRhkf5lz+ywFDcbmmq6fJFIp5QXNbMSc6C4s83myAQ 1pDDZB0Gi7hdX8yNxNM+TfAfMg3z6wDlWXT/F+q6Bg6R5aY+vaL9VofTtg6AQsnMYAnjCz 2lkCgxTiSziRD0qP4Kfr2rvIHvDEuEM5KqeenSEuIF2fzLRpi15403hMwPeGew== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1639117574; a=rsa-sha256; cv=none; b=nVTY5CJ+hAgfSrW7/NzTwtFQe7PvO3zRQ9K1w+KoXZWjcB6wj8tLz7SDvazWeJHXEprKWK uJ/dqJVe6rW41zATre/06j0ZPv6RFqTMb5rJC3R67JY+HzNHCQ2bUK1PghvTpsl8B/2VJc 9fg3hsFVnTpv1DVoniFy/a8CXT/cPDZ+9Qy1B8FPSOrUhQCW0RzramwQ4fAvmnrV4/gs1/ C0gtjOcoa3f0paRj/VPmjuXwM5oNNyYbxnTZSmieinH29TSSS7yTSac4daCeI7hMkQSoXm duoHrgmW052dz3u9a533nU3XdczNPel/gBBOMjAIb0AMV+Ixp5UIKNJ70EPZEg== 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="FLBy/2tk"; 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: -3.66 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b="FLBy/2tk"; 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: 40D9F2C58D X-Spam-Score: -3.66 X-Migadu-Scanner: scn1.migadu.com X-TUID: tkjeNONKdJHl Hey, New GC recap. The process that has been started yesterday at 04:00 is still running. I killed the GC that was started today at 04:00 to keep things clear. >From yesterday 11:00 when I started monitoring it to today when I'm writing this email, 20 hours have elapsed and the GC is still in the same phase: removing recursively the /gnu/store/trash directory content. It corresponds to the following snippet for those of you who would like to have a look to the corresponding code: --8<---------------cut here---------------start------------->8--- if (state.shouldDelete) { if (pathExists(state.trashDir)) deleteGarbage(state, state.trashDir); // > 20 hours try { createDirs(state.trashDir); } catch (SysError & e) { if (e.errNo == ENOSPC) { printMsg(lvlInfo, format("note: can't create trash directory: %1%") % e.msg()); state.moveToTrash = false; } } }--8<---------------cut here---------------end--------------->8--- This is an early phase of the garbage collecting, where store items that were moved to the trash directory by previous GC runs are effectively removed. Stracing the guix-daemon process associated with the GC process clearly shows what's going on: --8<---------------cut here---------------start------------->8--- chmod("/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/rust-syntex-0.58.1", 040755) = 0 <0.000012> openat(AT_FDCWD, "/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/rust-syntex-0.58.1", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 13 <0.000011> fstat(13, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000007> getdents64(13, 0x397a510 /* 3 entries */, 32768) = 80 <0.005059> getdents64(13, 0x397a510 /* 0 entries */, 32768) = 0 <0.000007> close(13) = 0 <0.000008> statx(AT_FDCWD, "/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/rust-syntex-0.58.1/index.html", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_MODE|STATX_NLINK|STATX_SIZE, {stx_mask=STATX_BASIC_STATS|0x1000, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=10265, ...}) = 0 <0.000023> unlink("/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/rust-syntex-0.58.1/index.html") = 0 <0.000013> rmdir("/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/rust-syntex-0.58.1") = 0 <0.000028> statx(AT_FDCWD, "/gnu/store/trash/272ibwb38i0kcbcl3n9v0ka1rsmd1104-guix-web-site/de/packages/lofreq-2.1.5", AT_STATX_ --8<---------------cut here---------------end--------------->8--- Several syscalls are involved to clean the trash directory: chmod, openat, statx, unlink and rmdir. This does not seem particularly wrong. What is problematic though is that in 20 hours, the free space has bumped from 9.6T to 9.7T in the store partition. As the GC lock is preventing most of Berlin services from running, almost all the machine IO is dedicated to removing this directory, as shown by iotop. I'm not sure to understand why this removing process is so long, but if someone has an idea, I'm all ears. In the meantime, I plan to let the GC run and keep monitoring it. Thanks, Mathieu