Slow startup of systemd-journal on BTRFS

Hi all,

I would like to share a my experience about a slowness of systemd when used on BTRFS.

My boot time was very high (about ~50 seconds); most of time it was due to NetworkManager which took about 30-40 seconds to start (this data came from "systemd-analyze plot").

I make several attempts to address this issue. Also I noticed that sometime this problem disappeared; but I was never able to understand why.

However this link

	https://bugzilla.redhat.com/show_bug.cgi?id=1006386

suggested me that the problem could be due to a bad interaction between systemd and btrfs. NetworkManager was innocent.
It seems that systemd-journal create a very hight fragmented files when it stores its log. And BTRFS it is know to behave slowly when a file is highly fragmented. This had caused a slow startup of systemd-journal, which in turn had blocked the services which depend by the loggin system.

In fact after I de-fragmented the files under /var/log/journal [*], my boot time decreased of about 20second (from 50s to 30s).

Unfortunately I don't have any data to show. The next time I will try to collect more information. But I am quite sure that when the log are highly fragmented systemd-journal becomes very slow on BTRFS.

I don't know if the problem is more on the systemd side or btrfs side. What I know is that both the projects likely will be important in the near futures, and both must work well together.

I know that I can "chattr +C" to avoid COW for some files; but I don't want to lost also the checksum protection.

If someone is able to suggest me how FRAGMENT the log file, I can try to collect more scientific data.

BR
G.Baroncelli

[*]

# btrfs fi defrag /var/log/journal/*/*

gpg @keyserver.linux.it: Goffredo Baroncelli (kreijackATinwind.it>
Key fingerprint BBF5 1610 0B64 DAC6 5F7D  17B2 0EDA 9B37 8B82 E0B5

So long as you're not using compression, filefrag will show you fragments of systemd-journald journals. I can vouch for the behavior you experience without xattr +C or autodefrag, but further it also causes much slowness when reading journal contents. LIke if I want to search all boots for a particular error message to see how far back it started, this takes quite a bit longer than on other file systems. So far I'm not experiencing this problem with autodefrag or any other negative side effects, but my understanding is this code is still in flux.

Since the journals have their own checksumming I'm not overly concerned about setting xattr +C.

Chris Murphy

On my BTRFS/systemd systems I edit /etc/systemd/journald.conf and put "SystemMaxUse=50M". That doesn't solve the fragmentation problem but reduces it enough that it doesn't bother me.

My Main Blog         http://etbe.coker.com.au/
My Documents Blog    http://doc.coker.com.au/

Russell Coker posted on Thu, 12 Jun 2014 11:18:37 +1000 as excerpted:

FWIW, as a relatively new switcher to systemd, that is, after switching to btrfs only a year or so ago... Two comments:

1) Having seen a few reports of journald's journal fragmentation on this list, I was worried about those journals here as well.

My solution to both this problem and to an unrelated frustration with journald[1] was to:

a) confine journald to only a volatile (memory-only) log, first on a temporary basis while I was only experimenting with and setting up systemd (using the kernel command-line's init= to point at systemd while /sbin/ init still pointed at sysv's init for openrc), then later permanently, once I got enough of my systemd and journald config setup to actually switch to it.

b) configure my former syslogger (syslog-ng, in my case) to continue in that role under systemd, with journald relaying to it for non-volatile logging.

Here's the /etc/journald.conf changes I ended up with to accomplish (a), see the journald.conf(5) manpage for the documentation, as well as the below explanation:

Storage=volatile
RuntimeMaxUse=448M
RuntimeKeepFree=48M
RuntimeMaxFileSize=64M

Storage=volatile is the important one. As the manpage notes, that means journald stores files under /run/log/journal only, where /run is normally setup by systemd as a tmpfs mount, so these files are tmpfs and thus memory-only.

The other three must be read in the context of a 512 MiB /run on tmpfs [2]. From that and the information in the journald.conf manpage, it should be possible to see that my setup is (runtime* settings apply to the volatile files under /run):

An individual journal filesize (MaxFileSize) of 64 MiB, with seven such files in rotation (the default if MaxFileSize is unset is eight), totaling 448 MiB (MaxUse, the default being 10% of the filesystem, too small here since the journals are basically the only thing taking space). On a 512 MiB filesystem, that will leave 64 MiB for other uses (pretty much all 0-byte lock and pidfiles, IIRC I was running something like a 2 MiB /run before systemd without issue).

It's worth noting that UNLIKE MaxUse, which will trigger journal file rotation when hit, hitting the KeepFree forces journald to stop journaling entirely -- *NOT* just to stop writing them here, but to stop forwarding to syslog (syslog-ng here) as well. I FOUND THIS OUT THE HARD WAY! Thus, in ordered to keep journald still functional, make sure journald runs into the MaxUse limit before it runs into KeepFree. The KeepFree default is 15% of the filesystem, just under 77 MiB on a 512 MiB filesystem which is why I found this out the hard way with settings that would otherwise keep only 64 MiB free. The 48 MiB setting I chose leaves 16 MiB of room for other files before journald shuts down journaling, which should be plenty, since under normal circumstances the other files should all be 0-byte lock and pidfiles. Just in case, however, there's still 48 MiB of room for other files after journald shuts down, before the filesystem itself fills up.

