systemctl list-unit-files takes more than a second

[mbiebl]

systemd version the issue has been seen with

v241,
but also reproducible with v244

Filed as downstream bug report https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=946961

Listing systemd units takes more than a second on a rather fast
system:

# time systemctl list-unit-files | wc
351     703   19219

real	0m1.107s
user	0m0.000s
sys	0m0.013s

Adding a filter makes it run twice as long:

# time systemctl --state=enabled list-unit-files | wc
     63     127    2890

real	0m2.153s
user	0m0.010s
sys	0m0.002s

During this time, the PID 1 (systemd) makes an inordinate number
of file access system calls (counts, from the strace output):

      1 accept4
      1 getsockname
      1 sendmsg
      2 setsockopt
      3 epoll_ctl
      3 recvmsg
      4 clock_gettime
      4 epoll_wait
      7 getsockopt
    496 read
  30535 fstat
  33505 close
  39334 getdents64
  40030 fcntl
  45839 openat
  98565 readlinkat

This is a serious usability problem because of the perceived
delay during interactive work.

This behaviour is observed on several installations of the
up-to-date Debian Buster. This seems to be a regression compared
to the Stretch version:

# systemctl --version 
systemd 232
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP
+LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID
+ELFUTILS +KMOD +IDN
# time systemctl list-unit-files | wc
    252     505   12274

real	0m0.057s
user	0m0.000s
sys	0m0.004s
# time systemctl --state=enabled list-unit-files | wc
     36      73    1179

real	0m0.059s
user	0m0.000s
sys	0m0.000s

Looking at some versions in between (234, 237), the regression
seems to be cumulative, rather than something that happened in a
single commit.

For fun, I ran this also on a Rasperry Pi:

     53     107    2318

real	0m10,630s
user	0m0,022s
sys	0m0,046s

[Werkov]

See also efforts in #20328.

[argonius2412]

We still can see this issue f.e. on all ubuntu 20.04 (systemd: 245.4-4ubuntu3.15 )machines. when going back on ubuntu 18.04 (systemd: 237-3ubuntu10.52) the issue is gone.

The readlinkat() function is called sooo many times, that the called programm takes > double of the time

[msp729]

On my system (arch, linux 6.1.9, systemd 252.5), systemctl list-unit-files --all takes about 5.8 seconds immediately after boot. Repeated strace runs have indicated that a single ppoll call is taking nearly all this time.
The call usually looks like this:
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999959000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=19, tv_nsec=198775486})
The tv_nsec numbers will vary, but the first will invariably be nearly 1000000000, and the second will be much lower.

[Werkov]

@msp729 Thanks for sharing. However, note that stracing systemctl process is not that relevant (I assume you did that and not strace -p1), the poll is a wait for PID1 to respond and that's where the slowness stems from as we've known by know :-/