syzbot


possible deadlock in perf_event_open

Status: upstream: reported C repro on 2021/05/25 00:30
Reported-by: syzbot+37763c1eb5316112abc7@syzkaller.appspotmail.com
First crash: 1121d, last: 483d
Fix bisection attempts (18)
Created Duration User Patch Repo Result
2023/02/22 00:55 34m bisect fix linux-4.14.y job log (0) log
2023/01/22 23:43 25m bisect fix linux-4.14.y job log (0) log
2022/11/05 03:02 24m bisect fix linux-4.14.y job log (0) log
2022/08/30 14:00 23m bisect fix linux-4.14.y job log (0) log
2022/07/29 18:05 31m bisect fix linux-4.14.y job log (0) log
2022/06/29 17:16 21m bisect fix linux-4.14.y job log (0) log
2022/05/29 16:25 21m bisect fix linux-4.14.y job log (0) log
2022/04/29 16:00 24m bisect fix linux-4.14.y job log (0) log
2022/03/30 15:28 32m bisect fix linux-4.14.y job log (0) log
2022/02/28 14:22 22m bisect fix linux-4.14.y job log (0) log
2022/01/29 13:52 30m bisect fix linux-4.14.y job log (0) log
2021/12/30 12:30 28m bisect fix linux-4.14.y job log (0) log
2021/11/30 12:05 25m bisect fix linux-4.14.y job log (0) log
2021/10/31 11:38 25m bisect fix linux-4.14.y job log (0) log
2021/09/23 12:41 21m bisect fix linux-4.14.y job log (0) log
2021/08/24 12:07 23m bisect fix linux-4.14.y job log (0) log
2021/07/25 03:28 25m bisect fix linux-4.14.y job log (0) log
2021/06/25 00:17 21m bisect fix linux-4.14.y job log (0) log

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.14.291-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor389/7972 is trying to acquire lock:
 (&cpuctx_mutex/1){+.+.}, at: [<ffffffff81663893>] mutex_lock_double kernel/events/core.c:9868 [inline]
 (&cpuctx_mutex/1){+.+.}, at: [<ffffffff81663893>] __perf_event_ctx_lock_double kernel/events/core.c:10012 [inline]
 (&cpuctx_mutex/1){+.+.}, at: [<ffffffff81663893>] SYSC_perf_event_open kernel/events/core.c:10277 [inline]
 (&cpuctx_mutex/1){+.+.}, at: [<ffffffff81663893>] SyS_perf_event_open+0xd13/0x2530 kernel/events/core.c:10032

but task is already holding lock:
 (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] mutex_lock_double kernel/events/core.c:9867 [inline]
 (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] __perf_event_ctx_lock_double kernel/events/core.c:10012 [inline]
 (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] SYSC_perf_event_open kernel/events/core.c:10277 [inline]
 (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] SyS_perf_event_open+0xd06/0x2530 kernel/events/core.c:10032

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #5 (&cpuctx_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       perf_event_init_cpu+0xb7/0x170 kernel/events/core.c:11286
       perf_event_init+0x2cc/0x308 kernel/events/core.c:11333
       start_kernel+0x45d/0x763 init/main.c:624
       secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #4 (pmus_lock){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       perf_event_init_cpu+0x2c/0x170 kernel/events/core.c:11280
       cpuhp_invoke_callback+0x1e6/0x1a80 kernel/cpu.c:186
       cpuhp_up_callbacks kernel/cpu.c:574 [inline]
       _cpu_up+0x21e/0x520 kernel/cpu.c:1193
       do_cpu_up+0x9a/0x160 kernel/cpu.c:1229
       smp_init+0x197/0x1ac kernel/smp.c:578
       kernel_init_freeable+0x406/0x626 init/main.c:1074
       kernel_init+0xd/0x167 init/main.c:1006
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

-> #3 (cpu_hotplug_lock.rw_sem){++++}:
       percpu_down_read_preempt_disable include/linux/percpu-rwsem.h:36 [inline]
       percpu_down_read include/linux/percpu-rwsem.h:59 [inline]
       cpus_read_lock+0x39/0xc0 kernel/cpu.c:297
       static_key_slow_inc+0xe/0x20 kernel/jump_label.c:123
       tracepoint_add_func+0x747/0xa40 kernel/tracepoint.c:269
       tracepoint_probe_register_prio kernel/tracepoint.c:331 [inline]
       tracepoint_probe_register+0x8c/0xc0 kernel/tracepoint.c:352
       trace_event_reg+0x272/0x330 kernel/trace/trace_events.c:305
       perf_trace_event_reg kernel/trace/trace_event_perf.c:122 [inline]
       perf_trace_event_init kernel/trace/trace_event_perf.c:197 [inline]
       perf_trace_init+0x424/0xa30 kernel/trace/trace_event_perf.c:221
       perf_tp_event_init+0x79/0xf0 kernel/events/core.c:8140
       perf_try_init_event+0x15b/0x1f0 kernel/events/core.c:9374
       perf_init_event kernel/events/core.c:9412 [inline]
       perf_event_alloc.part.0+0xe2d/0x2640 kernel/events/core.c:9672
       perf_event_alloc kernel/events/core.c:10042 [inline]
       SYSC_perf_event_open kernel/events/core.c:10146 [inline]
       SyS_perf_event_open+0x683/0x2530 kernel/events/core.c:10032
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

