syzbot


possible deadlock in perf_trace_init

Status: closed as invalid on 2017/10/27 06:57
First crash: 2414d, last: 2406d
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-4.14 possible deadlock in perf_trace_init C inconclusive 27 1420d 1822d 0/1 upstream: reported C repro on 2019/04/24 18:48
upstream possible deadlock in perf_trace_init (2) trace 2 2324d 2329d 0/26 closed as dup on 2018/02/12 15:04

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.13.0+ #86 Not tainted
------------------------------------------------------
syz-executor0/2996 is trying to acquire lock:
 (event_mutex){+.+.}, at: [<ffffffff81757f68>] perf_trace_init+0x58/0xab0 kernel/trace/trace_event_perf.c:216

but task is already holding lock:
 (&ctx->mutex){+.+.}, at: [<ffffffff8183729b>] perf_event_init_context kernel/events/core.c:10965 [inline]
 (&ctx->mutex){+.+.}, at: [<ffffffff8183729b>] perf_event_init_task+0x25b/0x890 kernel/events/core.c:11040

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #8 (&ctx->mutex){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893
       mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
       perf_event_ctx_lock_nested+0x1dc/0x3c0 kernel/events/core.c:1210
       perf_event_ctx_lock kernel/events/core.c:1223 [inline]
       perf_read+0xb9/0x970 kernel/events/core.c:4584
       do_loop_readv_writev fs/read_write.c:693 [inline]
       do_iter_read+0x3db/0x5b0 fs/read_write.c:917
       vfs_readv+0x121/0x1c0 fs/read_write.c:979
       kernel_readv fs/splice.c:361 [inline]
       default_file_splice_read+0x508/0xae0 fs/splice.c:416
       do_splice_to+0x110/0x170 fs/splice.c:880
       do_splice fs/splice.c:1173 [inline]
       SYSC_splice fs/splice.c:1402 [inline]
       SyS_splice+0x11a8/0x1630 fs/splice.c:1382
       entry_SYSCALL_64_fastpath+0x1f/0xbe

-> #7 (&pipe->mutex/1){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893
       mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
       pipe_lock_nested fs/pipe.c:66 [inline]
       pipe_lock+0x56/0x70 fs/pipe.c:74
       iter_file_splice_write+0x264/0xf50 fs/splice.c:699
       do_splice_from fs/splice.c:851 [inline]
       do_splice fs/splice.c:1147 [inline]
       SYSC_splice fs/splice.c:1402 [inline]
       SyS_splice+0x7d5/0x1630 fs/splice.c:1382
       entry_SYSCALL_64_fastpath+0x1f/0xbe

-> #6 (sb_writers){.+.+}:
       percpu_down_read_preempt_disable include/linux/percpu-rwsem.h:35 [inline]
       percpu_down_read include/linux/percpu-rwsem.h:58 [inline]
       __sb_start_write+0x18f/0x290 fs/super.c:1340
       sb_start_write include/linux/fs.h:1541 [inline]
       mnt_want_write+0x3f/0xb0 fs/namespace.c:386
       filename_create+0x12b/0x520 fs/namei.c:3628
       kern_path_create+0x33/0x40 fs/namei.c:3674
       handle_create+0xc0/0x760 drivers/base/devtmpfs.c:202

-> #5 ((complete)&req.done){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       complete_acquire include/linux/completion.h:39 [inline]
       __wait_for_common kernel/sched/completion.c:108 [inline]
       wait_for_common kernel/sched/completion.c:122 [inline]
       wait_for_completion+0xc8/0x770 kernel/sched/completion.c:143
       devtmpfs_create_node+0x32b/0x4a0 drivers/base/devtmpfs.c:114
       device_add+0x120f/0x1640 drivers/base/core.c:1824
       device_create_groups_vargs+0x1f3/0x250 drivers/base/core.c:2430
       device_create_vargs drivers/base/core.c:2470 [inline]
       device_create+0xda/0x110 drivers/base/core.c:2506
       msr_device_create+0x26/0x40 arch/x86/kernel/msr.c:188
       cpuhp_invoke_callback+0x256/0x14d0 kernel/cpu.c:145
       cpuhp_thread_fun+0x265/0x520 kernel/cpu.c:434
       smpboot_thread_fn+0x489/0x850 kernel/smpboot.c:164
       kthread+0x39c/0x470 kernel/kthread.c:231
       ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431

