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-boun...@lists.freedesktop.org> *On Behalf
Of *Windl, Ulrich
*Sent:* Wednesday, April 9, 2025 11:48 AM
*To:* systemd-devel@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
