[systemd-devel] slowness reading persistent journal

[Windl, Ulrich]

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

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20250506/08173319/attachment-0001.htm>