[systemd-devel] Fwd: Journalctl performance

[Colin Guthrie]

'Twas brillig, and Jan Engelhardt at 01/10/13 12:42 did gyre and gimble:
> 
> 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.

Ouch 5s for a status is nasty. I guess there would be an optimisation
whereby the journal data can be skipped for a non-existant service, but
that just moves the problem as a status on a real operation would likely
take almost as long (tho' if it finds the needed number of logs
searching backwards I guess it can escape early from the lookup, so a
real world case *should* be somewhat faster generally).

Col


-- 

Colin Guthrie
gmane(at)colin.guthr.ie
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited http://www.tribalogic.net/
Open Source:
  Mageia Contributor http://www.mageia.org/
  PulseAudio Hacker http://www.pulseaudio.org/
  Trac Hacker http://trac.edgewall.org/