GC takes more than 9 hours on berlin

Hello,

On berlin, the daily GC command is still running whereas it was started

9 hours ago.

and

That's really problematic as it is blocking some other berlin services

such as Cuirass, which has 4564 packages in its fetch queue:

Thanks,

Mathieu

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

Mathieu

Hi,

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

How is it possible to investigate?

Cheers,

simon

severity 51787 important

quit

Hello!

Mathieu Othacehe <othacehe@gnu.org> skribis:

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’.

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

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");

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.

Doing a VACCUM might address some fragmentation and improve performance,

it's probably worth trying.

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)?

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

Stracing the client shows that the daemon spends several seconds on a

single store item occasionally:

(Notice ‘read’ taking 5.9s above.)

Ludo’.

Hi Chris,

Christopher Baines <mail@cbaines.net> skribis:

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.

Understood. It’s really not about defending software X against Y, but

rather about finding ways to address the issues we experience.

Alright, let’s give it a try.

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.

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’.

Hello,

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

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:

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_

Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

This is the first time GC runs since we’ve increased the threshold from

10 TiB to 15 TiB free. There are at least 5 more TiBs to delete than

usual, so it’s expected to take more time.

Still, I’m surprised a mere ‘rm -rf’ can take this long. ‘strace -T’ on

the child guix-daemon process doesn’t reveal anything obviously wrong,

pause times or similar.

Ludo’.

Hey,

I noticed that the process isn't around anymore. Did anyone killed it,

or maybe it just crashed? Also noticed some trash removing commands were

running. Regardless of the root cause of the problem, getting rid of the

trash directory before the next evaluation seems like a good idea.

Thanks,

Mathieu

Hey,

I noticed that the process isn't around anymore. Did anyone killed it,

or maybe it just crashed? Also noticed some trash removing commands were

running. Regardless of the root cause of the problem, getting rid of the

trash directory before the next evaluation seems like a good idea.

Thanks,

Mathieu

I have not touched it.

--

Ricardo

Mathieu Othacehe <othacehe@gnu.org> skribis:

Yeah I don’t know what happened to the GC process but it disappeared

earlier today. Then I started things like this:

unshare -m sh -c 'mount --bind -o remount,rw /gnu/store; rm -rf --one-file-system /gnu/store/trash/[abc]*'

which is equally slow (perhaps slightly slower: it seems to do more

syscalls per file to remove than the guix-daemon code).

Anyway, I’ll let it run hoping it’ll be done by the next GC.

Ludo’.

Hey,

OK, thanks. Looks it just finished removing the trash directory

content. I started a GC process from my session to monitor it closely.

Mathieu

Hey,

Daily GC recap:

approximately 24 hours, that are now in the /gnu/store/trash

directory.

are removed at the same rate than on the previous days, it will take

days/months to delete them all.

locking. I think it shouldn't be too hard to port it to our fork or

maybe rewrite the process in Guile while we are at it.

That will not fix the slow hard-drives issues though.

Thanks,

Mathieu

On 2021-12-12 18:09, Mathieu Othacehe wrote:

While discussing this issue on IRC I came up with some idea:

'rmrfd' a system daemon that deletes huge trees in the background where

'-rf' stands for --really --fast :)

Actually this is an use case that happens for on my backup system too.

With that idea I just started coding and ran some experiments. For me

this looks quite feasible now and I will continue next days on this

small project. Any feedback or help would be welcomed!

The initial ideas and experiments are at https://github.com/cehteh/rmrfd

Note that the important part is that it will put some efforts into

freeing as much space as possible at begin of the freeing process,

Unlike just 'rm -rf' where space may only freed really late when the

last link count of the data goes to zero.

Cheers

Christian

On 2021-12-12 18:09, Mathieu Othacehe wrote:

On another note: when 'guix gc' determines that objects are dead, are

they really dead then or can it be that they are 'locally' dead but in

case the store serves as substitutes/offload server some external

clients may still request dead objects?

In the either case would make sense to run the GC more frequently, but

for the later case a --min-age option to preserve objects that just

died recently could be helping. Further it may consider the atime of

objects for removal.

And finally while I had this Idea: You mount the

guix store with 'relatime' or 'nodiratme', if not that could explain

the slow deletion process as well!

Christian

