[systemd-devel] Journalctl performance

[Frederic Crozat]

Le mercredi 25 septembre 2013 à 12:10 +0100, Colin Guthrie a écrit :
> Hi,
> 
> On a relatively average journal it can take a looooooooong time to page
> through all the data collected.
> 
> With data stored from 5th August to 25th September  and running
> "journalctl" and pressing G to jump to the end in less, and it takes
> several minutes before the end of the messages are reached with
> journalctl taking 100% CPU for most of that time.
> 
> This is on a slightly older systemd (approximately similar to the 195
> version used in Suse - i.e. a shitton of backported patches!) but even
> on my regular-use laptop (with SSD) and logs dating back to Jun 18th it
> takes ~1m 30s to do the same. This is ultimately with something
> approximating 2.5m lines of output to be paged through (systemd
> debugging is on!)
> 
> With this kind of performance, it's kinda a hard sell, although I'm not
> really sure if I should *expect* any better performance and I appreciate
> that listing specific date ranges or particular services can reduce the
> amont of data returned and thus speed things up dramitcally. So I guess
> my question is is it basically unrealistic to expect better performance
> from a simple "just output everything" operation like this? Sadly this
> is exactly the type of operation a typical user who is used to syslog
> would do with journalctl and thus don't see the beneifts.
> 
> Any thoughts on this?
> 
> HDD (systemd 195+patches):
> [root at marley ~]# du -sh /var/log/journal/
> 1.5G	/var/log/journal/
> [root at marley ~]# date; journalctl | wc -l; date
> Wed 25 Sep 11:39:00 BST 2013
> 1957295
> Wed 25 Sep 11:42:16 BST 2013
> 
> 
> SSD (systemd 207):
> [root at jimmy ~]# du -sh /var/log/journal/
> 2.0G	/var/log/journal/
> [root at jimmy ~]# date; journalctl | wc -l; date
> Wed 25 Sep 11:40:18 BST 2013
> 2391076
> Wed 25 Sep 11:42:10 BST 2013
> 
> 
> And just for some plain text comparisions on the older, HDD machine:
> 
> [root at marley ~]# date; journalctl >/home/journal; date
> Wed 25 Sep 11:50:41 BST 2013
> Wed 25 Sep 11:53:59 BST 2013
> [root at marley ~]# wc -l /home/journal
> 1957527 /home/journal
> [root at marley ~]# date; cat /home/journal >/dev/null; date
> Wed 25 Sep 11:54:49 BST 2013
> Wed 25 Sep 11:54:50 BST 2013
> [root at marley ~]# date; cat /home/journal | gzip >/home/journal.gz; date
> Wed 25 Sep 11:55:23 BST 2013
> Wed 25 Sep 11:55:28 BST 2013
> [root at marley ~]# date; zcat /home/journal.gz >/dev/null; date
> Wed 25 Sep 11:55:50 BST 2013
> Wed 25 Sep 11:55:51 BST 2013
> [root at marley ~]# date; cat /home/journal | xz >/home/journal.xz; date
> Wed 25 Sep 11:56:15 BST 2013
> Wed 25 Sep 11:58:12 BST 2013
> [root at marley ~]# date; xzcat /home/journal.xz >/dev/null; date
> Wed 25 Sep 12:01:25 BST 2013
> Wed 25 Sep 12:01:27 BST 2013
> [root at marley ~]# ls -lh /home/journal*
> -rw-r--r-- 1 root root 244M Sep 25 11:53 /home/journal
> -rw-r--r-- 1 root root  17M Sep 25 11:55 /home/journal.gz
> -rw-r--r-- 1 root root 9.8M Sep 25 11:58 /home/journal.xz
> 
> So, 2 seconds to page through 9.8M of compressed data directly with log
> files, or ~2 minutes, 30 seconds to page through 1.5GB of journal based
> logs to produce the same result.... (and I know the files here will be
> "hot" in terms of cache etc which gives them a slightly unfair
> advantage, but this would factor into real world usage too)
> 
> Now, of course I do know that in the journalctl case, there is both more
> to look at, perhaps some old journals that are ultimately analysed at
> but never used because they are corrupt or something, and a whole bunch
> of other data that is not synthesizable to the journalctl syslog-style
> output, but forgetting features and looking at raw numbers and, as I
> said above, it's a hard sell on the surface!
> 
> Is there something wrong here? Are my numbers unrealistic? Is this
> pointing at a larger problem with my setup/usage?

I'm seeing similar bad numbers on openSUSE, but I recently noticed an
owner difference between some journal files (since journal files moved
from adm to systemd-journal group) and I'm wondering if it wasn't
breaking cleanup / rotation of old journal entries (I haven't
investigated much :(

-- 
Frederic Crozat <fcrozat at suse.com>
SUSE