-> #4 (cpuhp_state){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       cpuhp_invoke_ap_callback kernel/cpu.c:467 [inline]
       cpuhp_issue_call+0x1a2/0x3e0 kernel/cpu.c:1308
       __cpuhp_setup_state_cpuslocked+0x2d6/0x5f0 kernel/cpu.c:1455
       __cpuhp_setup_state+0xb0/0x140 kernel/cpu.c:1484
       cpuhp_setup_state include/linux/cpuhotplug.h:177 [inline]
       page_writeback_init+0x4d/0x71 mm/page-writeback.c:2082
       pagecache_init+0x48/0x4f mm/filemap.c:871
       start_kernel+0x6c1/0x754 init/main.c:690
       x86_64_start_reservations+0x2a/0x2c arch/x86/kernel/head64.c:377
       x86_64_start_kernel+0x77/0x7a arch/x86/kernel/head64.c:358
       verify_cpu+0x0/0xfb

-> #3 (cpuhp_state_mutex){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893
       mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
       __cpuhp_setup_state_cpuslocked+0x5b/0x5f0 kernel/cpu.c:1430
       __cpuhp_setup_state+0xb0/0x140 kernel/cpu.c:1484
       cpuhp_setup_state_nocalls include/linux/cpuhotplug.h:205 [inline]
       kvm_guest_init+0x1f3/0x20f arch/x86/kernel/kvm.c:488
       setup_arch+0x1879/0x1a93 arch/x86/kernel/setup.c:1297
       start_kernel+0xa5/0x754 init/main.c:530
       x86_64_start_reservations+0x2a/0x2c arch/x86/kernel/head64.c:377
       x86_64_start_kernel+0x77/0x7a arch/x86/kernel/head64.c:358
       verify_cpu+0x0/0xfb

-> #2 (cpu_hotplug_lock.rw_sem){++++}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       percpu_down_read_preempt_disable include/linux/percpu-rwsem.h:35 [inline]
       percpu_down_read include/linux/percpu-rwsem.h:58 [inline]
       cpus_read_lock+0x42/0x90 kernel/cpu.c:218
       static_key_slow_inc+0x9d/0x3c0 kernel/jump_label.c:123
       tracepoint_add_func kernel/tracepoint.c:223 [inline]
       tracepoint_probe_register_prio+0x80d/0x9a0 kernel/tracepoint.c:283
       tracepoint_probe_register+0x2a/0x40 kernel/tracepoint.c:304
       trace_event_reg+0x167/0x320 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+0x4f9/0xab0 kernel/trace/trace_event_perf.c:221
       perf_tp_event_init+0x7d/0xf0 kernel/events/core.c:8037
       perf_try_init_event+0xc9/0x1f0 kernel/events/core.c:9261
       perf_init_event kernel/events/core.c:9299 [inline]
       perf_event_alloc+0x1c5b/0x2a00 kernel/events/core.c:9558
       SYSC_perf_event_open+0x84e/0x2e00 kernel/events/core.c:10013
       SyS_perf_event_open+0x39/0x50 kernel/events/core.c:9899
       entry_SYSCALL_64_fastpath+0x1f/0xbe

-> #1 (tracepoints_mutex){+.+.}:
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893
       mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
       tracepoint_probe_register_prio+0xa0/0x9a0 kernel/tracepoint.c:279
       tracepoint_probe_register+0x2a/0x40 kernel/tracepoint.c:304
       trace_event_reg+0x167/0x320 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+0x4f9/0xab0 kernel/trace/trace_event_perf.c:221
       perf_tp_event_init+0x7d/0xf0 kernel/events/core.c:8037
       perf_try_init_event+0xc9/0x1f0 kernel/events/core.c:9261
       perf_init_event kernel/events/core.c:9299 [inline]
       perf_event_alloc+0x1c5b/0x2a00 kernel/events/core.c:9558
       SYSC_perf_event_open+0x84e/0x2e00 kernel/events/core.c:10013
       SyS_perf_event_open+0x39/0x50 kernel/events/core.c:9899
       entry_SYSCALL_64_fastpath+0x1f/0xbe

