[systemd-devel] Journald Scalability

[Roland Schatz]

On 10.09.2012 09:57, Lennart Poettering wrote:
> Well, I am not aware of anybody having done measurements recently
> about this. But I am not aware of anybody running into scalability
> issues so far. 
I'm able to share a data point here, see attachment.

TLDR: Outputting the last ten journal entries takes 30 seconds on my server.

I have not reported this so far, because I'm not really sure whom to
blame. Current suspects include the journal, btrfs and hyper-v ;)

Some details about my setup: I'm running Arch Linux on a virtual server,
running on hyper-v on some windows host (outside of my control). I'm
currently using systemd 189, but the journal files are much older.
journald.conf is empty (everything commented, i.e., the default). The
journal logging was activated in February (note the strange first output
line that says the journal ends on 28 Feb, while still containing
entries up to right now). Since then, I have not removed/archived any
journal files from the system.

After issuing journalctl a few times, time goes down significantly, ever
for larger values of -n (e.g. first try -n10 takes 30 secs, second -n10
takes 18 secs, third -n10 takes 0.2 secs, after that, even -n100 takes
0.2 secs, -n500 takes 0.8 secs and so on). Rebooting or simply waiting a
day or so makes it slow again.

Btrfs and fragmentation may be an issue: Defragmenting the journal files
seems to make things better. But its hard to be sure whether this is
really the problem, because defrag could just be pulling the journal
files into the fs cache, therefore having a similar effect than the
repeated journalctl...

I'm not able to reproduce the problem by copying the whole journal to
another system and running journalctl there. I'm also seeing the getting
faster effect, but it starts at 2 secs and then goes down to 0.2 secs.
Also, I'm not seeing any difference between btrfs and ext4, so maybe
really fragmentation is the issue, although I don't really understand
how a day of logging could fragment the log files that badly, even on a
COW filesystem. Yes, there still is the indirection of the virtual
drive, but I have a fixed-size disk file residing on an ntfs drive, so
there shouldn't be any noticable additional fragmentation coming from
that setup.

I'm not sure what I can do investigate this further. For me this is a
low priority problem, since the system is running stable and the problem
goes away after a few journalctl runs. But if you have anything you'd
like me to try, I'd be happy to assist.

-Roland
-------------- next part --------------
[admin at server ~]$ time journalctl -n 10 --no-pager
Logs begin at Mon, 27 Feb 2012 14:15:55 +0100, end at Tue, 28 Feb 2012 09:41:54 +0100.
Sep 10 13:53:00 server sshd[27987]: Did not receive identification string fr...22
Sep 10 14:01:01 server /usr/sbin/crond[28029]: pam_unix(crond:session): sessi...)
Sep 10 14:01:01 server /USR/SBIN/CROND[28030]: (root) CMD (run-parts /etc/cro...)
Sep 10 14:01:01 server /USR/SBIN/CROND[28029]: pam_unix(crond:session): sessi...t
Sep 10 15:01:01 server /usr/sbin/crond[28282]: pam_unix(crond:session): sessi...)
Sep 10 15:01:01 server /USR/SBIN/CROND[28283]: (root) CMD (run-parts /etc/cro...)
Sep 10 15:01:01 server /USR/SBIN/CROND[28282]: pam_unix(crond:session): sessi...t
Sep 10 15:05:55 server sshd[28311]: Accepted password for admin from ....h2
Sep 10 15:05:55 server sshd[28311]: pam_unix_session(sshd:session): session ...0)
Sep 10 15:05:55 server systemd-logind[231]: New session 217 of user admin.

real    0m29.886s
user    0m0.040s
sys     0m4.613s

[admin at server ~]$ du -sh /var/log/journal
867M    /var/log/journal

[admin at server ~]$ find /var/log/journal | wc -l
21