[systemd-devel] slowness reading persistent journal

[František Šumšal]

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