GNU bug report logs - #51787
GC takes more than 9 hours on berlin

Previous Next

Full log

View this message in rfc822 format

From: Mathieu Othacehe <othacehe <at> gnu.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 51787 <at> debbugs.gnu.org
Subject: bug#51787: GC takes more than 9 hours on berlin
Date: Fri, 10 Dec 2021 07:24:15 +0100

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

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.