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

2020-12-19 Thread Lennart Poettering
On Fr, 20.11.20 10:39, Ulrich Windl (ulrich.wi...@rz.uni-regensburg.de) 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.

How to you jump to the last lines? You are in "less" (i.e. the usual
auto-paging) and press ?  If so, the full journal needs to be
streamed to less first. That is necessarily slow if you have a lot of
log data, since it all needs to be read into memory, passed to less
which then buffers it again, counts lines and finds the "end" of it).

> 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):

Performance deteriorates with the number of journal files. There are
some O(n)'isms with the number of journal files currently. These
should be addressable though, but so far noone spent the time on this
(i.e. we can move a tiny bit more information from the file contents
into the file name so that we don't have to even open the files to be
able to know where they belong in the chronology of things)

btrfs makes things a lot worse btw, since the write pattern we employ
that are very unfriendly to CoW file systems (i.e. we do random
writes; CoW file systems can't really handle anything that aren't
linear writes). In upstream defaults we thus turn off cow for these
files, not sure if your distro undoes that though.

Lennart

--
Lennart Poettering, Berlin
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


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

2020-11-20 Thread 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
> 
> real0m21.890s
> user0m19.053s
> sys 0m3.292s
> 
> Reading all files to compare:
>  # time cat /run/log/journal/e766c8d06f144b1588487221640f55b5/* |wc -l
> 3203984
> 
> real0m0.729s
> user0m0.135s
> sys 0m0.962s
> 
>  # df /run
> Filesystem 1K-blocksUsed 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
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel