[RCU] zombie task hung in synchronize_rcu_expedited

[Rachel Menge]

Hello,

We are facing a soft lockup on our systems which appears to be related 
to rcu scheduling.

The bug appears as high CPU usage. Dmesg shows a soft lock which is 
associated with "zap_pid_ns_processes". I have confirmed the behavior on 
5.15 and 6.8 kernels.

This example was taken from an Ubuntu 22.04 VM running in a hyper-v 
environment.
rachel@ubuntu:~$ uname -a
Linux ubuntu 5.15.0-107-generic #117-Ubuntu SMP Fri Apr 26 12:26:49 UTC 
2024 x86_64 x86_64 x86_64 GNU/Linux

dmesg snippet:
watchdog: BUG: soft lockup - CPU#0 stuck for 212s! [npm start:306207]
Modules linked in: veth nf_conntrack_netlink xt_conntrack nft_chain_nat 
xt_MASQUERADE nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat nf_tables 
nfnetlink binfmt_misc nls_iso8859_1 intel_rapl_msr serio_raw 
intel_rapl_common hyperv_fb hv_balloon joydev mac_hid sch_fq_codel 
dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua overlay 
iptable_filter ip6table_filter ip6_tables br_netfilter bridge stp llc 
arp_tables msr efi_pstore ip_tables x_tables autofs4 btrfs 
blake2b_generic zstd_compress raid10 raid456 async_raid6_recov 
async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 
raid0 multipath linear hyperv_drm drm_kms_helper syscopyarea sysfillrect 
sysimgblt fb_sys_fops crct10dif_pclmul cec hv_storvsc crc32_pclmul 
hid_generic hv_netvsc ghash_clmulni_intel scsi_transport_fc rc_core 
sha256_ssse3 hid_hyperv drm sha1_ssse3 hv_utils hid hyperv_keyboard 
aesni_intel crypto_simd cryptd hv_vmbus
CPU: 0 PID: 306207 Comm: npm start Tainted: G             L 
5.15.0-107-generic #117-Ubuntu
Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, 
BIOS Hyper-V UEFI Release v4.1 04/06/2022
RIP: 0010:_raw_spin_unlock_irqrestore+0x25/0x30
Code: eb 8d cc cc cc 0f 1f 44 00 00 55 48 89 e5 e8 3a b8 36 ff 66 90 f7 
c6 00 02 00 00 75 06 5d e9 e2 cb 22 00 fb 66 0f 1f 44 00 00 <5d> e9 d5 
cb 22 00 0f 1f 44 00 00 0f 1f 44 00 00 55 48 89 e5 8b 07
RSP: 0018:ffffb15fc915bc60 EFLAGS: 00000206
RAX: 0000000000000001 RBX: ffffb15fc915bcf8 RCX: 0000000000000000
RDX: ffff9d4713f9c828 RSI: 0000000000000246 RDI: ffff9d4713f9c820
RBP: ffffb15fc915bc60 R08: ffff9d4713f9c828 R09: ffff9d4713f9c828
R10: 0000000000000228 R11: ffffb15fc915bcf0 R12: ffff9d4713f9c820
R13: 0000000000000004 R14: ffff9d47305a9980 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff9d4643c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fd63a1b6008 CR3: 0000000288bd6003 CR4: 0000000000370ef0
Call Trace:
 <IRQ>
 ? show_trace_log_lvl+0x1d6/0x2ea
 ? show_trace_log_lvl+0x1d6/0x2ea
 ? add_wait_queue+0x6b/0x80
 ? show_regs.part.0+0x23/0x29
 ? show_regs.cold+0x8/0xd
 ? watchdog_timer_fn+0x1be/0x220
 ? lockup_detector_update_enable+0x60/0x60
 ? __hrtimer_run_queues+0x107/0x230
 ? read_hv_clock_tsc_cs+0x9/0x30
 ? hrtimer_interrupt+0x101/0x220
 ? hv_stimer0_isr+0x20/0x30
 ? __sysvec_hyperv_stimer0+0x32/0x70
 ? sysvec_hyperv_stimer0+0x7b/0x90
 </IRQ>
 <TASK>
 ? asm_sysvec_hyperv_stimer0+0x1b/0x20
 ? _raw_spin_unlock_irqrestore+0x25/0x30
 add_wait_queue+0x6b/0x80
 do_wait+0x52/0x310
 kernel_wait4+0xaf/0x150
 ? thread_group_exited+0x50/0x50
 zap_pid_ns_processes+0x111/0x1a0
 forget_original_parent+0x348/0x360
 exit_notify+0x4a/0x210
 do_exit+0x24f/0x3c0
 do_group_exit+0x3b/0xb0
 __x64_sys_exit_group+0x18/0x20
 x64_sys_call+0x1937/0x1fa0
 do_syscall_64+0x56/0xb0
 ? do_user_addr_fault+0x1e7/0x670
 ? exit_to_user_mode_prepare+0x37/0xb0
 ? irqentry_exit_to_user_mode+0x17/0x20
 ? irqentry_exit+0x1d/0x30
 ? exc_page_fault+0x89/0x170
 entry_SYSCALL_64_after_hwframe+0x67/0xd1
