[systemd-devel] Why is journalctl -b so slow?

[Vito Caputo]

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?

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

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.

Regards,
Vito Caputo