[systemd-devel] Slow startup of systemd-journal on BTRFS

[Kai Krakow]

Goffredo Baroncelli <kreijack at libero.it> schrieb:

>>> I have enabled all the services (collect, replay, done), but I was
>>> unable to see any gain.
>> 
>> I don't think you can actually enable the "done" service because it is
>> static... But if it placed a symlink in /etc/systemd that is probably
>> wrong and you should undo it. It is automatically activated a few seconds
>> after booting is done to store the collected data for replaying on next
>> reboot.
> 
> I checked the output of systemd-analyze: systemd-readahead-done is called
> at the end of the chart. The sym-links exist only for the collect and
> replay services, which were called at the beginning.

Then all is good.

>>> I don't know why but system.journal is not considered by readahead:
>>>
>>> # /usr/lib/systemd/systemd-readahead analyze | grep journal
>>>
>>>
>>>    100% ( 1)          770: /etc/systemd/journald.conf
>>>     50% ( 1)      4194304:
>>>     /var/log/journal/36f10f5379ec4a1398ac303a0ce20fd0/user-997.journal
>>>     50% ( 1)      4194304:
>>>     /var/log/journal/36f10f5379ec4a1398ac303a0ce20fd0/user-1000.journal
>> 
>> I tried that on my system and it looks vice-versa somehow:
>> 
>> $ sudo /usr/lib/systemd/systemd-readahead analyze|fgrep journal
>>    100% ( 1)          812: /etc/systemd/journald.conf
>>    100% ( 1)      8388608:
>> /var/log/journal/121b87ca633e8ac0016656680000001b/system.journal
>> 
>> Strange... ;-)
> 
> May be this is a reason of my degraded performance. However I tried on two
> machines (all fedora) and after several reboot; I tried also removing the
> /.readahead file... Nothing.

I'm not sure but generally it is said that readahead utilities may need a 
few reboots before fully working. Did you try that? Will it take the journal 
into account then?

Maybe there is something special about your setup and your system.journal 
does not become touched during boot because of this? You said you also use 
rsyslogd. Maybe logs are redirected there instead of written to both logging 
mechanisms? Maybe most logging by system daemons is turned off or they write 
directly to log files?

I tuned all my daemons and services to not write to any log files at all, 
instead log everything to stderr/stdout (which is captured by systemd) or 
into the syslogger which is journald as the only mechanism in my system. I 
just prefer to have everything in one place, and journalctl is a great way 
to filter the logs or create custom views. Maybe that's a reason why it is 
taken into account by readahead on my system? I can only guess but maybe 
worth a try for you...

>> To get back to your performance problem: Did you try "systemctl enable
>> bootchart" and then (after a reboot) look at the png generated in
>> /run/log (at least in my system it is placed there, look at the configs
>> if in doubt). It can give some interesting clues about why a service
>> starts late or takes long to execute.
> Unfortunately bootchart doesn't work on fedora, because CONFIG_SCHEDSTATS
> is not enabled in the kernel.

Well, I'm on Gentoo so my kernel is custom built by design. But I checked my 
config, I even have no config option "CONFIG_SCHEDSTATS" but bootchart works 
for me:

$ zfgrep SCHED /proc/config.gz 
CONFIG_HAVE_UNSTABLE_SCHED_CLOCK=y
CONFIG_CGROUP_SCHED=y
CONFIG_FAIR_GROUP_SCHED=y
CONFIG_RT_GROUP_SCHED=y
CONFIG_SCHED_AUTOGROUP=y
CONFIG_IOSCHED_NOOP=y
CONFIG_IOSCHED_DEADLINE=y
CONFIG_IOSCHED_CFQ=y
CONFIG_CFQ_GROUP_IOSCHED=y
CONFIG_IOSCHED_BFQ=y
CONFIG_DEFAULT_IOSCHED="deadline"
CONFIG_SCHED_OMIT_FRAME_POINTER=y
CONFIG_SCHED_SMT=y
CONFIG_SCHED_MC=y
CONFIG_SCHED_HRTICK=y
# CONFIG_NET_SCHED is not set
CONFIG_USB_EHCI_TT_NEWSCHED=y

BTW: After migrating to systemd, I had a boot time of 15s to DM on 
rotational with serveral heavy services enabled. I did not measure time to 
desktop back then. But after I did a btrfs balance (I use multidevice 
btrfs), the time to DM went up to around 25s and never went back no matter 
what I tried (even when I disabled some services). I switched to autologin 
DM since then so at least systemd-readahead catches some of the KDE 
services, too, now. But it still feels slow. I'm probably redoing my btrfs 
in the future, switching to 16k leaf size in that process. But I'll wait 
with that until I migrate to bigger hard disks. Currently I have still 
plenty of space left. According to bootchart I never had a problem with time 
spent processing the journal. But since a few kernel versions, auto-suspend 
works great for me, so I usually do not switch the system off, just leave it 
running and it suspends to RAM after 2 hours. As a nice side effect, it 
wakes up instantly (especially since kernel 3.15), and I save a lot of 
power. Still waiting for the systemd auto-wakeup facility to run timer jobs 
like a backup. ;-)

-- 
Replies to list only preferred.