unofficial mirror of bug-guix@gnu.org 
 help / color / mirror / Atom feed
* bug#51787: GC takes more than 9 hours on berlin
@ 2021-11-12 11:49 Mathieu Othacehe
  2021-11-12 19:17 ` Mathieu Othacehe
                   ` (2 more replies)
  0 siblings, 3 replies; 8+ messages in thread
From: Mathieu Othacehe @ 2021-11-12 11:49 UTC (permalink / raw)
  To: 51787


Hello,

On berlin, the daily GC command is still running whereas it was started
9 hours ago.

--8<---------------cut here---------------start------------->8---
guix processes
[...]
SessionPID: 37231
ClientPID: 37195
ClientCommand: /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/libexec/guix/guile \ /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/bin/guix gc -F10995116277760
--8<---------------cut here---------------end--------------->8---

and

--8<---------------cut here---------------start------------->8---
mathieu@berlin ~$ ps auxww|grep 37195
root      37195  0.0  0.0 183260 33440 ?        Sl   03:59   0:00 /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/libexec/guix/guile \ /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/bin/guix gc -F10995116277760
--8<---------------cut here---------------end--------------->8---

That's really problematic as it is blocking some other berlin services
such as Cuirass, which has 4564 packages in its fetch queue:

--8<---------------cut here---------------start------------->8---
mathieu@berlin ~$ less /var/log/cuirass-remote-server.log
[...]
2021-11-12T12:47:01 period update: 0 resumable, 0 failed builds.
2021-11-12T12:47:01 period update: 4564 items in the fetch queue.
--8<---------------cut here---------------end--------------->8---

Thanks,

Mathieu




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-12 11:49 bug#51787: GC takes more than 9 hours on berlin Mathieu Othacehe
@ 2021-11-12 19:17 ` Mathieu Othacehe
  2021-11-22  9:16 ` zimoun
  2021-11-23 17:48 ` Ludovic Courtès
  2 siblings, 0 replies; 8+ messages in thread
From: Mathieu Othacehe @ 2021-11-12 19:17 UTC (permalink / raw)
  To: 51787


> mathieu@berlin ~$ ps auxww|grep 37195
> root      37195  0.0  0.0 183260 33440 ?        Sl   03:59   0:00 /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/libexec/guix/guile \ /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/bin/guix gc -F10995116277760

I just killed this process, it was running for more than 16 hours.

Mathieu




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-12 11:49 bug#51787: GC takes more than 9 hours on berlin Mathieu Othacehe
  2021-11-12 19:17 ` Mathieu Othacehe
@ 2021-11-22  9:16 ` zimoun
  2021-11-23 17:48 ` Ludovic Courtès
  2 siblings, 0 replies; 8+ messages in thread
From: zimoun @ 2021-11-22  9:16 UTC (permalink / raw)
  To: Mathieu Othacehe; +Cc: 51787

Hi,

On Fri, 12 Nov 2021 at 12:51, Mathieu Othacehe <othacehe@gnu.org> wrote:

> On berlin, the daily GC command is still running whereas it was started
> 9 hours ago.
>
> --8<---------------cut here---------------start------------->8---
> guix processes
> [...]
> SessionPID: 37231
> ClientPID: 37195
> ClientCommand: /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/libexec/guix/guile \ /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/bin/guix gc -F10995116277760
> --8<---------------cut here---------------end--------------->8---
>
> and
>
> --8<---------------cut here---------------start------------->8---
> mathieu@berlin ~$ ps auxww|grep 37195
> root      37195  0.0  0.0 183260 33440 ?        Sl   03:59   0:00 /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/libexec/guix/guile \ /gnu/store/49vfv8l1j96bbd73ssbqanpnjz83arss-guix-1.3.0-11.014f1b6/bin/guix gc -F10995116277760
> --8<---------------cut here---------------end--------------->8---
>
> That's really problematic as it is blocking some other berlin services
> such as Cuirass, which has 4564 packages in its fetch queue:
>
> --8<---------------cut here---------------start------------->8---
> mathieu@berlin ~$ less /var/log/cuirass-remote-server.log
> [...]
> 2021-11-12T12:47:01 period update: 0 resumable, 0 failed builds.
> 2021-11-12T12:47:01 period update: 4564 items in the fetch queue.
> --8<---------------cut here---------------end--------------->8---

How is it possible to investigate?

Cheers,
simon




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-12 11:49 bug#51787: GC takes more than 9 hours on berlin Mathieu Othacehe
  2021-11-12 19:17 ` Mathieu Othacehe
  2021-11-22  9:16 ` zimoun
