[systemd-devel] [EXT] Re: slowness reading persistent journal

[Windl, Ulrich]

Hi!

SLES Support is working on it, and that support claimed that journalctl would output the journal line-by-line, calling fstat for each journal file for each line to output. So for 100 journal files and 6 million lines of journal, that number would be simply crazy. Most of all I'd wonder what the original programmer did think about it: Modern systems are fast anyway, so any algorithm would do?
Disclaimer: I did not inspect the actual code; it's just what support told me.

Kind regards,
Ulrich Windl

> -----Original Message-----
> From: systemd-devel <systemd-devel-bounces at lists.freedesktop.org> On
> Behalf Of František Šumšal
> Sent: Tuesday, May 6, 2025 4:02 PM
> To: systemd-devel at lists.freedesktop.org
> Subject: [EXT] Re: [systemd-devel] slowness reading persistent journal
> 
> Hey,
> 
> On 5/6/25 13:54, Windl, Ulrich wrote:
> > Hi,
> >
> > An update: The version I’m using (SLES 15 SP6 systemd-254.24) spends
> most of the time in fstat() cals, and I really wonder what’s going on there (say
> there are fewer than 20 files to process):
> 
> You might want to try a newer systemd version (as Vito already suggested),
> since there were several improvements in this area, like
> https://github.com/systemd/systemd/pull/30209.
> 
> > A perf example:
> >
> >
> >
> > 41245567 % time     seconds  usecs/call     calls    errors syscall
> >
> > 41245568 ------ ----------- ----------- --------- --------- ----------------
> >
> > 41245569  99.94   64.453476           1  41230003           fstat
> >
> > 41245570   0.04    0.023192           1     14234           write
> >
> > 41245571   0.01    0.007399          29       253           munmap
> >
> > 41245572   0.00    0.002771           6       432           mmap
> >
> > 41245573   0.00    0.000908           5       166        17 openat
> >
> > 41245574   0.00    0.000549           2       200           fcntl
> >
> > 41245575   0.00    0.000528           5       103           fstatfs
> >
> > 41245576   0.00    0.000262           8        32           mprotect
> >
> > 41245577   0.00    0.000120           2        49           close
> >
> > 41245578   0.00    0.000112           3        35           read
> >
> > 41245579   0.00    0.000033           2        14           getrandom
> >
> > 41245580   0.00    0.000016           4         4           brk
> >
> > 41245581   0.00    0.000012           6         2         1 statfs
> >
> > 41245582   0.00    0.000011           1         6         4 prctl
> >
> > 41245583   0.00    0.000011           1         6           getdents64
> >
> > …
> >
> > So fstat is called 41 million times. Probably more often than the whole
> journal has blocks…
> >
> > Kind regards,
> >
> > Ulrich Windl
> >
> > *From:*systemd-devel <systemd-devel-bounces at lists.freedesktop.org>
> *On Behalf Of *Windl, Ulrich
> > *Sent:* Wednesday, April 9, 2025 11:48 AM
> > *To:* systemd-devel at lists.freedesktop.org
> > *Subject:* [EXT] [systemd-devel] slowness reading persistent journal
> >
> > Hi!
> >
> > In SLES15 SP6 (systemd-254.24-150600.4.28.1.x86_64) I noticed that
> collecting logs took quite long, so I checked.
> >
> > # time journalctl |wc -l
> >
> > 2705448
> >
> > real    2m23.008s
> >
> > user    1m25.666s
> >
> > sys     0m57.389s
> >
> > The journal is persistent and it’s located on a BtrFS subvolume using a
> device that is provided by VMware from a high-performance SSD SAN
> storage:
> >
> > # lsblk
> >
> > NAME   MAJ:MIN RM  SIZE RO TYPE MOUNTPOINTS
> >
> > sda      8:0    0   40G  0 disk
> >
> > ├─sda1   8:1    0  512M  0 part /boot/efi
> >
> > ├─sda2   8:2    0   21G  0 part /root
> >
> > │                               /srv
> >
> > │                               /usr/local
> >
> > │                               /var
> >
> > │                               /opt
> >
> > │                               /tmp
> >
> > │                               /boot/grub2/x86_64-efi
> >
> > │                               /boot/grub2/i386-pc
> >
> > │                               /.snapshots
> >
> > │                               /
> >
> > ├─sda3   8:3    0 10.7G  0 part /home
> >
> > └─sda4   8:4    0  7.8G  0 part [SWAP]
> >
> > # hdparm -t /dev/sda2
> >
> > /dev/sda2:
> >
> > Timing buffered disk reads: 1680 MB in  3.00 seconds = 559.48 MB/sec
> >
> > # hdparm -T /dev/sda2
> >
> > /dev/sda2:
> >
> > Timing cached reads:   18612 MB in  2.00 seconds = 9322.49 MB/sec
> >
> > During boot this statistics had been logged:
> >
> > System Journal (/var/log/journal/41d6ce7a6cfc467297b777b8d87f071d) is
> 2.0G, max 2.1G, 103.1M free.
> >
> > Obvious question: Why is it so slow?
> >
> > Kind regards,
> >
> > Ulrich Windl
> >
> 
> 
> --
> Frantisek Sumsal
> GPG key ID: 0xFB738CE27B634E4B