Hey,

New day, new benchmark. Berlin has two hard drives, which are roughly

used this way:

/dev/sda -> / (916G)

/dev/sdb -> /gnu (37T)

I ran the fio benchmark tool on both of them. See the reports

attached, and the following summary:

I'm not sure how slow those figures are relatively to the hard drives

technologies. Ricardo, any idea about that?

My own NVME hard drive has 294MiB/s read and 98.1MiB/s write with the

same test in comparison.

I also tried to benchmark file removal this way, but this is not really

conclusive:

Thanks,

Mathieu

Hi Mathieu,

sda consists of two local hard disks that are combined to a RAID.

Here are the disk details:

sdb is an external storage array (Dell MD3400) filled with 10 hard disks

(SAS) in a RAID 10 configuration (36.36 TB effective capacity). There

are two hot spares that are currently unassigned. They are used

automatically when the RAID is degraded. The two RAID controllers have

read and write caches enabled. The enclosure has two redundant host

interfaces.

Berlin has two host based adapter cards of which *one* is connected to

the array. Why only one? Because we don’t have multipathd configured

so that the system could *boot* off the external array with multipath.

Without multipath the storage would appear as one disk device per card,

but it would not be safe to mount them both at the same time.

If we wanted to make use of the redundant connection here: figure out

how to add multipathd to the initrd and set up multipath *before*

handing off control to Linux. This would effectively double our

bandwidth to the storage.

My guess is that we’re not even close to saturating the available

bandwidth.

It seems awfully slow. Especially performance of sda is abysmal: this

is a local disk. sdb is the fancy external disk array that’s hooked up

to two HBA cards. It should not perform *better* than sda.

I’ll run this on a few of the build nodes to get some more comparisons.

--

Ricardo

Ricardo Wurmus <rekado@elephly.net> writes:

I ran “guix deploy” for hydra-guix-107, a node that was bought at the

same time as the one that is now the head node of ci.guix.gnu.org. I

copied over a current Guix and installed “fio”

(/gnu/store/qs9cyy5s95n2fbjmxs48iccqvsvj6wxr-fio-3.28/bin/fio) there.

Here’s the output:

Here sda is RAID of two SSDs:

--

Ricardo

Hey,

Mmh interesting, I also have a x10 speed up on sdb by increasing the

block size from 4k to 512k. I'm not sure what conclusion should we draw

from this observation.

In particular for our most urging matter, /gnu/store/trash

removal. Moving to a faster hard drive would definitely help here, but I

still don't understand if that disk performance regression comes from

Linux, the file-system fragmentation, or the disk itself.

Wooh that's fast! On test could be to copy the /gnu/store/trash content

to the SAN an observe how long that it takes for this operating to

complete.

Thanks for your support on that complex topic :)

Mathieu

Mathieu Othacehe <othacehe@gnu.org> writes:

As a general rule, we want the block size to match that of the

configured disk layout — if we care about getting the best numbers in

our benchmarks. With real workloads things are always going to be

slower anyway.

Do you mean time the copy or time the removal from that storage? You

know what, I’ll time both. I’ll need to get more space first. I think

the trash directory is larger than the 500G that I got for testing the

SAN.

Hey, I’m just happy neither of us has to do this alone. Thank you!

--

Ricardo

On +2021-12-20 17:59:33 +0100, Mathieu Othacehe wrote:

also might be interesting to copy to /dev/null

to see read rate alone on /gnu/store?

--

Regards,

Bengt Richter

My colleague extended the SAN slice to 5TB for more realistic testing.

I formatted the disk with btrfs, and mounted it like this:

mount /dev/sdd /mnt_test/

Then I ran the test with block size 512k:

Because this is fun I reran it with the same arguments:

Then I mounted with compression and space cache:

mount /dev/sdd -o compress-force=zstd,space_cache=v2 /mnt_test/

The numbers don’t differ much at all.

I then erased the file system and again put on a big ext4:

No idea why btrfs performs so much worse in comparison.

I’ll copy over /gnu/store/trash next.

--

Ricardo

Hey,

Yeah I meant removal time :) I found this article[1] that suggests that

over time the ext4 fragmentation can cause a performance drop that is

very noticeable on hard drives.

I'm trying to determine how fragmented is the sdb1 file-system, by