@ 2021-11-23 17:48 ` Ludovic Courtès
  2021-11-25 13:24   ` Christopher Baines
  2021-11-27 11:11   ` Ludovic Courtès
  2 siblings, 2 replies; 8+ messages in thread
From: Ludovic Courtès @ 2021-11-23 17:48 UTC (permalink / raw)
  To: Mathieu Othacehe; +Cc: 51787

Hello!

Mathieu Othacehe <othacehe@gnu.org> skribis:

> On berlin, the daily GC command is still running whereas it was started
> 9 hours ago.

Some data points:

  • I deployed on berlin the new daemon featuring the faster “deleting
    unused links” phase from <https://issues.guix.gnu.org/24937> on
    Nov. 20.

    However, that part runs after the GC lock has been released, so it’s
    not really relevant (but it is relevant to I/O load and GC
    efficiency.)

  • When discussing together with Chris Baines yesterday on IRC, we
    found that the sqlite WAL file was 8 GiB.  I later ran:

      PRAGMA wal_checkpoint(TRUNCATE);

    which emptied it immediately.  However, GC time wasn’t particularly
    different today.

  • ‘db.sqlite’ weighs in at 19 GiB (!) so perhaps there’s something to
    do, like the “VACUUM” thing maybe.  Chris?

  • Stracing the session’s guix-daemon process during GC suggests that
    most of the time goes into I/O from ‘db.sqlite’.  It’s not
    surprising because that GC phase is basically about browsing the
    database, but it does seem to take a little too long for each store
    item.

  • I haven’t checked recently but I recall that ‘guix gc --list-roots’
    (or its C++ counterpart, ‘findRoots’) would take ages on berlin
    because of all the GC roots Cuirass registers.  It may be that an
    hour or so goes into enumerating GC roots.

Collecting garbage,
Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-23 17:48 ` Ludovic Courtès
@ 2021-11-25 13:24   ` Christopher Baines
  2021-11-27 11:23     ` Ludovic Courtès
  2021-11-27 11:11   ` Ludovic Courtès
  1 sibling, 1 reply; 8+ messages in thread
From: Christopher Baines @ 2021-11-25 13:24 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: Mathieu Othacehe, 51787

[-- Attachment #1: Type: text/plain, Size: 3720 bytes --]


Ludovic Courtès <ludo@gnu.org> writes:

>   • When discussing together with Chris Baines yesterday on IRC, we
>     found that the sqlite WAL file was 8 GiB.  I later ran:
>
>       PRAGMA wal_checkpoint(TRUNCATE);
>
>     which emptied it immediately.  However, GC time wasn’t particularly
>     different today.

So, as I understand it, the WAL is made up of pages, and checking for
this db, I think they're the current default size of 4096 bytes.

sqlite> PRAGMA page_size;
4096

From looking at the code, the wal_autocheckpoint value is set to 40000:

    /* Increase the auto-checkpoint interval to 40000 pages.  This
       seems enough to ensure that instantiating the NixOS system
       derivation is done in a single fsync(). */
    if (mode == "wal" && sqlite3_exec(db, "pragma wal_autocheckpoint = 40000;", 0, 0, 0) != SQLITE_OK)
        throwSQLiteError(db, "setting autocheckpoint interval");

https://git.savannah.gnu.org/cgit/guix.git/tree/nix/libstore/local-store.cc#n253

This means you'd expect the WAL to be in the region of 40000*4096 bytes,
or ~160MB. Assuming the autocheckpointing is keeping up... it doesn't
look to be, since the file is now much larger than this.

As described here [1], the automatic checkpoints are PASSIVE ones, which
has the advantage of not interrupting any readers or writers, but can
also do nothing if it's being blocked by readers or writers.

1: https://www.sqlite.org/wal.html#application_initiated_checkpoints

What I've found while writing the Guix Build Coordinator, is that when
the service is busy (usually new builds being submitted, plus lots of
builds happening), the PASSIVE checkpoints aren't sufficient. To
supplement them, there's a regular check that looks at the size of the
WAL file, and runs a TRUNCATE checkpoint, which is a FULL checkpoint
(which blocks new writers), plus truncating the WAL file once it's
finished checkpointing the entire WAL. The truncating is mostly so that
it's easier to monitor the size of the WAL, by checking the size of the
file.

I feel like I need to defend SQLite at this point. Tuning the
configuration of a database to get acceptable performance is the norm, I
had to tune the PostgreSQL configuration for data.guix.gnu.org to
improve the performance. It's easier to get in to trouble with SQLite
because it's a lower level too, and requires you to actually initiate
things like checkpoints or periodic optimisation if you want them to
happen.

Unfortunately, I don't know enough about the internals of the daemon to
say anything specific though.

>   • ‘db.sqlite’ weighs in at 19 GiB (!) so perhaps there’s something to
>     do, like the “VACUUM” thing maybe.  Chris?

Doing a VACCUM might address some fragmentation and improve performance,
it's probably worth trying.

>   • Stracing the session’s guix-daemon process during GC suggests that
>     most of the time goes into I/O from ‘db.sqlite’.  It’s not
>     surprising because that GC phase is basically about browsing the
>     database, but it does seem to take a little too long for each store
>     item.

At least the way I've approached finding and fixing the poor performance
issues in the Guix Build Coordinator is through adding instrumentation,
so just recording the time that calling particular procedures takes, and
then logging if it's longer than some threshold.

Since this issue is about Cuirass, there's also the possibility of
avoiding the problems of a large store, by avoiding having a large
store. That's what bordeaux.guix.gnu.org does, and I thought it was part
of the plan for ci.guix.gnu.org (at least around a year ago)?

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-23 17:48 ` Ludovic Courtès
  2021-11-25 13:24   ` Christopher Baines
@ 2021-11-27 11:11   ` Ludovic Courtès
  1 sibling, 0 replies; 8+ messages in thread
