Bug 56776
| Summary: | systemctl daemon-reload длится 45 секунд | ||
|---|---|---|---|
| Product: | Sisyphus | Reporter: | Vitaly Chikunov <vt> |
| Component: | systemd | Assignee: | Alexey Shabalin <shaba> |
| Status: | NEW --- | QA Contact: | qa-sisyphus |
| Severity: | normal | ||
| Priority: | P5 | CC: | arseny, shaba |
| Version: | unstable | ||
| Hardware: | x86 | ||
| OS: | Linux | ||
Есть ли возможность повторить тест так, чтобы system manager выводил debug-сообщения? (trap "systemctl log-level `systemctl log-level`" 0 1 2 3 6 15 systemctl log-level debug time systemctl daemon-reload ; date ) Пока что только понятно, что процесс, который по генераторам проходился, не смог завершиться с нулём и прекратил работу через 45102 ms. [Лишний раз поною о том, что никому не надо в лог-сообщениях использовать %m, ведь есть %#m. Компромисс: ": %#m (%m)"] Часть лога вокруг подвисания между 09:35:38-09:36:23: ноя 10 09:35:38 alt systemd[1]: environment-generators: no executables found. ноя 10 09:35:38 alt systemd[1]: Successfully forked off '(sd-gens)' as PID 1127. ноя 10 09:35:38 alt (sd-gens)[1127]: Successfully forked off '(generators)' as PID 1128. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/cloud-init-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1129. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/netplan ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1130. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-bless-boot-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1131. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-cryptsetup-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1132. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-debug-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1133. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-factory-reset-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1134. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-fstab-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1135. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-getty-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1136. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-gpt-auto-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1137. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1138. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-import-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1139. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-integritysetup-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1140. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-rc-local-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1142. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-run-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1143. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-ssh-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1144. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-system-update-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1145. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-sysv-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1146. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-tpm2-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1147. ноя 10 09:35:38 alt (generato[1128]: About to execute /usr/lib/systemd/system-generators/systemd-veritysetup-generator ноя 10 09:35:38 alt (generato[1128]: Successfully forked off '(exec-inner)' as PID 1148. ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-ssh-generator succeeded. ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-bless-boot-generator succeeded. ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-rc-local-generator succeeded. ноя 10 09:35:38 alt systemd-sysv-generator[1146]: SysV service '/etc/rc.d/init.d/cloud-init' lacks a native systemd unit file, automatically generating a unit file for compatibility. ноя 10 09:35:38 alt systemd-sysv-generator[1146]: Please update package to include a native systemd unit file. ноя 10 09:35:38 alt systemd-sysv-generator[1146]: ⚠️ This compatibility logic is deprecated, expect removal soon. ⚠️ ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-sysv-generator succeeded. ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-factory-reset-generator succeeded. ноя 10 09:35:38 alt (generato[1128]: /usr/lib/systemd/system-generators/systemd-system-update-generator succeeded. ноя 10 09:36:23 alt (sd-gens)[1127]: (generators) terminated by signal ALRM. ноя 10 09:36:23 alt systemd[1]: (sd-gens) failed with exit status 1. ноя 10 09:36:23 alt systemd[1]: Failed to fork off sandboxing environment for executing generators: Protocol error А в это время в ps: root 1205 0.0 0.0 22852 7520 ? S 09:39 0:00 (sd-gens) root 1206 0.0 0.0 22852 6268 ? S 09:39 0:00 \_ (generators) root 1207 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [cloud-init-gene] <defunct> root 1208 0.0 0.0 10060 5852 ? S 09:39 0:00 \_ /usr/lib/systemd/system-generators/netplan /run/systemd/generator /run/systemd/generator.early /run/systemd/generator.late root 1209 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-bless-b] <defunct> root 1211 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-debug-g] <defunct> root 1212 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-factory] <defunct> root 1213 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-fstab-g] <defunct> root 1216 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-hiberna] <defunct> root 1217 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-import-] <defunct> root 1221 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-run-gen] <defunct> root 1227 0.0 0.0 0 0 ? Z 09:39 0:00 \_ [systemd-veritys] <defunct> [root@alt ~]# lsof -p 1509 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME netplan 1509 root cwd DIR 253,1 4096 2 / netplan 1509 root rtd DIR 253,1 4096 2 / netplan 1509 root txt REG 253,1 23064 30074 /usr/lib/netplan/generate netplan 1509 root mem REG 253,1 945408 23810 /usr/lib64/libm.so.6 netplan 1509 root mem REG 253,1 444952 2664 /usr/lib64/libnss_systemd.so.2 netplan 1509 root mem REG 253,1 238032 24031 /usr/lib64/libblkid.so.1.1.0 netplan 1509 root mem REG 253,1 47792 24066 /usr/lib64/libffi.so.8.2.0 netplan 1509 root mem REG 253,1 201128 16949 /usr/lib64/libselinux.so.1 netplan 1509 root mem REG 253,1 321104 24033 /usr/lib64/libmount.so.1.1.0 netplan 1509 root mem REG 253,1 117312 23845 /usr/lib64/libz.so.1.3.1 netplan 1509 root mem REG 253,1 23088 24196 /usr/lib64/libgmodule-2.0.so.0.8600.1 netplan 1509 root mem REG 253,1 715520 23838 /usr/lib64/libpcre2-8.so.0.15.0 netplan 1509 root mem REG 253,1 31416 24029 /usr/lib64/libuuid.so.1.3.0 netplan 1509 root mem REG 253,1 129424 24089 /usr/lib64/libyaml-0.so.2.0.9 netplan 1509 root mem REG 253,1 2024560 23807 /usr/lib64/libc.so.6 netplan 1509 root mem REG 253,1 400856 24198 /usr/lib64/libgobject-2.0.so.0.8600.1 netplan 1509 root mem REG 253,1 1928360 25902 /usr/lib64/libgio-2.0.so.0.8600.1 netplan 1509 root mem REG 253,1 1402472 24192 /usr/lib64/libglib-2.0.so.0.8600.1 netplan 1509 root mem REG 253,1 360376 21548 /usr/lib64/libnetplan.so.1 netplan 1509 root mem REG 253,1 254960 23805 /usr/lib64/ld-linux-x86-64.so.2 netplan 1509 root 0u CHR 1,3 0t0 4 /dev/null netplan 1509 root 1u CHR 1,3 0t0 4 /dev/null netplan 1509 root 2u CHR 1,3 0t0 4 /dev/null netplan 1509 root 5u a_inode 0,16 0 59 [eventpoll] netplan 1509 root 6u a_inode 0,16 0 59 [timerfd] netplan 1509 root 7u unix 0x000000007ece454e 0t0 2724 type=STREAM [root@alt ~]# strace -p 1509 strace: Process 1509 attached epoll_wait(5^C Казалось бы дело в /usr/lib/systemd/system-generators/netplan, он отдыхает, а sd-gens его прибивает по таймауту (terminated by signal ALRM).
Если установить debuginfo и сделать на него (генератор) strace -k, то вылетает такой трейс:
# strace -kk -p 5734
strace: Process 5734 attached
epoll_wait(5, 0x55c87b2fde50, 16, -1) = -1 EINTR (Interrupted system call)
> /usr/lib64/libc.so.6(epoll_wait+0x17) [0x113ff7] ../sysdeps/unix/sysv/linux/epoll_wait.c:30
> /usr/lib64/libnss_systemd.so.2(sd_event_wait+0x150) [0x2e690] ../src/libsystemd/sd-event/sd-event.c:4541
> /usr/lib64/libnss_systemd.so.2(userdb_process.part.0.lto_priv.0+0x4f6) [0x2cad6] ../src/libsystemd/sd-event/sd-event.c:4836
> /usr/lib64/libnss_systemd.so.2(groupdb_by_name.constprop.0+0x1a7) [0x40db7] ../src/shared/userdb.c:1388
> /usr/lib64/libnss_systemd.so.2(_nss_systemd_getgrnam_r+0x24b) [0x1443b] ../src/nss-systemd/userdb-glue.c:296
> /usr/lib64/libc.so.6(getgrnam_r@@GLIBC_2.2.5+0x138) [0x13b698] ../nss/getXXbyYY_r.c:273
> /usr/lib64/libc.so.6(getgrnam+0xa0) [0x13b490] ../nss/getXXbyYY.c:140
> /usr/lib64/libnetplan.so.1(_netplan_g_string_free_to_file_with_permissions.constprop.0+0xc0) [0x337b0] ../src/util.c:127
> /usr/lib64/libnetplan.so.1(_netplan_netdef_write_network_file+0x119d) [0x166fd] ../src/networkd.c:1122
> /usr/lib64/libnetplan.so.1(_netplan_netdef_write_networkd+0x7ed) [0x1895d] ../src/networkd.c:1541
> /usr/lib/netplan/generate(main+0x7bb) [0x2c0b] ../src/generate.c:293
> /usr/lib64/libc.so.6(__libc_start_call_main+0x7d) [0x2a1ad] ../sysdeps/nptl/libc_start_call_main.h:58
> /usr/lib64/libc.so.6(__libc_start_main@@GLIBC_2.34+0x88) [0x2a268] ../csu/libc-start.c:360
> /usr/lib/netplan/generate(_start+0x24) [0x3294] ../src/generate.c:322
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=5732, si_uid=0} ---
То есть зависание в getgrnam(3) и далее в libnss_systemd.so
# gstack 6072 #0 0x00007fdaba52fff7 in epoll_wait (epfd=5, events=0x55da0449be50, maxevents=16, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00007fdaba20d691 in epoll_wait_usec (fd=<optimized out>, events=<optimized out>, maxevents=16, timeout=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4541 #2 process_epoll (e=0x55da0449b230, timeout=<optimized out>, threshold=9223372036854775807, ret_min_priority=<synthetic pointer>) at ../src/libsystemd/sd-event/sd-event.c:4564 #3 sd_event_wait (e=<optimized out>, timeout=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4687 #4 0x00007fdaba20bad7 in sd_event_run (timeout=18446744073709551615, e=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4836 #5 userdb_process.part.0.lto_priv.0 (iterator=0x55da04477af0, ret_user_record=0x0, ret_group_record=0x7fff08461100, ret_user_name=0x0, ret_group_name=0x0) at ../src/shared/userdb.c:694 #6 0x00007fdaba21fdb8 in userdb_process (iterator=0x55da04477af0, ret_user_record=0x0, ret_group_record=0x7fff08461100, ret_user_name=0x0, ret_group_name=0x0) at ../src/shared/userdb.c:1388 #7 groupdb_by_name.constprop.0 (name=0x7fdaba9ebe1b "systemd-network", flags=9, ret=0x7fff08461180, match=0x0) at ../src/shared/userdb.c:1389 #8 0x00007fdaba1f343c in userdb_getgrnam (name=0x7fdaba9ebe1b "systemd-network", gr=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=1024, errnop=<synthetic pointer>) at ../src/nss-systemd/userdb-glue.c:23 #9 _nss_systemd_getgrnam_r (name=0x7fdaba9ebe1b "systemd-network", gr=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=1024, errnop=0x7fdaba24c808) at ../src/nss-systemd/nss-systemd.c:464 #10 0x00007fdaba557699 in __getgrnam_r (name=name@entry=0x7fdaba9ebe1b "systemd-network", resbuf=resbuf@entry=0x7fdaba615d80 <resbuf>, buffer=0x55da04490920 "systemd-network", buflen=buflen@entry=1024, result=result@entry=0x7fff08461350) at ../nss/getXXbyYY_r.c:273 #11 0x00007fdaba557491 in getgrnam (name=name@entry=0x7fdaba9ebe1b "systemd-network") at ../nss/getXXbyYY.c:140 #12 0x00007fdaba9de7b1 in _netplan_g_string_free_to_file_with_permissions.constprop.0 (s=s@entry=0x55da0448eca0, rootdir=rootdir@entry=0x0, path=path@entry=0x55da0448ee10 "run/systemd/network/10-netplan-ens3", suffix=suffix@entry=0x7fdaba9ebe2b ".network", group=group@entry=0x7fdaba9ebe1b "systemd-network", mode=mode@entry=416, owner=0x7fdaba9eb2f1 "root") at ../src/util.c:127 #13 0x00007fdaba9c16fe in _netplan_netdef_write_network_file (np_state=np_state@entry=0x55da0448d8d0, def=def@entry=0x55da0447f690, rootdir=rootdir@entry=0x0, path=path@entry=0x55da0448ee10 "run/systemd/network/10-netplan-ens3", has_been_written=has_been_written@entry=0x7fff084615d0, error=error@entry=0x7fff084615b8) at ../src/networkd.c:1122 #14 0x00007fdaba9c395e in _netplan_netdef_write_networkd (np_state=0x55da0448d8d0, def=def@entry=0x55da0447f690, rootdir=0x0, has_been_written=has_been_written@entry=0x7fff084615d0, error=error@entry=0x7fff084615b8) at ../src/networkd.c:1541 #15 0x000055d9cb37fc0c in main (argc=<optimized out>, argv=<optimized out>) at ../src/generate.c:293 Если поменять /etc/nsswitch.conf - group: files [SUCCESS=merge] systemd + group: files То зависание пропадает. По идее, `lslogins -g systemd-network` делает такой же вызов getgrnam(3). 1. Если делать независимые запуски `lslogins -g systemd-network`, то они не зависают. 2. Если сделать `systemctl daemon-reload`, который подвисает и в это время сделать `lslogins -g systemd-network`, то оно тоже подвисает до конца daemon-reload. Значит какой-то ресурс блокируется. После реинсталла systemd в /etc/nsswitch.conf появляется строка group: files [SUCCESS=merge] [SUCCESS=merge] systemd Два раза "[SUCCESS=merge]". Но, с такой ошибочной конфигурацией `systemctl daemon-reload` перестает подвисать. |
Description
Vitaly Chikunov 2025-11-09 05:03:47 MSKВнутри виртуалки с Сизифом обновленное dist-upgrade + reboot команда `systemctl daemon-reload` длится 45 секунд, что плохо сказывается на UI/UX. Лог: [root@alt ~]# rpm -q systemd systemd-258.1-alt1.x86_64 [root@alt ~]# time systemctl daemon-reload ; date 0.00user 0.00system 0:45.13elapsed 0%CPU (0avgtext+0avgdata 11604maxresident)k 0inputs+0outputs (0major+616minor)pagefaults 0swaps Вс 09 ноя 2025 01:52:58 UTC В это время в journalctl -f: ноя 09 01:52:13 alt systemd[1]: Reload requested from client PID 1146 ('systemctl') (unit session-1.scope)... ноя 09 01:52:13 alt systemd[1]: Reloading... ноя 09 01:52:13 alt systemd-sysv-generator[1189]: SysV service '/etc/rc.d/init.d/cloud-init' lacks a native systemd unit file, automatically generating a unit file for compatibility. ноя 09 01:52:13 alt systemd-sysv-generator[1189]: Please update package to include a native systemd unit file. ноя 09 01:52:13 alt systemd-sysv-generator[1189]: ⚠️ This compatibility logic is deprecated, expect removal soon. ⚠️ ноя 09 01:52:58 alt systemd[1]: Failed to fork off sandboxing environment for executing generators: Protocol error ноя 09 01:52:58 alt systemd[1]: Reloading finished in 45102 ms. ноя 09 01:52:58 alt audit: BPF prog-id=45 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=31 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=46 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=47 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=32 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=33 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=48 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=34 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=49 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=50 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=35 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=36 op=UNLOAD ноя 09 01:52:58 alt kernel: kauditd_printk_skb: 18 callbacks suppressed ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:129): prog-id=45 op=LOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:130): prog-id=31 op=UNLOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:131): prog-id=46 op=LOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:132): prog-id=47 op=LOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:133): prog-id=32 op=UNLOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:134): prog-id=33 op=UNLOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:135): prog-id=48 op=LOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:136): prog-id=34 op=UNLOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:137): prog-id=49 op=LOAD ноя 09 01:52:58 alt kernel: audit: type=1334 audit(1762653178.283:138): prog-id=50 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=51 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=37 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=52 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=53 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=38 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=39 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=54 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=40 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=55 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=41 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=56 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=42 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=57 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=58 op=LOAD ноя 09 01:52:58 alt audit: BPF prog-id=43 op=UNLOAD ноя 09 01:52:58 alt audit: BPF prog-id=44 op=UNLOAD При strace он отдыхает во время ppoll([{fd=3<socket:[10822]>, events=POLLIN}], 1, {tv_sec=89, tv_nsec=966286000}, NULL, 8 <тут> ) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=44, tv_nsec=872776652}) где 3 это `/run/systemd/private`.