systemctl bash tab-auto-completion freezes the terminal and causes 100% CPU utilization

[mbiebl]

Submission type

• Bug report

systemd version the issue has been seen with

v237

Used distribution

Debian
Initially filed as downstream bug report at
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=890445

Using tab-auto-completion with systemctl can cause /sbin/init to go to 100% CPU utilization and lock up the terminal. This is probably due to the implementation of it's bash-completion file.

This can be replicated by typing systemctl start whatever and then quickly pressing tab a few times.

The result is first that the terminal appears to lock up; no input is accepted from the user. Additionally, CPU usage on the system goes to 100% for a long time, dependent upon how many times the user pressed tab.

[fsateler]

I can't reproduce on zsh so I change the title to mark bash as affected.

[blanet]

I meet this problem too and I tried to disable bash_completion by using:

shopt -u progcomp

and everything turn back to normal again

Anyone who can answer this and give a solution?

[nekohayo]

In my case, whenever I try to see what's available to me as "targets" to switch to, for example typing

systemctl isolate single

...I then get the system using the CPU and grinding the disk (even though it's a SSD!) locking my terminal for what feels like five minutes. And yet there's only 27 files in /etc/systemd/system, there is no reason why it should spin around like that.

Note that there is a potential patch mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1491668 for what it's worth...

[mrc0mmand]

Is this still an issue? The performance should be drastically improved by f28255e. It still takes some time as it has to go through thousands of units, but that should be matter of seconds, not minutes.

...I then get the system using the CPU and grinding the disk (even though it's a SSD!) locking my terminal for what feels like five minutes. And yet there's only 27 files in /etc/systemd/system, there is no reason why it should spin around like that.

Unfortunately, it's not simple as that. For example, in case of systemctl isolate, we have to go through all loaded (non-template) systemd units, to pick only those with AllowIsolate=true.

[poettering]

OK, let's close this given that f28255e got merged. If this is still an issue, please reopen.

[sgpinkus]

Still experiencing very slow Bash prompt tab completion with journalctl and systemctl in v 247.3-7+deb11u2 on 5.10.0-23-amd64 #1 SMP Debian 5.10.179-1 (2023-05-12) x86_64 GNU/Linux. About 10s and a big spike to ~100% CPU usage by /sbin/init.

[ipaqmaster]

Dang last comment in mid 2023? I'm still experiencing this even on an expensive NVMe host and yes I see the systemd (pid1, init) spike up to 100% of one cpu thread while it hangs on this too. Accidentally Tab'ing or Double-Esc'ing while trying to Esc-Backspace some words from the right side to the left is very painful.

Unrelated, but Saltstack's salt command's autocomplete has a similar problem. That is that they're just supposed to autofill arguments or something else quick and helpful but end up hanging the entire shell doing something else that is heavy instead.

I turned off all my bashisms with unset BASH_COMMAND PROMPT_COMMAND ; trap '' DEBUG ; PS1='$ ';

Then ran set -x to trace what the heck is going on.

Typed systemctl status <Tab> and followed the shell's completion flow

The hang + high cpu usage at that moment is because of this line: systemctl --system --full --legend=no --no-pager --plain list-unit-files

The shell completion responsible for this at least for Bash (my case) is this

systemd/shell-completion/bash/run0

Line 21 in 6de1c68

systemctl --system --full --no-legend --no-pager --plain "$@"

Which gets called by this /usr/share/bash-completion/completions/run0 which is called by __get_non_template_units here

systemd/shell-completion/bash/systemctl.in

Line 60 in 6de1c68

__get_non_template_units() { { __systemctl $1 list-unit-files "$2*"; __systemctl $1 list-units --all "$2*"; } |

strace -f -s 9999999'ing that command and professionally holding/mashing the Enter key while it runs to produce gaps in the output where the delay is - the source of the slowness is this particular part where it binds dbus-broker's socket /run/dbus/system_bus_socket to file descriptor 3 then attempts to reecvmsg from it (This is where it hangs, waiting on systemd to actually return its call, and why a single cpu thread skyrockets by the init [systemd] process during this moment), then the call is returned with a bunch of services listed:

bind(3, {sa_family=AF_UNIX, sun_path=@"6c1f71acf3876461/bus/systemctl/system"}, 40) = 0
getsockopt(3, SOL_SOCKET, SO_RCVBUF, [212992], [4]) = 0
setsockopt(3, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0
getsockopt(3, SOL_SOCKET, SO_RCVBUF, [16777216], [4]) = 0
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(3, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [16777216], [4]) = 0
connect(3, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 30) = 0
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
getsockopt(3, SOL_SOCKET, SO_PEERSEC, 0x5f842de8cc80, [64]) = -1 ENOPROTOOPT (Protocol not available)
openat(AT_FDCWD, "/proc/sys/kernel/ngroups_max", O_RDONLY|O_CLOEXEC) = 4
read(4, "65536\n", 31)                  = 6
close(4)                                = 0
mmap(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7550575b8000
getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, 0x7550575b8010, [262144 => 0]) = 0
getsockopt(3, SOL_SOCKET, SO_PEERPIDFD, [4], [4]) = 0
getpeername(3, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, [127 => 30]) = 0
fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
getsockname(3, {sa_family=AF_UNIX, sun_path=@"6c1f71acf3876461/bus/systemctl/system"}, [128 => 40]) = 0
sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL\r\nDATA\r\n", iov_len=22}, {iov_base="NEGOTIATE_UNIX_FD\r\n", iov_len=19}, {iov_base="BEGIN\r\n", iov_len=7}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 48
gettid()                                = 113157
futex(0x755057abfc84, FUTEX_WAKE_PRIVATE, 2147483647) = 0
gettid()                                = 113157
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="DATA\r\nOK 1e8c94dcaee5f5f70fb5b25b2956fc54\r\nAGREE_UNIX_FD\r\n", iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 58
sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", iov_len=128}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999948000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=24, tv_nsec=999947420})
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\v\0\0\0\377\377\377\377?\0\0\0\5\1u\0\1\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\6\0\0\0:1.403\0\0\10\1g\0\1s\0\0\6\0\0\0:1.403\0", iov_len=67}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 67
sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\4\1\10\0\0\0\2\0\0\0\252\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/systemd1\0\0\0\0\0\0\0\3\1s\0\27\0\0\0ListUnitFilesByPatterns\0\2\1s\0 \0\0\0org.freedesktop.systemd1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\4asas\0\0\0\0\0\0\0", iov_len=192}, {iov_base="\0\0\0\0\0\0\0\0", iov_len=8}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 200
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\v\0\0\0\377\377\377\377\217\0\0\0\7\1s\0\24\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="org.freedesktop.DBus\0\0\0\0\6\1s\0\6\0\0\0:1.403\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0NameAcquired\0\0\0\0\10\1g\0\1s\0\0\6\0\0\0:1.403\0", iov_len=147}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 147
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999922000}, NULL, 8


<my professional Enter-key debugging>


) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=23, tv_nsec=666846924})
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\5\324\0\0\\\27\0\0005\0\0\0\5\1u\0\2\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.403\0\0\10\1g\0\5a(ss)\0\0\0\0\0\0\7\1s\0\4\0\0\0:1.0\0\0\0\0\375\323\0\0\0\0\0\0%\0\0\0/usr/lib/systemd/system/syslog.socket\0\0\0\6\0\0\0static\0\0+\0\0\0/usr/lib/systemd/system/cloud-config.target\0\6\0\0\0static\0\0\0\0\0\0(\0\0\0/usr/lib/systemd/system/e2scrub@.service\0\0\0\0\6\0\0\0static\0\0\0\0\0\0/\0\0\0/usr/lib/systemd/system/zfs-trim-monthly@.timer\0\10\0\0\0disabled\0\0\0\0\0\0\0\0#\0\0\0/usr/lib/systemd/system/gdm.service\0\10\0\0\0disabled\0\0\0\0001\0\0\0/etc/systemd/system/podman-network-reload.service\0\0\0\7\0\0\0enabled\0\0\0\0\0D\0\0\0/usr/lib/systemd/system/systemd-pcrphase-storage-target-mode.service\0\0\0\0\6\0\0\0static\0\0'\0\0\0/usr/lib/systemd/system/ananicy.service\0\10\0\0\0disabled\0\0\0\0\0\0\0\08\0\0\0/usr/lib/systemd/system/systemd-pcrphase-sysinit.service\0\0\0\0\6\0\0\0static\0\0\0\0\0\0%\0\0\0/usr/lib/systemd/system/named.service\0\0\0\10\0\0\0disabled\0\0\0\0\0\0\0\0000\0\0\0/usr/lib/systemd/system/sys-kernel-tracing.mount\0\0\0\0\6\0\0\0static\0\0\0\0\0\0&\0\0\0/usr/lib/systemd/system/mysqld.service\0\0\5\0\0\0alias\0\0\0007\0\0\0/usr/lib/systemd/system/systemd-homed-firstboot.service\0\10\0\0\0disabled\0\0\0\0\0\0\0\0.\0\0\0/run/systemd/generator/home-mylinuxusernamehere-.local.mount\0\0\t\0\0\0generated\0\0\0\0\0\0\0'\0\0\0/usr/lib/systemd/system/machines.target\0\10\0\0\0disabled\0\0\0\0\0\0\0\0'\0\0\0/usr/lib/systemd/system/winbind.service\0\10\0\0\0disabled\0\0\0\0\0\0\0\0<\0\0\0/usr/lib/systemd/system/dbus-org.

In that output it's this line which makes the request for that information sending systemd skyrocketing:

sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\4\1\10\0\0\0\2\0\0\0\252\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/systemd1\0\0\0\0\0\0\0\3\1s\0\27\0\0\0ListUnitFilesByPatterns\0\2\1s\0 \0\0\0org.freedesktop.systemd1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\4asas\0\0\0\0\0\0\0", iov_len=192}, {iov_base="\0\0\0\0\0\0\0\0", iov_len=8}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 200

lsof /run/dbus/system_bus_socket shows that systemd (init) listens to this dbus-socket and so does of course, the dbus-broker process. This is evidently how it does its brokering. Cool.

Evidently the true issue lies in the efficiency of systemd's unit information gathering ability when systemctl --system --full --legend=no --no-pager --plain list-unit-files gets called.

Too many of these at once really queues up some work locking up my workstation in some areas (Opening a new shell has a delay for me for example). This will also be why accidentally double-Esc'ing and Tab'ing causes so much stuff to hang as it sends back to back systemctl commands to that socket and init (systemd) has to fulful the requests back to back.

Example short lockup command for about 13 seconds: threads=10 ; time yes 'systemctl --system --full --legend=no --no-pager --plain list-unit-files' | head -n${threads} | parallel -j${threads} >/dev/null 2>&1.

This probably needs to be optimized in the systemd init process. Systemd should collect this list of units either once, or at some stage during startup and only refresh that list when new services are added/enabled or maybe even only when systemctl daemon-reload is called. Or something. Anything but this terminal-freezing behavior when I just wanted to autocomplete services and accidentally had a trailing whitespace character when I Tab or accidentally Double-Esc'd on a blank.

[ipaqmaster]

Looks like this has also been discussed here in 2021: #20328 (Closed as a duplicate of the below one)

And here: #14730

I didn't know we could strace -p1 but in that issue someone already did (The true source of the delay, the waiting for it to finish).

This too: #29181

There is similar but maybe not entirely related discussion also here: #26950