[systemd-devel] Fwd: Journalctl performance

[Jason St. John]

On Wed, Sep 25, 2013 at 8:44 AM, Frederic Crozat <fcrozat at suse.com> wrote:
> 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
>
> _______________________________________________
> systemd-devel mailing list
> systemd-devel at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/systemd-devel


I've been seeing similar performance issues with the journal for
several recent versions of systemd (at least from v204 through v207 on
Arch Linux). I have journal logs from 2012-10-20 through today that
contain 1,268,128 lines. I just ran "journalctl" with "less" as the
pager, pressed "G", and it took 5.5 minutes to get all the way to the
bottom. journalctl used lots of CPU throughout and regularly went to
99% CPU utilization.

This is on a 3.5 year old laptop with a Core i5 M 430 and a 5,400 RPM
hard drive.

Jason