running e4defrag and e2freefrag[2], but I'm not sure if they will

complete soon.

Copying and removing /gnu/store/trash on the SAN will be interesting but

the ultimate test would be to be able to re-create the ext4 file-system

directly on Berlin's sdb drive to evaluate the fragmentation role in

this funny business.

Thanks,

Mathieu

[1]: https://www.usenix.org/system/files/hotstorage19-paper-conway.pdf

[2]: https://cromwell-intl.com/open-source/performance-tuning/file-systems.html

Today we discovered a few more things and discussed them on IRC. Here’s

a summary.

/var/cache sits on the same storage as /gnu. We mounted the 5TB ext4

file system that’s hosted by the SAN at /mnt_test and started copying

over /var/cache to /mnt_test/var/cache. Transfer speed was considerably

faster (not *great*, but reasonably fast) than the copy of

/gnu/store/trash to the same target.

This confirmed our suspicions that the problem is not with the storage

array but due to the fact that /gnu/store/trash (and also /gnu/store)

is an extremely large, flat directory. /var/cache is not.

Here’s what we do now: continue copying /var/cache to the SAN, then

remount to serve substitutes from there. This removes some pressure

from the file system as it will only be used for /gnu. We’re

considering to dump the file system completely (i.e. reinstall the

server), thereby emptying /gnu, but leaving the stash of built

substitutes in /var/cache (hosted from the faster SAN).

We could take this opportunity to reformat /gnu with btrfs, which

performs quite a bit more poorly than ext4 but would be immune to

defragmentation. It’s not clear that defragmentation matters here. It

could just be that the problem is exclusively caused by having these

incredibly large, flat /gnu/store, /gnu/store/.links, and

/gnu/store/trash directories.

A possible alternative for this file system might also be XFS, which

performs well when presented with unreasonably large directories.

It may be a good idea to come up with realistic test scenarios that we

could test with each of these three file systems at scale.

Any ideas?

--

Ricardo

On Tue, Dec 21, 2021 at 06:26:03PM +0100, Ricardo Wurmus wrote:

My impression was that btrfs could also become fragmented. At least,

btrfs-progrs includes a command for defragmenting. Or do I

misunderstand?

Hey,

Nice summary :)

We could compare xfs, btrfs and ext4 performances on a store subset,

1TiB for instance that we would create on the SAN. Realistic test

scenario could be:

- Time the copy of new items to the test store.

- Time the removal of randomly picked items from the test store.

- Time the creation of nar archives from the test store.

That will allow us to choose the file-system that has the best

performances for our use-case, regardless of fragmentation.

Now fragmentation may or may not be a problem as you mentioned. What we

could do is repeat the same tests but on a test store that is created

and removed N times, to simulate file-system aging.

This is more or less what is done in this article[1] by "git pulling" N

times a repository and testing read performances. For them btrfs > xfs >

ext4 in term of performances, but we might draw different conclusions

for our specific use case.

Do you think it is realistic? If so, we can start working on some test

scripts.

Thanks,

Mathieu

[1]: https://www.usenix.org/system/files/hotstorage19-paper-conway.pdf

Hi Ricardo,

TL;DR: re: "Any ideas?" :)

Read this [0], and consider how file systems may be

interacting with with SSD wear-leveling algorithms.

Are some file systems dependent on successful speculative

transaction continuations, while others might slow down

waiting for signs that an SSD controller has committed one

of ITS transactions, e.g. in special cases where the user or

kernel file system wants to be sure metadata is

written/journaled for fs structural integrity, but maybe

cares less about data?

I guess this difference might show up in copying a large

file over-writing the same target file (slower) vs copying

to a series of new files (faster).

What happens if you use a contiguous file as swap space?

Or, if you use anonymous files as user data space buffers,

passing them to wayland as file handles, per its protocol,

can you do better than ignoring SSD controllers and/or

storage hardware altogether?

Reference [0] is from 2013, so probably much has happened

since then, and the paper mentions (which has probably not

gotten better), the following, referring to trade secrets

giving one manufacturer ability to produce longer-lasting

SSDs cheaper and better than others ...

Well, maybe you will have to parameterize your file system

tuning with manufacturer ID and SSD controller firmware

version ;/

