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 On
> Behalf Of František Šumšal
> Sent: Tuesday, May 6, 2025 4:02 PM
> To: [email protected]
> 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.33 2 14 getrandom
> >
> > 41245580 0.00 0.16 4 4 brk
> >
> > 41245581 0.00 0.12 6 2 1 statfs
> >
> > 41245582 0.00 0.11 1 6 4 prctl
> >
> > 41245583 0.00 0.11 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
> *On Behalf Of *Windl, Ulrich
> > *Sent:* Wednesday, April 9, 2025 11:48 AM
> > *To:* [email protected]
> > *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
