From debbugs-submit-bounces@debbugs.gnu.org Fri Dec 10 01:24:26 2021 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 To: Ludovic =?utf-8?Q?Court=C3=A8s?= Subject: Re: bug#51787: GC takes more than 9 hours on berlin 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-Spam-Score: -2.3 (--) X-Debbugs-Envelope-To: 51787 Cc: 51787@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -3.3 (---) 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