Mvh, Bengt

[0] https://www.snia.org/sites/default/files/SSSITECHNOTES_HowControllersMaximizeSSDLife.pdf

On +2021-12-21 18:26:03 +0100, Ricardo Wurmus wrote:

(sorry, the top-post grew)

--

Regards,

Bengt Richter

Hello,

Ricardo Wurmus <rekado@elephly.net> writes:

There was an interesting thread in the Linux kernel mailing lists about this

very issue earlier this year:

I’m not sure I completely understood all of the concerns discussed there, but

my understanding of it is that for workloads which don’t concurrently modify

the huge directory, it’s size isn’t a problem for btrfs and XFS and in fact

it’s even more efficient to have one big directory rather than

subdirectories¹. It’s should also be well handled even by ext4, IIUC².

The problem for all filesystems is concurrently modifying the directory

(e.g., adding or removing files), because the kernel serializes directory

operations at the VFS layer.

Also in that case XFS can also have allocation issues when adding new files

if one isn’t careful.³

--

Thanks

Thiago

¹ https://lore.kernel.org/linux-fsdevel/20210517232237.GE2893@dread.disaster.area/

² https://lore.kernel.org/linux-fsdevel/6E4DE257-4220-4B5B-B3D0-B67C7BC69BB5@dilger.ca/

³ https://lore.kernel.org/linux-fsdevel/20210519125743.GP2893@dread.disaster.area/

Ricardo Wurmus <rekado@elephly.net> writes:

Turns out that space on the SAN is insufficient for a full copy of

/var/cache. We’ve hit ENOSPC after 4.2TB. The SAN enforces some

headroom to remain free, so it denies us full access to the 5TB slice.

Bummer.

I guess we’ll have to wait for the SAN extension some time early 2022

before we can relocate the substitutes cache.

Should we attempt to overwrite /gnu/store and rely exclusively on

substitutes from the cache?

No matter how we look at it, the huge store is a performance problem for

us. Today I had to kill ’guix gc’ after the GC lock had been held for

about 24 hours. We will keep having this problem.

--

Ricardo

Hello Ricardo,

Yes, I don't see any other options. Before that, what might be nice

could be:

1. Ensure that all Berlin /var/cache/guix/publish directory is

synchronized on Bordeaux. We are now at 117G out of X. We could then

start a publish server on Bordeaux. As Bordeaux is already part of the

default substitute servers list, the transition could be smooth I guess.

2. Determine what file-system out of ext4, btrfs and xfs could be the

most suitable for Berlin's /gnu/store. I'm running some tests on an old

HDD to try to determine the fragmentation impact on those

file-systems. We can of course choose to be conservative and go for ext4

that did the job until now.

Regarding the /gnu/store re-creation, I wonder how can we do it without

reinstalling completely Berlin. Maybe we could save the system store

closure somewhere and restore it on the shining new file-system?

Thanks,

Mathieu

Mathieu Othacehe <othacehe@gnu.org> writes:

I had the SAN slice extended from 5TB to 10TB. This is now also full

(at 9.2TB due to SAN configuration). I suggest doing the rsync to

Bordeaux from /mnt_test/var/cache/guix/publish instead of the much

slower /var/cache/guix/publish. It doesn’t hold *all* files, but 9+TB

should be enough to fuel the transfer to Bordeaux for a while.

I don’t know. I would want to take a copy of the root file system as a

backup of state (like the Lets Encrypt certs), and copy the closure of

the current operating system configuration somewhere. We could copy it

to a dedicated build node (after stopping the GC cron job) and set it up

as an internal substitute server. Then “guix system init” while

fetching the substitutes from that server.

But I guess we’d have to boot the installer image anyway so that we can

safely erase /gnu/store, or else we’d erase files that are currently in

use.

--

Ricardo

Hi,

Mathieu Othacehe <othacehe@gnu.org> writes:

I'm more than happy to close this old, no longer relevant bug :-).

Since it was reported, the storage was migrated to a much faster array,

and is using the Btrfs file system with zstd compression, which avoids

the inodes exhaustion issue we've had with ext4 in the past.

A full garbage collection (GC) is run daily to keep the store growth in

check and for the GC to always take a similar amount of time (less than

20 minutes) every day.

--

Thanks,

Maxim