Configuring the syslogger to work with journald is "left as an exercise for the reader", as they say, since for all I know the OP is using something other than the syslog-ng I'm familiar with anyway. But if hints for syslog-ng are needed too, let me know. =:^)

2) Someone else mentioned btrfs' autodefrag mount-option. Given #1 above I've obviously not had a lot of experience with journald logs and autodefrag, but based on all I know about btrfs fragmentation behavior as well as journald journal file behavior from this list, as long as journald's non-volatile files are kept significantly under 1 GiB and preferably under half a GiB each, it shouldn't be a problem, with a /possible/ exception if you get something run-away-journaling multiple messages a second for a reasonably long period, such that the I/O can't keep up with both the journaling and autodefrag.

If you do choose to keep a persistent journal with autodefrag, then, I'd recommend journald.conf settings that keep individual journal files to perhaps 128 MiB each. (System* settings apply to the non-volatile files under /var, in /var/log/journal/.)

SystemMaxFileSize=128M

AFAIK, that wouldn't affect the total journal size and thus the number of journal files, which would remain 10% of the filesystem size by default.

Alternatively, given the default 8-file rotation if MaxFileSize is unset, you could limit the total journal size to 1 GiB, for the same 128 MiB individual file size.

SystemMaxUse=1G

Of course if you want/need more control set both and/or other settings as I did for my volatile-only configuration above.

---
[1] Unrelated journald frustration: Being a syslog-ng user I've been accustomed to being able to pre-filter incoming messages *BEFORE* they get written to the files. This ability has been the important bit of my run-away-log coping strategy when I have no direct way to reconfigure the source to reduce the rate at which it's spitting out "noise" that's otherwise overwhelming my logs.

Unfortunately, while it seems journald has all /sorts/ of file-grep-style filtering tools to focus in like a laser on what you want to see AFTER the journal is written, I found absolutely NO documentation on setting up PREWRITE journal filters (except log-level, and there's global rate- limiting as well, but I didn't want to use those, I wanted to filter specific "noise" messages), which means runaway journaling simply runs away, and if I use the size restriction stuff to turn it down, I quickly lose the important stuff I want to keep around when the files size-rotate due to that runaway!

Thus my solution, keep journald storage volatile only, relatively small but still big enough I can use the great systemctl status integration to get the last few journal entries from each service, then feed it to syslog-ng to pre-write filter the noise out before actual write to permanent storage. =:^)

[2] 512 MiB /run tmpfs. This is on a 16 GiB RAM system, so default tmpfs size would be 8 GiB. But I have several such tmpfs including a big /tmp that I use for scratch space when I'm building stuff (gentoo's PORTAGE_TMPDIR, and for fully in-memory DVD ISOs too), and I don't have swap configured at all, so keeping a reasonable lid on things by limiting /run and its major journal-file space user to half a GiB seems prudent.

Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

systemd has a very stupid journal write pattern. It checks if there is space in the file for the write, and if not it fallocates the small amount of space it needs (it does *4 byte* fallocate calls!) and then does the write to it. All this does is fragment the crap out of the log files because the filesystems cannot optimise the allocation patterns.

Yup, it fragments journal files on XFS, too.

http://oss.sgi.com/archives/xfs/2014-03/msg00322.html

IIRC, the systemd developers consider this a filesystem problem and so refused to change the systemd code to be nice to the filesystem allocators, even though they don't actually need to use fallocate...

Cheers,

Dave.

Dave Chinner
[email protected]

BTW, the systemd list is subscriber only, so thay aren't going to see anything that we comment on from a cross-post to the btrfs list.

Cheers,

Dave.

Dave Chinner
[email protected]

Unless a subscriber finds something really interesting, quotes it, and cross posts it.

Chris murphy

Not really the case.

http://cgit.freedesktop.org/systemd/systemd/tree/src/journal/journal-file.c#n354

We allocate 8mb at minimum.

Well, it would be good if you'd tell me what to do instead...

I am invoking fallocate() in advance, because we write those files with mmap() and that of course would normally triggered SIGBUS already on the most boring of reasons, such as disk full/quota full or so. Hence, before we do anything like that, we invoke fallocate() to ensure that the space is actually available... As far as I can see, that pretty much in line with what fallocate() is supposed to be useful for, the man page says this explicitly:

"...After a successful call to posix_fallocate(), subsequent writes
to bytes in the specified range are guaranteed not to fail because of lack of disk space."

Happy to be informed that the man page is wrong.

I am also happy to change our code, if it really is the wrong thing to do. Note however that I generally favour correctness and relying on documented behaviour, instead of nebulous optimizations whose effects might change with different file systems or kernel versions...

What? No need to be dick. Nobody ever pinged me about this. And yeah, I think I have a very good reason to use fallocate(). The only reason in fact the man page explicitly mentions.

Lennart

Lennart Poettering, Red Hat

For what it's worth, I did not write what is attributed to me above. I was quoting Dave Chinner, and I've confirmed the original attribution correctly made it onto the systemd-devel@ list.

