Bug 582082 – sys-apps/systemd-226-r2: systemd-journal-flush.service slows down boot a lot

• Product: Gentoo Linux
• Status: RESOLVED TEST-REQUEST

[Description Pacho Ramos 2016-05-04 13:24:01 UTC]

This is a problem I am hitting on multiple computers, it seems that, with the time, the systemd-journal-flush.service becomes the major service slowing down the boots. But I am not sure about the cause. This seems similar to:
https://bugzilla.redhat.com/show_bug.cgi?id=1006386

But I am running 226 version (also 229 is affected as I tried in other machine) and I use ext4 on all the systems :/

# systemd-analyze blame
         16.076s systemd-journal-flush.service
          8.645s dev-sda5.device
          3.070s systemd-udevd.service
          1.925s usr-portage.mount
          1.919s dev-sda6.swap
          1.256s systemd-fsck-root.service
          1.114s systemd-vconsole-setup.service
          1.091s NetworkManager.service
           902ms accounts-daemon.service
           900ms colord.service
           872ms gdm.service
           853ms sys-kernel-debug.mount
           853ms systemd-readahead-collect.service
           852ms kmod-static-nodes.service
           851ms dev-hugepages.mount
           833ms systemd-modules-load.service
           571ms systemd-readahead-replay.service
           534ms cups.service
           460ms systemd-journald.service
           428ms systemd-tmpfiles-clean.service
           356ms systemd-sysctl.service
           316ms polkit.service
           312ms systemd-logind.service
           292ms systemd-timedated.service
           285ms tmp.mount
           284ms dev-mqueue.mount
           224ms systemd-tmpfiles-setup-dev.service
           212ms systemd-hostnamed.service
           169ms systemd-remount-fs.service
           162ms rtkit-daemon.service
           146ms systemd-tmpfiles-setup.service
           141ms gpm.service
           141ms upower.service
           100ms systemd-timesyncd.service
           100ms udisks2.service
            92ms systemd-update-utmp.service
            85ms [e-mail]
            54ms [e-mail]
            46ms systemd-localed.service
            45ms systemd-udev-trigger.service
            45ms wpa_supplicant.service
            24ms systemd-user-sessions.service
            21ms geoclue.service
            13ms sys-fs-fuse-connections.mount
             3ms systemd-random-seed.service
             1ms systemd-readahead-done.service
             1ms var-tmp-portage.mount

In this case it takes 16secs... in other machines it can get even more :/

 cat /etc/systemd/journald.conf
#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
#
# See journald.conf(5) for details.

[Journal]
#Storage=auto
#Compress=yes
#Seal=yes
#SplitMode=uid
#SyncIntervalSec=5m
#RateLimitInterval=30s
#RateLimitBurst=1000
#SystemMaxUse=
#SystemKeepFree=
#SystemMaxFileSize=
#RuntimeMaxUse=
#RuntimeKeepFree=
#RuntimeMaxFileSize=
#MaxRetentionSec=
#MaxFileSec=1month
#ForwardToSyslog=no
#ForwardToKMsg=no
ForwardToConsole=yes
#ForwardToWall=yes
TTYPath=/dev/tty12
#MaxLevelStore=debug
#MaxLevelSyslog=debug
#MaxLevelKMsg=notice
#MaxLevelConsole=info
#MaxLevelWall=emerg

Thanks a lot for your help

[Comment 1 Mike Gilbert 2016-05-04 15:26:04 UTC]

What USE flags do you have enabled on sys-apps/systemd? In particular, are lz4 and/or lzma enabled?

How large is your system journal? ls -l /var/log/journal/*/

What kind of storage is /var/log/journal living on? What fstype?

If using btrfs, can you validate that COW has been disabled on the system.journal file? For example:

> floppym@naomi ~ % lsattr /var/log/journal/*/system.journal
> ---------------C /var/log/journal/4e39f1235b04c6398c7a5eaa0000000b/system.journal

[Comment 2 Mike Gilbert 2016-05-04 15:26:46 UTC]

(In reply to Mike Gilbert from comment #1)

I missed that you are using ext4. Disregard the questions about btrfs.

[Comment 3 Pacho Ramos 2016-05-05 08:51:22 UTC]

(In reply to Mike Gilbert from comment #1)
> What USE flags do you have enabled on sys-apps/systemd? In particular, are
> lz4 and/or lzma enabled?

[ebuild   R    ] sys-apps/systemd-226-r2:0/2::gentoo  USE="acl http kdbus kmod lz4 pam policykit seccomp ssl (-apparmor) -audit -cryptsetup -curl -elfutils -gcrypt -gnuefi -idn -importd -lzma -nat -qrcode (-selinux) -sysv-utils {-test} -vanilla -xkb" ABI_X86="32 (64) (-x32)" 0 KiB

[Comment 4 Pacho Ramos 2016-05-05 08:52:32 UTC]

Created attachment 433274 [details]
journal files

I have needed to attach the ls output as it was too large ;)

[Comment 5 Pacho Ramos 2016-05-05 08:54:13 UTC]

The partition has this options in fstab:
/dev/sda5               /               ext4            noatime,defaults 	0 1

That results in:
/dev/sda5 on / type ext4 (rw,noatime,data=ordered)
(from mount output)

[Comment 6 Mike Gilbert 2016-05-30 14:02:01 UTC]

I don't have any bright ideas on this one. I would suggest creating an issue upstream if one does not exist already.

[Comment 7 Pacho Ramos 2016-05-30 21:17:03 UTC]

No problem, I will try when updating to 230 as it supposedly should run flush in a different way to prevent issues like this :/