Messages in this thread | | | Date | Mon, 20 Mar 2023 16:29:05 +0800 | From | Pengfei Xu <> | Subject | [Syzkaller & bisect] There is "tp_perf_event_destroy" task hung in v6.3-rc3 kernel |
| |
Hi Pavel Begunkov and kernel experts,
Greeting!
Platform: x86 platforms. There is "tp_perf_event_destroy" task hung in v6.3-rc3 kernel.
All detailed info: https://github.com/xupengfe/syzkaller_logs/tree/main/230318_215818_tp_perf_event_destroy Reproduced code: https://github.com/xupengfe/syzkaller_logs/blob/main/230318_215818_tp_perf_event_destroy/repro.c Kconfig: https://github.com/xupengfe/syzkaller_logs/blob/main/230318_215818_tp_perf_event_destroy/kconfig_origin v6.3-rc3 issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/230318_215818_tp_perf_event_destroy/v6.3-rc3_issue_dmesg.log Bisect info: https://github.com/xupengfe/syzkaller_logs/blob/main/230318_215818_tp_perf_event_destroy/bisect_info.log
Confirmed this issue could be reproduced in v6.3-rc3 kernel in 2300s.
Bisected between v6.3-rc2 and v5.11 and found bad commit in last week: " 846072f16eed3b3fb4e59b677f3ed8afb8509b89 io_uring: mimimise io_cqring_wait_schedule " It's just suspected commit, because reverted the above commit on top of v6.3-rc2 and made kernel failed, and could not verify after reverted the commit.
" [ 158.190103] hrtimer: interrupt took 948122 ns [ 168.878677] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 2522 jiffies old. [ 199.374623] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 10146 jiffies old. [ 289.871462] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 32770 jiffies old. [ 447.599142] INFO: task repro:419 blocked for more than 147 seconds. [ 447.600607] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 447.603309] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 447.604861] task:repro state:D stack:0 pid:419 ppid:395 flags:0x00004002 [ 447.607597] Call Trace: [ 447.608530] <TASK> [ 447.610781] __schedule+0x40a/0xc30 [ 447.613504] schedule+0x5b/0xe0 [ 447.614867] schedule_preempt_disabled+0x1c/0x30 [ 447.616254] __mutex_lock+0x824/0xcb0 [ 447.618529] ? perf_trace_destroy+0x21/0xa0 [ 447.619831] ? perf_trace_destroy+0x21/0xa0 [ 447.622075] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.623795] mutex_lock_nested+0x1f/0x30 [ 447.624987] ? mutex_lock_nested+0x1f/0x30 [ 447.627019] perf_trace_destroy+0x21/0xa0 [ 447.628315] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.630454] tp_perf_event_destroy+0x1e/0x30 [ 447.631886] _free_event+0x101/0x810 [ 447.633787] put_event+0x3c/0x50 [ 447.635214] perf_event_release_kernel+0x2de/0x360 [ 447.636510] ? perf_event_release_kernel+0x9/0x360 [ 447.639127] ? __pfx_perf_release+0x10/0x10 [ 447.640646] perf_release+0x22/0x30 [ 447.642731] __fput+0x11f/0x450 [ 447.644831] ____fput+0x1e/0x30 [ 447.646309] task_work_run+0xb6/0x120 [ 447.648178] do_exit+0x547/0x12b0 [ 447.650481] ? write_comp_data+0x2f/0x90 [ 447.652453] do_group_exit+0x5e/0xf0 [ 447.654929] get_signal+0x1465/0x14a0 [ 447.658053] arch_do_signal_or_restart+0x33/0x280 [ 447.661093] exit_to_user_mode_prepare+0x13b/0x210 [ 447.663714] syscall_exit_to_user_mode+0x2d/0x60 [ 447.665332] do_syscall_64+0x4a/0x90 [ 447.666695] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 447.668028] RIP: 0033:0x7f7722b9159d [ 447.669404] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 447.671273] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 447.672733] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 447.674936] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 447.676392] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 447.678602] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 447.682294] </TASK> [ 447.683218] INFO: task repro:416 blocked for more than 147 seconds. [ 447.684574] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 447.686549] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 447.688092] task:repro state:D stack:0 pid:416 ppid:404 flags:0x00004002 [ 447.690853] Call Trace: [ 447.691788] <TASK> [ 447.693419] __schedule+0x40a/0xc30 [ 447.695782] ? wait_for_completion+0x7b/0x180 [ 447.697262] schedule+0x5b/0xe0 [ 447.698585] schedule_timeout+0x4db/0x5b0 [ 447.700870] ? schedule_timeout+0x9/0x5b0 [ 447.703596] ? wait_for_completion+0x7b/0x180 [ 447.704925] wait_for_completion+0xa6/0x180 [ 447.707869] __wait_rcu_gp+0x136/0x160 [ 447.709489] ? __pfx_arch_ftrace_ops_list_func+0x10/0x10 [ 447.711137] synchronize_rcu_tasks_generic.part.24+0x3b/0x60 [ 447.712538] ? __pfx_call_rcu_tasks+0x10/0x10 [ 447.714614] ? __pfx_wakeme_after_rcu+0x10/0x10 [ 447.716657] ? verify_cpu+0x10/0x100 [ 447.719178] synchronize_rcu_tasks_generic+0x24/0x70 [ 447.720588] synchronize_rcu_tasks+0x19/0x20 [ 447.722680] ftrace_shutdown+0x1cc/0x410 [ 447.724567] unregister_ftrace_function+0x35/0x230 [ 447.726917] ? __sanitizer_cov_trace_switch+0x57/0xa0 [ 447.728819] perf_ftrace_event_register+0x95/0xf0 [ 447.730371] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.731759] perf_trace_destroy+0x3a/0xa0 [ 447.733061] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.735193] tp_perf_event_destroy+0x1e/0x30 [ 447.736623] _free_event+0x101/0x810 [ 447.739130] put_event+0x3c/0x50 [ 447.740550] perf_event_release_kernel+0x2de/0x360 [ 447.742608] ? perf_event_release_kernel+0x9/0x360 [ 447.744492] ? __pfx_perf_release+0x10/0x10 [ 447.746758] perf_release+0x22/0x30 [ 447.748114] __fput+0x11f/0x450 [ 447.750960] ____fput+0x1e/0x30 [ 447.752297] task_work_run+0xb6/0x120 [ 447.754904] do_exit+0x547/0x12b0 [ 447.756524] ? write_comp_data+0x2f/0x90 [ 447.759255] do_group_exit+0x5e/0xf0 [ 447.761004] get_signal+0x1465/0x14a0 [ 447.764701] arch_do_signal_or_restart+0x33/0x280 [ 447.768441] exit_to_user_mode_prepare+0x13b/0x210 [ 447.770797] syscall_exit_to_user_mode+0x2d/0x60 [ 447.772266] do_syscall_64+0x4a/0x90 [ 447.774354] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 447.775680] RIP: 0033:0x7f7722b9159d [ 447.776887] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 447.779720] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 447.781345] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 447.782803] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 447.784258] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 447.786464] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 447.790697] </TASK> [ 447.792534] INFO: task repro:425 blocked for more than 147 seconds. [ 447.794718] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 447.795940] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 447.798661] task:repro state:D stack:0 pid:425 ppid:402 flags:0x00004002 [ 447.800661] Call Trace: [ 447.802321] <TASK> [ 447.803798] __schedule+0x40a/0xc30 [ 447.806473] schedule+0x5b/0xe0 [ 447.807823] schedule_preempt_disabled+0x1c/0x30 [ 447.809344] __mutex_lock+0x824/0xcb0 [ 447.810920] ? perf_trace_destroy+0x21/0xa0 [ 447.812215] ? perf_trace_destroy+0x21/0xa0 [ 447.815033] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.816749] mutex_lock_nested+0x1f/0x30 [ 447.818843] ? mutex_lock_nested+0x1f/0x30 [ 447.820158] perf_trace_destroy+0x21/0xa0 [ 447.822200] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.823589] tp_perf_event_destroy+0x1e/0x30 [ 447.825022] _free_event+0x101/0x810 [ 447.827503] put_event+0x3c/0x50 [ 447.828928] perf_event_release_kernel+0x2de/0x360 [ 447.830969] ? perf_event_release_kernel+0x9/0x360 [ 447.832864] ? __pfx_perf_release+0x10/0x10 [ 447.835090] perf_release+0x22/0x30 [ 447.836443] __fput+0x11f/0x450 [ 447.839498] ____fput+0x1e/0x30 [ 447.840832] task_work_run+0xb6/0x120 [ 447.842867] do_exit+0x547/0x12b0 [ 447.844491] ? write_comp_data+0x2f/0x90 [ 447.847194] do_group_exit+0x5e/0xf0 [ 447.848942] get_signal+0x1465/0x14a0 [ 447.852641] arch_do_signal_or_restart+0x33/0x280 [ 447.856372] exit_to_user_mode_prepare+0x13b/0x210 [ 447.858710] syscall_exit_to_user_mode+0x2d/0x60 [ 447.860202] do_syscall_64+0x4a/0x90 [ 447.862295] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 447.863624] RIP: 0033:0x7f7722b9159d [ 447.864844] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 447.867459] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 447.868934] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 447.870577] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 447.872051] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 447.874268] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 447.877963] </TASK> [ 447.878914] INFO: task repro:427 blocked for more than 147 seconds. [ 447.880283] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 447.882254] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 447.883809] task:repro state:D stack:0 pid:427 ppid:403 flags:0x00004002 [ 447.886569] Call Trace: [ 447.887508] <TASK> [ 447.888991] __schedule+0x40a/0xc30 [ 447.892252] schedule+0x5b/0xe0 [ 447.894255] schedule_preempt_disabled+0x1c/0x30 [ 447.895625] __mutex_lock+0x824/0xcb0 [ 447.897381] ? perf_trace_destroy+0x21/0xa0 [ 447.898713] ? perf_trace_destroy+0x21/0xa0 [ 447.900811] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.903238] mutex_lock_nested+0x1f/0x30 [ 447.904426] ? mutex_lock_nested+0x1f/0x30 [ 447.906460] perf_trace_destroy+0x21/0xa0 [ 447.907770] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.909320] tp_perf_event_destroy+0x1e/0x30 [ 447.910792] _free_event+0x101/0x810 [ 447.912539] put_event+0x3c/0x50 [ 447.914682] perf_event_release_kernel+0x2de/0x360 [ 447.915979] ? perf_event_release_kernel+0x9/0x360 [ 447.918019] ? __pfx_perf_release+0x10/0x10 [ 447.919501] perf_release+0x22/0x30 [ 447.920856] __fput+0x11f/0x450 [ 447.923141] ____fput+0x1e/0x30 [ 447.924447] task_work_run+0xb6/0x120 [ 447.927780] do_exit+0x547/0x12b0 [ 447.931182] ? write_comp_data+0x2f/0x90 [ 447.934722] do_group_exit+0x5e/0xf0 [ 447.936532] get_signal+0x1465/0x14a0 [ 447.940264] arch_do_signal_or_restart+0x33/0x280 [ 447.944018] exit_to_user_mode_prepare+0x13b/0x210 [ 447.945794] syscall_exit_to_user_mode+0x2d/0x60 [ 447.947286] do_syscall_64+0x4a/0x90 [ 447.948652] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 447.950725] RIP: 0033:0x7f7722b9159d [ 447.951943] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 447.954535] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 447.955993] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 447.958422] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 447.959904] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 447.962104] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 447.965788] </TASK> [ 447.967915] INFO: task repro:430 blocked for more than 147 seconds. [ 447.969442] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 447.970680] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 447.972193] task:repro state:D stack:0 pid:430 ppid:407 flags:0x00004002 [ 447.975058] Call Trace: [ 447.975971] <TASK> [ 447.977557] __schedule+0x40a/0xc30 [ 447.980071] schedule+0x5b/0xe0 [ 447.981674] schedule_preempt_disabled+0x1c/0x30 [ 447.983036] __mutex_lock+0x824/0xcb0 [ 447.984557] ? perf_trace_destroy+0x21/0xa0 [ 447.986555] ? perf_trace_destroy+0x21/0xa0 [ 447.988600] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.990982] mutex_lock_nested+0x1f/0x30 [ 447.992143] ? mutex_lock_nested+0x1f/0x30 [ 447.993565] perf_trace_destroy+0x21/0xa0 [ 447.994841] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 447.996222] tp_perf_event_destroy+0x1e/0x30 [ 447.998367] _free_event+0x101/0x810 [ 448.000101] put_event+0x3c/0x50 [ 448.001662] perf_event_release_kernel+0x2de/0x360 [ 448.002946] ? perf_event_release_kernel+0x9/0x360 [ 448.004795] ? __pfx_perf_release+0x10/0x10 [ 448.007013] perf_release+0x22/0x30 [ 448.008339] __fput+0x11f/0x450 [ 448.011124] ____fput+0x1e/0x30 [ 448.012434] task_work_run+0xb6/0x120 [ 448.014990] do_exit+0x547/0x12b0 [ 448.016581] ? write_comp_data+0x2f/0x90 [ 448.019455] do_group_exit+0x5e/0xf0 [ 448.021888] get_signal+0x1465/0x14a0 [ 448.024789] arch_do_signal_or_restart+0x33/0x280 [ 448.028453] exit_to_user_mode_prepare+0x13b/0x210 [ 448.030753] syscall_exit_to_user_mode+0x2d/0x60 [ 448.032208] do_syscall_64+0x4a/0x90 [ 448.033709] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 448.035025] RIP: 0033:0x7f7722b9159d [ 448.036207] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 448.038759] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 448.040195] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 448.042361] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 448.043795] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 448.045938] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 448.049568] </TASK> [ 448.050486] INFO: task repro:429 blocked for more than 147 seconds. [ 448.051815] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 448.053012] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 448.055229] task:repro state:D stack:0 pid:429 ppid:405 flags:0x00004002 [ 448.057355] Call Trace: [ 448.058283] <TASK> [ 448.059750] __schedule+0x40a/0xc30 [ 448.062372] schedule+0x5b/0xe0 [ 448.063668] schedule_preempt_disabled+0x1c/0x30 [ 448.065033] __mutex_lock+0x824/0xcb0 [ 448.067309] ? perf_trace_destroy+0x21/0xa0 [ 448.068608] ? perf_trace_destroy+0x21/0xa0 [ 448.071370] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 448.073039] mutex_lock_nested+0x1f/0x30 [ 448.074912] ? mutex_lock_nested+0x1f/0x30 [ 448.076183] perf_trace_destroy+0x21/0xa0 [ 448.078436] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 448.079810] tp_perf_event_destroy+0x1e/0x30 [ 448.081347] _free_event+0x101/0x810 [ 448.083069] put_event+0x3c/0x50 [ 448.084464] perf_event_release_kernel+0x2de/0x360 [ 448.086454] ? perf_event_release_kernel+0x9/0x360 [ 448.088274] ? __pfx_perf_release+0x10/0x10 [ 448.090457] perf_release+0x22/0x30 [ 448.091767] __fput+0x11f/0x450 [ 448.093960] ____fput+0x1e/0x30 [ 448.095257] task_work_run+0xb6/0x120 [ 448.097088] do_exit+0x547/0x12b0 [ 448.099437] ? write_comp_data+0x2f/0x90 [ 448.101545] do_group_exit+0x5e/0xf0 [ 448.103335] get_signal+0x1465/0x14a0 [ 448.106454] arch_do_signal_or_restart+0x33/0x280 [ 448.110172] exit_to_user_mode_prepare+0x13b/0x210 [ 448.111829] syscall_exit_to_user_mode+0x2d/0x60 [ 448.113466] do_syscall_64+0x4a/0x90 [ 448.114851] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 448.116187] RIP: 0033:0x7f7722b9159d [ 448.118140] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 448.120035] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 448.122386] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 448.123860] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 448.126074] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 448.127550] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 448.131287] </TASK> [ 448.134851] INFO: task repro:432 blocked for more than 147 seconds. [ 448.136243] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 448.138626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 448.140159] task:repro state:D stack:0 pid:432 ppid:408 flags:0x00004002 [ 448.142863] Call Trace: [ 448.143792] <TASK> [ 448.145398] __schedule+0x40a/0xc30 [ 448.147962] schedule+0x5b/0xe0 [ 448.149422] schedule_preempt_disabled+0x1c/0x30 [ 448.150827] __mutex_lock+0x824/0xcb0 [ 448.152393] ? perf_trace_destroy+0x21/0xa0 [ 448.154403] ? perf_trace_destroy+0x21/0xa0 [ 448.156514] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 448.158931] mutex_lock_nested+0x1f/0x30 [ 448.160129] ? mutex_lock_nested+0x1f/0x30 [ 448.162120] perf_trace_destroy+0x21/0xa0 [ 448.163428] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 448.164823] tp_perf_event_destroy+0x1e/0x30 [ 448.166560] _free_event+0x101/0x810 [ 448.168290] put_event+0x3c/0x50 [ 448.170417] perf_event_release_kernel+0x2de/0x360 [ 448.171702] ? perf_event_release_kernel+0x9/0x360 [ 448.173692] ? __pfx_perf_release+0x10/0x10 [ 448.175180] perf_release+0x22/0x30 [ 448.176497] __fput+0x11f/0x450 [ 448.179260] ____fput+0x1e/0x30 [ 448.180566] task_work_run+0xb6/0x120 [ 448.183105] do_exit+0x547/0x12b0 [ 448.184687] ? write_comp_data+0x2f/0x90 [ 448.187344] do_group_exit+0x5e/0xf0 [ 448.189059] get_signal+0x1465/0x14a0 [ 448.192701] arch_do_signal_or_restart+0x33/0x280 [ 448.196614] exit_to_user_mode_prepare+0x13b/0x210 [ 448.198944] syscall_exit_to_user_mode+0x2d/0x60 [ 448.200401] do_syscall_64+0x4a/0x90 [ 448.202466] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 448.203774] RIP: 0033:0x7f7722b9159d [ 448.204969] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 448.206968] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 448.208411] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 448.210569] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 448.212008] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 448.214165] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 448.217786] </TASK> [ 448.218689] [ 448.218689] Showing all locks held in the system: [ 448.220025] 1 lock held by rcu_tasks_kthre/11: [ 448.221304] #0: ffffffff83d63490 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 448.224867] 1 lock held by rcu_tasks_rude_/12: [ 448.226732] #0: ffffffff83d63210 (rcu_tasks_rude.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 448.231085] 1 lock held by rcu_tasks_trace/13: [ 448.232239] #0: ffffffff83d62f50 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 448.236085] 1 lock held by khungtaskd/29: [ 448.237918] #0: ffffffff83d63ea0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x1b/0x1e0 [ 448.242209] 1 lock held by repro/419: [ 448.243265] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.247475] 2 locks held by repro/416: [ 448.248529] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.252631] #1: ffffffff83e1cd68 (ftrace_lock){+.+.}-{3:3}, at: unregister_ftrace_function+0x2b/0x230 [ 448.256342] 1 lock held by repro/425: [ 448.258088] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.262205] 1 lock held by repro/427: [ 448.263242] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.267384] 1 lock held by repro/430: [ 448.268413] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.272557] 1 lock held by repro/429: [ 448.274354] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.278575] 1 lock held by repro/432: [ 448.279631] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 448.283856] [ 448.284660] ============================================= [ 448.284660] [ 560.206631] rcu_tasks_wait_gp: rcu_tasks grace period number 9 (since boot) is 100354 jiffies old. [ 595.054648] INFO: task repro:419 blocked for more than 294 seconds. [ 595.056103] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 595.058758] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 595.060338] task:repro state:D stack:0 pid:419 ppid:395 flags:0x00004002 [ 595.063086] Call Trace: [ 595.064000] <TASK> [ 595.065607] __schedule+0x40a/0xc30 [ 595.068094] schedule+0x5b/0xe0 [ 595.070083] schedule_preempt_disabled+0x1c/0x30 [ 595.071455] __mutex_lock+0x824/0xcb0 [ 595.073013] ? perf_trace_destroy+0x21/0xa0 [ 595.075071] ? perf_trace_destroy+0x21/0xa0 [ 595.077326] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.079050] mutex_lock_nested+0x1f/0x30 [ 595.080202] ? mutex_lock_nested+0x1f/0x30 [ 595.082179] perf_trace_destroy+0x21/0xa0 [ 595.083467] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.084920] tp_perf_event_destroy+0x1e/0x30 [ 595.087110] _free_event+0x101/0x810 [ 595.088829] put_event+0x3c/0x50 [ 595.090414] perf_event_release_kernel+0x2de/0x360 [ 595.091753] ? perf_event_release_kernel+0x9/0x360 [ 595.093819] ? __pfx_perf_release+0x10/0x10 [ 595.095386] perf_release+0x22/0x30 [ 595.096766] __fput+0x11f/0x450 [ 595.099583] ____fput+0x1e/0x30 [ 595.100926] task_work_run+0xb6/0x120 [ 595.103524] do_exit+0x547/0x12b0 [ 595.105921] ? write_comp_data+0x2f/0x90 [ 595.107947] do_group_exit+0x5e/0xf0 [ 595.110439] get_signal+0x1465/0x14a0 [ 595.113659] arch_do_signal_or_restart+0x33/0x280 [ 595.116675] exit_to_user_mode_prepare+0x13b/0x210 [ 595.119104] syscall_exit_to_user_mode+0x2d/0x60 [ 595.120655] do_syscall_64+0x4a/0x90 [ 595.122788] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 595.124137] RIP: 0033:0x7f7722b9159d [ 595.126152] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 595.128042] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 595.130250] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 595.131772] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 595.134033] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 595.135572] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 595.139283] </TASK> [ 595.140217] INFO: task repro:416 blocked for more than 294 seconds. [ 595.142705] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 595.143964] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 595.146263] task:repro state:D stack:0 pid:416 ppid:404 flags:0x00004002 [ 595.148288] Call Trace: [ 595.150743] <TASK> [ 595.152189] __schedule+0x40a/0xc30 [ 595.154648] ? wait_for_completion+0x7b/0x180 [ 595.156049] schedule+0x5b/0xe0 [ 595.157468] schedule_timeout+0x4db/0x5b0 [ 595.159739] ? schedule_timeout+0x9/0x5b0 [ 595.162351] ? wait_for_completion+0x7b/0x180 [ 595.163685] wait_for_completion+0xa6/0x180 [ 595.165981] __wait_rcu_gp+0x136/0x160 [ 595.167439] ? __pfx_arch_ftrace_ops_list_func+0x10/0x10 [ 595.169325] synchronize_rcu_tasks_generic.part.24+0x3b/0x60 [ 595.170754] ? __pfx_call_rcu_tasks+0x10/0x10 [ 595.172046] ? __pfx_wakeme_after_rcu+0x10/0x10 [ 595.174306] ? verify_cpu+0x10/0x100 [ 595.175832] synchronize_rcu_tasks_generic+0x24/0x70 [ 595.177391] synchronize_rcu_tasks+0x19/0x20 [ 595.178748] ftrace_shutdown+0x1cc/0x410 [ 595.180589] unregister_ftrace_function+0x35/0x230 [ 595.183146] ? __sanitizer_cov_trace_switch+0x57/0xa0 [ 595.185014] perf_ftrace_event_register+0x95/0xf0 [ 595.187106] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.188492] perf_trace_destroy+0x3a/0xa0 [ 595.190650] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.192050] tp_perf_event_destroy+0x1e/0x30 [ 595.193636] _free_event+0x101/0x810 [ 595.195375] put_event+0x3c/0x50 [ 595.196797] perf_event_release_kernel+0x2de/0x360 [ 595.198772] ? perf_event_release_kernel+0x9/0x360 [ 595.200619] ? __pfx_perf_release+0x10/0x10 [ 595.202793] perf_release+0x22/0x30 [ 595.204118] __fput+0x11f/0x450 [ 595.206330] ____fput+0x1e/0x30 [ 595.207619] task_work_run+0xb6/0x120 [ 595.209570] do_exit+0x547/0x12b0 [ 595.211192] ? write_comp_data+0x2f/0x90 [ 595.213301] do_group_exit+0x5e/0xf0 [ 595.215069] get_signal+0x1465/0x14a0 [ 595.218659] arch_do_signal_or_restart+0x33/0x280 [ 595.221777] exit_to_user_mode_prepare+0x13b/0x210 [ 595.223405] syscall_exit_to_user_mode+0x2d/0x60 [ 595.224909] do_syscall_64+0x4a/0x90 [ 595.226974] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 595.228316] RIP: 0033:0x7f7722b9159d [ 595.230569] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 595.232391] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 595.234504] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 595.235932] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 595.238043] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 595.239469] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 595.243044] </TASK> [ 595.244090] INFO: task repro:425 blocked for more than 295 seconds. [ 595.246596] Not tainted 6.3.0-rc3-kvm-e8d018dd #1 [ 595.247797] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 595.249475] task:repro state:D stack:0 pid:425 ppid:402 flags:0x00004002 [ 595.251419] Call Trace: [ 595.252336] <TASK> [ 595.254448] __schedule+0x40a/0xc30 [ 595.256931] schedule+0x5b/0xe0 [ 595.259688] schedule_preempt_disabled+0x1c/0x30 [ 595.261037] __mutex_lock+0x824/0xcb0 [ 595.263401] ? perf_trace_destroy+0x21/0xa0 [ 595.264703] ? perf_trace_destroy+0x21/0xa0 [ 595.267542] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.269904] mutex_lock_nested+0x1f/0x30 [ 595.271085] ? mutex_lock_nested+0x1f/0x30 [ 595.272349] perf_trace_destroy+0x21/0xa0 [ 595.274364] ? __pfx_tp_perf_event_destroy+0x10/0x10 [ 595.275730] tp_perf_event_destroy+0x1e/0x30 [ 595.277337] _free_event+0x101/0x810 [ 595.279086] put_event+0x3c/0x50 [ 595.280473] perf_event_release_kernel+0x2de/0x360 [ 595.282535] ? perf_event_release_kernel+0x9/0x360 [ 595.284410] ? __pfx_perf_release+0x10/0x10 [ 595.286934] perf_release+0x22/0x30 [ 595.288328] __fput+0x11f/0x450 [ 595.291181] ____fput+0x1e/0x30 [ 595.292542] task_work_run+0xb6/0x120 [ 595.295127] do_exit+0x547/0x12b0 [ 595.296739] ? write_comp_data+0x2f/0x90 [ 595.299422] do_group_exit+0x5e/0xf0 [ 595.301300] get_signal+0x1465/0x14a0 [ 595.304201] arch_do_signal_or_restart+0x33/0x280 [ 595.307819] exit_to_user_mode_prepare+0x13b/0x210 [ 595.310117] syscall_exit_to_user_mode+0x2d/0x60 [ 595.311564] do_syscall_64+0x4a/0x90 [ 595.312915] entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 595.314996] RIP: 0033:0x7f7722b9159d [ 595.316223] RSP: 002b:00007f7722a6aca8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a [ 595.318821] RAX: 0000000000000003 RBX: 0000000000000000 RCX: 00007f7722b9159d [ 595.320288] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 00000000200004c0 [ 595.322490] RBP: 00007f7722a6ae00 R08: 0000000000000000 R09: 0000000000000000 [ 595.323955] R10: 00000000ffffffff R11: 0000000000000246 R12: 00007ffdb9febe5e [ 595.326146] R13: 00007ffdb9febe5f R14: 00007ffdb9febef0 R15: 00007f7722a6b700 [ 595.329860] </TASK> [ 595.330790] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings [ 595.332380] [ 595.332380] Showing all locks held in the system: [ 595.334428] 1 lock held by rcu_tasks_kthre/11: [ 595.335544] #0: ffffffff83d63490 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 595.339209] 1 lock held by rcu_tasks_rude_/12: [ 595.340343] #0: ffffffff83d63210 (rcu_tasks_rude.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 595.344102] 1 lock held by rcu_tasks_trace/13: [ 595.345460] #0: ffffffff83d62f50 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0x420 [ 595.349059] 1 lock held by khungtaskd/29: [ 595.350802] #0: ffffffff83d63ea0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x1b/0x1e0 [ 595.354998] 1 lock held by repro/419: [ 595.356037] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.360123] 2 locks held by repro/416: [ 595.361309] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.364710] #1: ffffffff83e1cd68 (ftrace_lock){+.+.}-{3:3}, at: unregister_ftrace_function+0x2b/0x230 [ 595.368890] 1 lock held by repro/425: [ 595.370633] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.375506] 1 lock held by repro/427: [ 595.376544] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.380137] 1 lock held by repro/430: [ 595.381332] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.384754] 1 lock held by repro/429: [ 595.386509] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.390628] 1 lock held by repro/432: [ 595.391653] #0: ffffffff83e206a8 (event_mutex){+.+.}-{3:3}, at: perf_trace_destroy+0x21/0xa0 [ 595.395216] [ 595.396002] ============================================= [ 595.396002] [ 758.862658] INFO: rcu_tasks detected stalls on tasks: [ 758.863903] 00000000858563e2: .. nvcsw: 1/1 holdout: 1 idle_cpu: -1/1 [ 758.865579] task:repro state:R running task stack:0 pid:452 ppid:398 flags:0x00004004 [ 758.868098] Call Trace: [ 758.869032] <TASK> [ 758.870199] ? __wake_up_common_lock+0x5/0xd0 [ 758.871725] ? preempt_count_add+0x9/0xc0 [ 758.872868] __wake_up+0x17/0x20 [ 758.874225] io_cq_unlock_post+0x34/0xb0 [ 758.875706] ? __io_cqring_overflow_flush+0x33a/0x360 [ 758.878046] ? io_cqring_do_overflow_flush+0x37/0x90 [ 758.879380] ? io_cqring_wait+0x707/0xaf0 [ 758.880760] ? io_cqring_wait+0x9ee/0xaf0 [ 758.883425] ? __pfx_io_wake_function+0x10/0x10 [ 758.885940] ? __x64_sys_io_uring_enter+0x207/0x680 [ 758.888843] ? do_syscall_64+0x3b/0x90 [ 758.890390] ? entry_SYSCALL_64_after_hwframe+0x72/0xdc [ 758.893858] </TASK> "
I hope it's helpful.
Thanks!
---
If you don't need the following environment to reproduce the problem or if you already have one, please ignore the following information.
How to reproduce: git clone https://gitlab.com/xupengfe/repro_vm_env.git cd repro_vm_env tar -xvf repro_vm_env.tar.gz cd repro_vm_env; ./start3.sh // it needs qemu-system-x86_64 and I used v7.1.0 // start3.sh will load bzImage_2241ab53cbb5cdb08a6b2d4688feb13971058f65 v6.2-rc5 kernel // You could change the bzImage_xxx as you want You could use below command to log in, there is no password for root. ssh -p 10023 root@localhost
After login vm(virtual machine) successfully, you could transfer reproduced binary to the vm by below way, and reproduce the problem in vm: gcc -pthread -o repro repro.c scp -P 10023 repro root@localhost:/root/
Get the bzImage for target kernel: Please use target kconfig and copy it to kernel_src/.config make olddefconfig make -jx bzImage //x should equal or less than cpu num your pc has
Fill the bzImage file into above start3.sh to load the target kernel in vm.
Tips: If you already have qemu-system-x86_64, please ignore below info. If you want to install qemu v7.1.0 version: git clone https://github.com/qemu/qemu.git cd qemu git checkout -f v7.1.0 mkdir build cd build yum install -y ninja-build.x86_64 ../configure --target-list=x86_64-softmmu --enable-kvm --enable-vnc --enable-gtk --enable-sdl make make install
Thanks! BR.
| |