I don't know whether some people on this distribution list are even subscribed to systemd-devel@ so those subsequent responses aren't likely being posted to systemd-devel@ but rather to linux-btrfs@.

Chris Murphy

Fallocate is a red herring except insofar as it's a hint that btrfs isn't making much use of: you see the same behaviour with small writes to an mmap'ed file that's msync'ed after each write, and likewise with plain old appending small writes with an fsync after each write, with or without fallocating the file first. Looking at the fiemap output while doing either of those, you'll see a new 4k extent being made, and then the physical location of that extent will increment until the writes move on to the next 4k extent.

cwillu@cwillu-home:~/work/btrfs/e2fs$ touch /tmp/test

... m[x] = " "
... m.flush(x / 4096 * 4096, 4096) # msync(self->data + offset,
size, MS_SYNC)) {

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 800000
fs_ioc_fiemap 3223348747d
File /tmp/test has 3 extents:
#	Logical          Physical         Length           Flags
0:	0000000000000000 0000000b3d9c0000 0000000000001000 0000
1:	0000000000001000 000000069f012000 00000000003ff000 0000
2:	0000000000400000 0000000b419d1000 0000000000400000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b3daf3000 0000000000001000 0000
1:	0000000000001000 000000069f012000 00000000003ff000 0000
2:	0000000000400000 0000000b419d1000 0000000000400000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b3dc38000 0000000000001000 0000
1:	0000000000001000 000000069f012000 00000000003ff000 0000
2:	0000000000400000 0000000b419d1000 0000000000400000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b3dc9f000 0000000000001000 0000
1:	0000000000001000 0000000b3d2b7000 0000000000001000 0000
2:	0000000000002000 000000069f013000 00000000003fe000 0000
3:	0000000000400000 0000000b419d1000 0000000000400000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat
/tmp/test -c %s)# msync(self->data + offset, size, MS_SYNC)) {
0:	0000000000000000 0000000b3dc9f000 0000000000001000 0000
1:	0000000000001000 0000000b3d424000 0000000000001000 0000
2:	0000000000002000 000000069f013000 00000000003fe000 0000
3:	0000000000400000 0000000b419d1000 0000000000400000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b3dc9f000 0000000000001000 0000
1:	0000000000001000 0000000b3d563000 0000000000001000 0000
2:	0000000000002000 000000069f013000 00000000003fe000 0000
3:	0000000000400000 0000000b419d1000 0000000000400000 0001

========

cwillu@cwillu-home:~/work/btrfs/e2fs$ rm /tmp/test
cwillu@cwillu-home:~/work/btrfs/e2fs$ touch /tmp/test

... m[x] = " "
... m.flush(x / 4096 * 4096, 4096) # msync(self->data + offset,
size, MS_SYNC)) {

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 800000
fs_ioc_fiemap 3223348747d
File /tmp/test has 1 extents:
#	Logical          Physical         Length           Flags
0:	0000000000000000 0000000b47f11000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b48006000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b48183000 0000000000001000 0000
1:	0000000000001000 0000000b48255000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b48183000 0000000000001000 0000
1:	0000000000001000 0000000b48353000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b48183000 0000000000001000 0000
1:	0000000000001000 0000000b493ed000 0000000000001000 0000
2:	0000000000002000 0000000b4a68f000 0000000000001000 0000
3:	0000000000003000 0000000b4b36f000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
0:	0000000000000000 0000000b48183000 0000000000001000 0000
1:	0000000000001000 0000000b493ed000 0000000000001000 0000
2:	0000000000002000 0000000b4a68f000 0000000000001000 0000
3:	0000000000003000 0000000b4b4cf000 0000000000001000 0001

========

cwillu@cwillu-home:~/work/btrfs/e2fs$ rm /tmp/test
cwillu@cwillu-home:~/work/btrfs/e2fs$ touch /tmp/test

...   f.write(' ')
...   f.flush()
...   os.fdatasync(f.fileno())

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 395
fs_ioc_fiemap 3223348747d
File /tmp/test has 1 extents:
#	Logical          Physical         Length           Flags
0:	0000000000000000 0000000000000000 0000000000001000 0301

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 5b5
0:	0000000000000000 0000000000000000 0000000000001000 0301

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 1d61
0:	0000000000000000 0000000b4d2bc000 0000000000001000 0000
1:	0000000000001000 0000000b4e1c5000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 1e8c
0:	0000000000000000 0000000b4d2bc000 0000000000001000 0000
1:	0000000000001000 0000000b4e334000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 207c
0:	0000000000000000 0000000b4d2bc000 0000000000001000 0000
1:	0000000000001000 0000000b4e4a9000 0000000000001000 0000
2:	0000000000002000 0000000b4e528000 0000000000001000 0001

cwillu@cwillu-home:~/work/btrfs/e2fs$ fiemap /tmp/test 0 $(stat /tmp/test -c %s)
start: 0, length: 21be
0:	0000000000000000 0000000b4d2bc000 0000000000001000 0000
1:	0000000000001000 0000000b4e4a9000 0000000000001000 0000
2:	0000000000002000 0000000b4e66c000 0000000000001000 0001