From: Ludovic Courtès @ 2021-11-27 11:11 UTC (permalink / raw)
  To: Mathieu Othacehe; +Cc: 51787

Ludovic Courtès <ludo@gnu.org> skribis:

>   • Stracing the session’s guix-daemon process during GC suggests that
>     most of the time goes into I/O from ‘db.sqlite’.  It’s not
>     surprising because that GC phase is basically about browsing the
>     database, but it does seem to take a little too long for each store
>     item.

Stracing the client shows that the daemon spends several seconds on a
single store item occasionally:

--8<---------------cut here---------------start------------->8---
read(27, "gmlo\0\0\0\0", 8)             = 8 <0.363064>
read(27, "c\0\0\0\0\0\0\0", 8)          = 8 <0.000013>
read(27, "[95%] deleting '/gnu/store/p6r2jjy6frp682z3x94nvnmdh71p1p58-ecl-quicksearch-0.01"..., 104) = 104 <0.000010>
write(2, "[95%] deleting '/gnu/store/p6r2jjy6frp682z3x94nvnmdh71p1p58-ecl-quicksearch-0.01"..., 99) = 99 <0.000019>
read(27, "gmlo\0\0\0\0", 8)             = 8 <0.017863>
read(27, "^\0\0\0\0\0\0\0", 8)          = 8 <0.000019>
read(27, "[95%] deleting '/gnu/store/v6zd510kfmqd8j4w7q3zy9bid1fj96dk-shepherd-guix-daemon"..., 96) = 96 <0.000007>
write(2, "[95%] deleting '/gnu/store/v6zd510kfmqd8j4w7q3zy9bid1fj96dk-shepherd-guix-daemon"..., 94) = 94 <0.000012>
read(27, "gmlo\0\0\0\0", 8)             = 8 <5.861071>
read(27, "T\0\0\0\0\0\0\0", 8)          = 8 <0.000061>
read(27, "[95%] deleting '/gnu/store/0hpwig8cwdnzygjjzs9zjbxicvhif2vv-rust-bitvec-0.19.4.d"..., 88) = 88 <0.000087>
write(2, "[95%] deleting '/gnu/store/0hpwig8cwdnzygjjzs9zjbxicvhif2vv-rust-bitvec-0.19.4.d"..., 84) = 84 <0.000033>
--8<---------------cut here---------------end--------------->8---

