[systemd-devel] Antw: [EXT] Re: Why is journalctl -b so slow?

[Ulrich Windl]

>>> Vito Caputo <vcaputo at pengaru.com> schrieb am 20.11.2020 um 20:09 in
Nachricht
<20201120190913.4t4dupzxrshonwjl at shells.gnugeneration.com>:
> On Fri, Nov 20, 2020 at 10:39:14AM +0100, Ulrich Windl wrote:
>> Hi!
>> 
>> journactl ‑b is quite fast to display the first lines, but when I want to
see 
> the last lines, it's quite slow. The journal is on BtrFS that is on a 
> hardware RAID made from two SSDs, so the _filesystem_ should not be the 
> problem (actually it seems the journal is in tmpfs actually):
>> 
>> ### done after being called before, so the file contents should be cached 
> anyway.
>> # time journalctl ‑b |wc ‑l
>> 2018589
>> 
>> real    0m21.890s
>> user    0m19.053s
>> sys     0m3.292s
>> 
>> Reading all files to compare:
>>  # time cat /run/log/journal/e766c8d06f144b1588487221640f55b5/* |wc ‑l
>> 3203984
>> 
>> real    0m0.729s
>> user    0m0.135s
>> sys     0m0.962s
>> 
>>  # df /run
>> Filesystem     1K‑blocks    Used Available Use% Mounted on
>> tmpfs          131889480 1664768 130224712   2% /run
>> 
>> systemd‑234‑24.61.1.x86_64 from SLES15 SP2.
>> 
> 
> How big are the journal files and how many are there?

While trying to determine the sizes I made a very interesting observation:
While "wc -l" is fast (less than 1 second), "wc" (without "-l") takes more
than a minute!

 # time wc -l /run/log/journal/e766c8d06f144b1588487221640f55b5/*
    126016 /run/log/journal/e766c8d06f144b1588487221640f55b5/system.journal
    237547
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000000001-0005b3f9b726314e.journal

    289220
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000002626b-0005b3fdddc1ac31.journal

    289962
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000004d777-0005b4052d952b37.journal

    267185
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000074d19-0005b40c7f1e2c5b.journal

    333123
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000009c2ad-0005b413d068abd6.journal

    266936
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000000c37d4-0005b41b203c33eb.journal

    237000
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000000ead24-0005b42270cb3177.journal

    236427
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000112238-0005b429c0dd2e09.journal

    236646
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000001396ea-0005b4310efb31c0.journal

    231837
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000160b9a-0005b4385a2b3033.journal

    226417
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000187e2a-0005b43e6ae73265.journal

    226363
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000001af146-0005b443b238b0e1.journal

   3204679 total

real    0m0.314s
user    0m0.100s
sys     0m0.215s

# time wc /run/log/journal/e766c8d06f144b1588487221640f55b5/*
    126016     831206   92274688
/run/log/journal/e766c8d06f144b1588487221640f55b5/system.journal
    237547    1275825  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000000001-0005b3f9b726314e.journal

    289220    1335438  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000002626b-0005b3fdddc1ac31.journal

    289962    1411322  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000004d777-0005b4052d952b37.journal

    267185    1348136  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000074d19-0005b40c7f1e2c5b.journal

    333123    1602322  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-000000000009c2ad-0005b413d068abd6.journal

    266936    1463014  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000000c37d4-0005b41b203c33eb.journal

    237000    1226780  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000000ead24-0005b42270cb3177.journal

    236427    1196644  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000112238-0005b429c0dd2e09.journal

    236646    1252991  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000001396ea-0005b4310efb31c0.journal

    231837    1190868  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000160b9a-0005b4385a2b3033.journal

    226417    1213569  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-0000000000187e2a-0005b43e6ae73265.journal

    226363    1214434  134217728
/run/log/journal/e766c8d06f144b1588487221640f55b5/system at 43da9abd7ab542c1b67267b7b7bddd63-00000000001af146-0005b443b238b0e1.journal

   3204679   16562549 1702887424 total

real    1m11.904s
user    1m11.516s
sys     0m0.388s

At least that answered the size question, maybe even the speed question.

> 
> Can you re‑run the command with SYSTEMD_LOG_LEVEL=debug and show the
> "mmap cache statistics" line?

Directory /run/log/journal/e766c8d06f144b1588487221640f55b5 removed.
Root directory /run/log/journal removed.
mmap cache statistics: 213666312 hit, 348 miss

> 
> Would it be possible to run journalctl ‑b under `valgrind
> ‑‑tool=callgrind` and supply the callgrind.out?  It would help
> identify where the CPU time is being spent on that set of logs.

Sorry, I can't.

> 
> Regards,
> Vito Caputo