[systemd-devel] Fwd: Journalctl performance

[Jan Engelhardt]

On Tuesday 2013-10-01 13:08, Colin Guthrie wrote:
>'Twas brillig, and Lennart Poettering at 01/10/13 03:03 did gyre and gimble:
>> On Mon, 30.09.13 12:48, Jason St. John (jstjohn at purdue.edu) wrote:
>> 
>>> 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.
>> 
>> If this only happens with some journalctl versions, any change you could
>> git bisect this and fiugre out what made journalctl so slow?
>
>
>Well as noted in my original mail, I've been getting similarly bad
>performance between 195 and 207 and thus I'm not convinced this is a
>regression as such. Seems more likely just a general problem that has
>always been present but is only showing up now when sufficient amounts
>of journal log data has been generated.
>
>Perhaps some performance tests are needed to generate synthetic large
>journals?

The log entries do not need to be hugely diverse or meaningful. I
have, for example, strongswan-ipsec (charon(8)) running which, even
just with a single peer, emits enough messages that you get lots
of real-world journals real fast.

# ls -Slrt syst*
-rw-r----- 1 122454016 Aug 28 09:41 system at 41aff803e2cf449d8a249f38b11d7fb7-0000000000000001-0004e4a12c34df3c.journal
-rw-r----- 1 120889344 Sep  1 18:45 system at 41aff803e2cf449d8a249f38b11d7fb7-0000000000025bf2-0004e4fd1ec466a4.journal
-rw-r----- 1 123904000 Sep  6 23:37 system at 41aff803e2cf449d8a249f38b11d7fb7-000000000004a761-0004e5552dc059d4.journal
-rw-r----- 1 122720256 Sep 11 23:04 system at 41aff803e2cf449d8a249f38b11d7fb7-0000000000071eec-0004e5bdd9651a15.journal
-rw-r----- 1 122212352 Sep 16 21:43 system at 41aff803e2cf449d8a249f38b11d7fb7-0000000000098e6f-0004e621f85869be.journal
-rw-r----- 1  91037696 Sep 17 12:34 system at 41aff803e2cf449d8a249f38b11d7fb7-00000000000bef28-0004e6856b148e93.journal
-rw-r----- 1  91955200 Sep 18 00:56 system at 41aff803e2cf449d8a249f38b11d7fb7-00000000000d7244-0004e691ddc43d8c.journal
-rw-r----- 1  91705344 Sep 18 15:23 system at 41aff803e2cf449d8a249f38b11d7fb7-00000000000ef87b-0004e69c3cc69ce8.journal
-rw-r----- 1 120033280 Sep 23 06:50 system at 41aff803e2cf449d8a249f38b11d7fb7-00000000001083d7-0004e6a85723b5a8.journal
-rw-r----- 1 123625472 Sep 28 07:19 system at 41aff803e2cf449d8a249f38b11d7fb7-000000000012c56d-0004e705c201cc5a.journal
-rw-r----- 1  95404032 Oct  1 13:38 system.journal

13:41 ares07:~ # time systemctl status doesnotexist.service
doesnotexist.service
          Loaded: error (Reason: No such file or directory)
          Active: inactive (dead)


real    0m5.769s
user    0m0.000s
sys     0m0.028s

The program is disk-bound for me, as running status another time
can/will get satisfied immediately from the file cache.