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

[Goffredo Baroncelli]

On 06/14/2014 11:37 PM, Kai Krakow wrote:
> Goffredo Baroncelli <kreijack at libero.it> schrieb:
> 
>> On 06/14/2014 10:13 PM, Kai Krakow wrote:
>>> Take care to enable all needed services to enable defrag... If your
>>> services make use of journal file loading these files should also become
>>> part of the process. You can check with
>>> "/usr/lib/systemd/systemd-readahead analyze". The state is stored in
>>> /.readahead.
>>>
>> 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.

> 
> Check with "find /etc/systemd -name '*readahead*' -type l"...
> 
>> 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.


On another fedora machine, I found

$ sudo /lib/systemd/systemd-readahead analyze | grep journal
   100% ( 1)       220384: /usr/lib/systemd/systemd-journald
   100% ( 1)          770: /etc/systemd/journald.conf
   100% ( 1)        24544: /usr/lib64/rsyslog/imjournal.so
   100% ( 1)       122880: /usr/lib64/libsystemd-journal.so.0.11.3
    50% ( 1)      4194304: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-1000 at 0004f1b1019bc549-09d9ae048ff8eeef.journal~
   100% ( 1)      8388608: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-1000 at 0004f1b7dcfd728c-38950862a134194d.journal~
    50% ( 1)      4194304: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-995 at 0004f1c3fa738010-b0829bd837e30f61.journal~
    50% ( 1)      4194304: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-995.journal
   100% ( 1)      8388608: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/system at 0004f6ed6604ebc7-bb2f3b30ac6eb32c.journal~
   100% ( 1)      8388608: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-1000 at 0004f6ed66a05b08-9d244b02cc294baf.journal~
    77% ( 1)      6508544: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/system at 0004f6ed6d02e69f-d9c815aa06264d7a.journal~
   100% ( 1)      8388608: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-1000 at 0004f6ed6db6dd7d-cc84da57d5b01680.journal~
   100% ( 1)      8388608: /var/log/journal/189323cd4cc348159b9fd5b32b566b05/user-1000.journal
   100% ( 1)          121: /var/lib/rsyslog/imjournal.state


So some journal files are present, but not the current one (system.journal)



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

 


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