(Notice ‘read’ taking 5.9s above.)

Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-25 13:24   ` Christopher Baines
@ 2021-11-27 11:23     ` Ludovic Courtès
  2021-12-03  9:45       ` Mathieu Othacehe
  0 siblings, 1 reply; 8+ messages in thread
From: Ludovic Courtès @ 2021-11-27 11:23 UTC (permalink / raw)
  To: Christopher Baines; +Cc: Mathieu Othacehe, 51787

Hi Chris,

Christopher Baines <mail@cbaines.net> skribis:

> So, as I understand it, the WAL is made up of pages, and checking for
> this db, I think they're the current default size of 4096 bytes.
>
> sqlite> PRAGMA page_size;
> 4096
>
> From looking at the code, the wal_autocheckpoint value is set to 40000:
>
>     /* Increase the auto-checkpoint interval to 40000 pages.  This
>        seems enough to ensure that instantiating the NixOS system
>        derivation is done in a single fsync(). */
>     if (mode == "wal" && sqlite3_exec(db, "pragma wal_autocheckpoint = 40000;", 0, 0, 0) != SQLITE_OK)
>         throwSQLiteError(db, "setting autocheckpoint interval");
>
> https://git.savannah.gnu.org/cgit/guix.git/tree/nix/libstore/local-store.cc#n253
>
> This means you'd expect the WAL to be in the region of 40000*4096 bytes,
> or ~160MB. Assuming the autocheckpointing is keeping up... it doesn't
> look to be, since the file is now much larger than this.
>
> As described here [1], the automatic checkpoints are PASSIVE ones, which
> has the advantage of not interrupting any readers or writers, but can
> also do nothing if it's being blocked by readers or writers.
>
> 1: https://www.sqlite.org/wal.html#application_initiated_checkpoints
>
> What I've found while writing the Guix Build Coordinator, is that when
> the service is busy (usually new builds being submitted, plus lots of
> builds happening), the PASSIVE checkpoints aren't sufficient. To
> supplement them, there's a regular check that looks at the size of the
> WAL file, and runs a TRUNCATE checkpoint, which is a FULL checkpoint
> (which blocks new writers), plus truncating the WAL file once it's
> finished checkpointing the entire WAL. The truncating is mostly so that
> it's easier to monitor the size of the WAL, by checking the size of the
> file.

OK.  That may well be what happens on berlin these days: the database is
kept busy all day long, so presumably checkpoints don’t happen and the
WAL file grows.

> I feel like I need to defend SQLite at this point. Tuning the
> configuration of a database to get acceptable performance is the norm, I
> had to tune the PostgreSQL configuration for data.guix.gnu.org to
> improve the performance. It's easier to get in to trouble with SQLite
> because it's a lower level too, and requires you to actually initiate
> things like checkpoints or periodic optimisation if you want them to
> happen.

Understood.  It’s really not about defending software X against Y, but
rather about finding ways to address the issues we experience.

>>   • ‘db.sqlite’ weighs in at 19 GiB (!) so perhaps there’s something to
>>     do, like the “VACUUM” thing maybe.  Chris?
>
> Doing a VACCUM might address some fragmentation and improve performance,
> it's probably worth trying.

Alright, let’s give it a try.

>>   • Stracing the session’s guix-daemon process during GC suggests that
>>     most of the time goes into I/O from ‘db.sqlite’.  It’s not
>>     surprising because that GC phase is basically about browsing the
>>     database, but it does seem to take a little too long for each store
>>     item.
>
> At least the way I've approached finding and fixing the poor performance
> issues in the Guix Build Coordinator is through adding instrumentation,
> so just recording the time that calling particular procedures takes, and
> then logging if it's longer than some threshold.

Yeah, that makes sense.  I think we always took these bits of the daemon
for granted because they’d been used on large stores even before Guix
existed.

> Since this issue is about Cuirass, there's also the possibility of
> avoiding the problems of a large store, by avoiding having a large
> store. That's what bordeaux.guix.gnu.org does, and I thought it was part
> of the plan for ci.guix.gnu.org (at least around a year ago)?

That’s indeed the case: the store is smaller than it used to be (but
still 27 TiB), it’s GC’d more aggressively than before, and instead we
rely on /var/cache/guix/publish for long-term storage.

Perhaps we should go further and keep the store smaller though.

Thanks for your feedback!

Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#51787: GC takes more than 9 hours on berlin
  2021-11-27 11:23     ` Ludovic Courtès
@ 2021-12-03  9:45       ` Mathieu Othacehe
  0 siblings, 0 replies; 8+ messages in thread
From: Mathieu Othacehe @ 2021-12-03  9:45 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: 51787


Hello,

> That’s indeed the case: the store is smaller than it used to be (but
> still 27 TiB), it’s GC’d more aggressively than before, and instead we
> rely on /var/cache/guix/publish for long-term storage.
>
> Perhaps we should go further and keep the store smaller though.

That's what I did with 93adf7aaa693d234ee13240e9f4ff22a2dfef599 on
maintenance. It increases the GC threshold to 15TiB. Let's see if it
brings some improvements.

Thanks,

Mathieu




^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2021-12-03  9:47 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-11-12 11:49 bug#51787: GC takes more than 9 hours on berlin Mathieu Othacehe
2021-11-12 19:17 ` Mathieu Othacehe
2021-11-22  9:16 ` zimoun
2021-11-23 17:48 ` Ludovic Courtès
2021-11-25 13:24   ` Christopher Baines
2021-11-27 11:23     ` Ludovic Courtès
2021-12-03  9:45       ` Mathieu Othacehe
2021-11-27 11:11   ` Ludovic Courtès

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).