RIP: 0033:0x7f60019daf8e
Code: Unable to access opcode bytes at RIP 0x7f60019daf64.
RSP: 002b:00007fff2812a468 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 00007f5ffeda01b0 RCX: 00007f60019daf8e
RDX: 00007f6001a560c0 RSI: 0000000000000000 RDI: 0000000000000001
RBP: 00007fff2812a4b0 R08: 0000000000000024 R09: 0000000800000000
R10: 0000000000000003 R11: 0000000000000246 R12: 0000000000000001
R13: 00007f60016f4a90 R14: 0000000000000000 R15: 00007f5ffede4d50
 </TASK>

Looking at the running processes, there are zombie threads
root@ubuntu:/home/rachel# ps aux | grep Z
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
rachel    305832  0.5  0.0      0     0 ?        Zsl  01:55   0:00 [npm 
start] <defunct>
rachel    308234  0.3  0.0      0     0 ?        Zl   01:55   0:00 [npm 
run zombie] <defunct>
rachel    308987  0.0  0.0      0     0 ?        Z    01:55   0:00 [sh] 
<defunct>
root      345328  0.0  0.0   6480  2220 pts/5    S+   01:56   0:00 grep 
--color=auto Z

"308234" zombie thread group shows a thread is stuck on 
synchronize_rcu_expedited
root@ubuntu:/home/rachel# ls /proc/308234/task
308234  308312
root@ubuntu:/home/rachel# cat /proc/308312/stack
[<0>] exp_funnel_lock+0x1eb/0x230
[<0>] synchronize_rcu_expedited+0x6d/0x1b0
[<0>] namespace_unlock+0xd6/0x1b0
[<0>] put_mnt_ns+0x74/0xa0
[<0>] free_nsproxy+0x1c/0x1b0
[<0>] switch_task_namespaces+0x5e/0x70
[<0>] exit_task_namespaces+0x10/0x20
[<0>] do_exit+0x212/0x3c0
[<0>] io_sq_thread+0x457/0x5b0
[<0>] ret_from_fork+0x22/0x30

To consistently reproduce the issue, disable "CONFIG_PREEMPT_RCU". It is 
unclear if this completely prevents the issue, but it is much easier to 
reproduce with preemption off. I was able to reproduce on the Ubuntu 
22.04 5.15.0-107-generic and 24.04 6.8.0-30-generic. There are 2 methods 
of reproducing. Both methods are hosted at 
https://github.com/rlmenge/rcu-soft-lock-issue-repro .

Repro using npm and docker:
Get the script here: 
https://github.com/rlmenge/rcu-soft-lock-issue-repro/blob/main/rcu-npm-repro.sh
# get image so that script doesn't keep pulling for images
$ sudo docker run telescope.azurecr.io/issue-repro/zombie:v1.1.11
$ sudo ./rcu-npm-repro.sh

This script creates several containers. Each container runs in new pid 
and mount namespaces. The container's entrypoint is `npm run task && npm 
start`.
npm run task: This command is to run `npm run zombie & npm run done` 
command.
npm run zombie: It's to run `while true; do echo zombie; sleep 1; done`. 
Infinite loop to print zombies.
npm run done: It's to run `echo done`. Short live process.
npm start: It's also a short live process. It will exit in a few seconds.

When `npm start` exits, the process tree in that pid namespace will be like
npm start (pid 1)
   |__npm run zombie
           |__ sh -c "whle true; do echo zombie; sleep 1; done"

Repro using golang:
Use the go module found here: 
https://github.com/rlmenge/rcu-soft-lock-issue-repro/blob/main/rcudeadlock.go

Run
$ go mod init rcudeadlock.go
$ go mod tidy
$ CGO_ENABLED=0 go build -o ./rcudeadlock ./
$ sudo ./rcudeadlock

This golang program is to simulate the npm reproducer without involving 
docker as dependency. This binary is using re-exec self to support 
multiple subcommands. It  also sets up processes in new pid and mount 
namespaces by unshare, since the `put_mnt_ns` is a critical code path in 
the kernel to reproduce this issue. Both mount and pid namespaces are 
required in this issue.

The entrypoint of new pid and mount namespaces is `rcudeadlock task && 
rcudeadlock start`.
rcudeadlock task: This command is to run `rcudeadlock zombie & 
rcudeadlock done`
rcudeadlock zombie: It's to run `bash -c "while true; do echo zombie; 
sleep 1; done"`. Infinite loop to print zombies.
rcudeadlock done: Prints done and exits.
rcudeadlock start: Prints `AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA` 10 times 
and exits.

When `rcudeadlock start` exits, the process tree in that pid namespace 
will be like
rcudeadlock start (pid 1)
   |__rcudeadlock zombie
           |__bash -c "while true; do echo zombie; sleep 1; done".

Each rcudeadlock process will set up 4 idle io_uring threads before 
handling commands, like `task`, `zombie`, `done` and `start`. That is 
similar to npm reproducer. Not sure that it's related to io_uring. But 
with io_uring idle threads, it's easy to reproduce this issue.

Thank you,
Rachel