-> #2 (tracepoints_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       tracepoint_probe_register_prio kernel/tracepoint.c:327 [inline]
       tracepoint_probe_register+0x68/0xc0 kernel/tracepoint.c:352
       trace_event_reg+0x272/0x330 kernel/trace/trace_events.c:305
       perf_trace_event_reg kernel/trace/trace_event_perf.c:122 [inline]
       perf_trace_event_init kernel/trace/trace_event_perf.c:197 [inline]
       perf_trace_init+0x424/0xa30 kernel/trace/trace_event_perf.c:221
       perf_tp_event_init+0x79/0xf0 kernel/events/core.c:8140
       perf_try_init_event+0x15b/0x1f0 kernel/events/core.c:9374
       perf_init_event kernel/events/core.c:9412 [inline]
       perf_event_alloc.part.0+0xe2d/0x2640 kernel/events/core.c:9672
       perf_event_alloc kernel/events/core.c:10042 [inline]
       SYSC_perf_event_open kernel/events/core.c:10146 [inline]
       SyS_perf_event_open+0x683/0x2530 kernel/events/core.c:10032
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

-> #1 (event_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       perf_trace_init+0x4f/0xa30 kernel/trace/trace_event_perf.c:216
       perf_tp_event_init+0x79/0xf0 kernel/events/core.c:8140
       perf_try_init_event+0xdf/0x1f0 kernel/events/core.c:9374
       perf_init_event kernel/events/core.c:9412 [inline]
       perf_event_alloc.part.0+0xe2d/0x2640 kernel/events/core.c:9672
       perf_event_alloc kernel/events/core.c:10042 [inline]
       SYSC_perf_event_open kernel/events/core.c:10146 [inline]
       SyS_perf_event_open+0x683/0x2530 kernel/events/core.c:10032
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

-> #0 (&cpuctx_mutex/1){+.+.}:
       lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       mutex_lock_double kernel/events/core.c:9868 [inline]
       __perf_event_ctx_lock_double kernel/events/core.c:10012 [inline]
       SYSC_perf_event_open kernel/events/core.c:10277 [inline]
       SyS_perf_event_open+0xd13/0x2530 kernel/events/core.c:10032
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

other info that might help us debug this:

Chain exists of:
  &cpuctx_mutex/1 --> pmus_lock --> &cpuctx_mutex

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&cpuctx_mutex);
                               lock(pmus_lock);
                               lock(&cpuctx_mutex);
  lock(&cpuctx_mutex/1);

 *** DEADLOCK ***

1 lock held by syz-executor389/7972:
 #0:  (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] mutex_lock_double kernel/events/core.c:9867 [inline]
 #0:  (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] __perf_event_ctx_lock_double kernel/events/core.c:10012 [inline]
 #0:  (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] SYSC_perf_event_open kernel/events/core.c:10277 [inline]
 #0:  (&cpuctx_mutex){+.+.}, at: [<ffffffff81663886>] SyS_perf_event_open+0xd06/0x2530 kernel/events/core.c:10032

stack backtrace:
CPU: 0 PID: 7972 Comm: syz-executor389 Not tainted 4.14.291-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x1b2/0x281 lib/dump_stack.c:58
 print_circular_bug.constprop.0.cold+0x2d7/0x41e kernel/locking/lockdep.c:1258
 check_prev_add kernel/locking/lockdep.c:1905 [inline]
 check_prevs_add kernel/locking/lockdep.c:2022 [inline]
 validate_chain kernel/locking/lockdep.c:2464 [inline]
 __lock_acquire+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 __mutex_lock_common kernel/locking/mutex.c:756 [inline]
 __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
 mutex_lock_double kernel/events/core.c:9868 [inline]
 __perf_event_ctx_lock_double kernel/events/core.c:10012 [inline]
 SYSC_perf_event_open kernel/events/core.c:10277 [inline]
 SyS_perf_event_open+0xd13/0x2530 kernel/events/core.c:10032
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hw

Crashes (6):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2022/09/02 09:18 linux-4.14.y e548869f356f a805568e .config console log report syz C [disk image] [vmlinux] ci2-linux-4-14 possible deadlock in perf_event_open
2021/07/25 10:03 linux-4.14.y 964f3712e6a7 4d1b57d4 .config console log report syz ci2-linux-4-14 possible deadlock in perf_event_open
2021/05/25 00:47 linux-4.14.y 96afcb20f36f 3c7fef33 .config console log report syz ci2-linux-4-14 possible deadlock in perf_event_open
2022/10/05 05:50 linux-4.14.y 9d5c0b3a8e1a 267e3bb1 .config console log report info [disk image] [vmlinux] ci2-linux-4-14 possible deadlock in perf_event_open
2022/09/02 04:31 linux-4.14.y e548869f356f a805568e .config console log report info [disk image] [vmlinux] ci2-linux-4-14 possible deadlock in perf_event_open
2021/05/25 00:29 linux-4.14.y 96afcb20f36f 3c7fef33 .config console log report info ci2-linux-4-14 possible deadlock in perf_event_open
* Struck through repros no longer work on HEAD.