-> #0 (event_mutex){+.+.}:
       check_prev_add+0x865/0x1520 kernel/locking/lockdep.c:1894
       check_prevs_add kernel/locking/lockdep.c:2020 [inline]
       validate_chain kernel/locking/lockdep.c:2469 [inline]
       __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
       lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893
       mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
       perf_trace_init+0x58/0xab0 kernel/trace/trace_event_perf.c:216
       perf_tp_event_init+0x7d/0xf0 kernel/events/core.c:8037
       perf_try_init_event+0xc9/0x1f0 kernel/events/core.c:9261
       perf_init_event kernel/events/core.c:9283 [inline]
       perf_event_alloc+0x10fa/0x2a00 kernel/events/core.c:9558
       inherit_event.isra.93+0x15b/0x910 kernel/events/core.c:10772
       inherit_group kernel/events/core.c:10863 [inline]
       inherit_task_group.isra.95.part.96+0x73/0x240 kernel/events/core.c:10921
       inherit_task_group kernel/events/core.c:10901 [inline]
       perf_event_init_context kernel/events/core.c:10972 [inline]
       perf_event_init_task+0x348/0x890 kernel/events/core.c:11040
       copy_process.part.36+0x173b/0x4af0 kernel/fork.c:1709
       copy_process kernel/fork.c:1548 [inline]
       _do_fork+0x1ef/0xfe0 kernel/fork.c:2027
       SYSC_clone kernel/fork.c:2137 [inline]
       SyS_clone+0x37/0x50 kernel/fork.c:2131
       do_syscall_64+0x26c/0x8c0 arch/x86/entry/common.c:287
       return_from_SYSCALL_64+0x0/0x7a

other info that might help us debug this:

Chain exists of:
  event_mutex --> &pipe->mutex/1 --> &ctx->mutex

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&ctx->mutex);
                               lock(&pipe->mutex/1);
                               lock(&ctx->mutex);
  lock(event_mutex);

 *** DEADLOCK ***

2 locks held by syz-executor0/2996:
 #0:  (&ctx->mutex){+.+.}, at: [<ffffffff8183729b>] perf_event_init_context kernel/events/core.c:10965 [inline]
 #0:  (&ctx->mutex){+.+.}, at: [<ffffffff8183729b>] perf_event_init_task+0x25b/0x890 kernel/events/core.c:11040
 #1:  (&pmus_srcu){....}, at: [<ffffffff8181c08a>] perf_event_alloc+0x104a/0x2a00 kernel/events/core.c:9554

stack backtrace:
CPU: 1 PID: 2996 Comm: syz-executor0 Not tainted 4.13.0+ #86
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x194/0x257 lib/dump_stack.c:52
 print_circular_bug+0x503/0x710 kernel/locking/lockdep.c:1259
 check_prev_add+0x865/0x1520 kernel/locking/lockdep.c:1894
 check_prevs_add kernel/locking/lockdep.c:2020 [inline]
 validate_chain kernel/locking/lockdep.c:2469 [inline]
 __lock_acquire+0x328f/0x4620 kernel/locking/lockdep.c:3498
 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002
 __mutex_lock_common kernel/locking/mutex.c:756 [inline]
 __mutex_lock+0x16f/0x1870 kernel/locking/mutex.c:893

Crashes (7):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2017/09/16 00:34 upstream b38923a068c1 96b8e399 .config console log report syz ci-upstream-kasan-gce
2017/09/15 23:55 linux-next 1f183459b514 da1873aa .config console log report syz skylake-linux-next-kasan-qemu
2017/09/17 20:53 linux-next 1f183459b514 da1873aa .config console log report skylake-linux-next-kasan-qemu
2017/09/15 22:16 linux-next 1f183459b514 da1873aa .config console log report skylake-linux-next-kasan-qemu
2017/09/13 23:56 linux-next 6f20b7a58cb9 96b8e399 .config console log report skylake-linux-next-kasan-qemu
2017/09/13 13:07 linux-next 6f20b7a58cb9 96b8e399 .config console log report skylake-linux-next-kasan-qemu
2017/09/10 11:22 linux-next 58bcd35f859b d18bfda0 .config console log report skylake-linux-next-kasan-qemu
* Struck through repros no longer work on HEAD.