Re: [systemd-devel] Why is journalctl -b so slow?
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?
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
[systemd-devel] Why is journalctl -b so slow?
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. Regards, Ulrich ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
