deadlock in perf_ioctl

DISCUSSION Dmitry Vyukov 3 participants 3 messages Nov 30, 2015 – Dec 4, 2015

Subsystems (2)

Stable branch perf events

lore

Share & tools

lore

Dmitry Vyukov

author

2015-11-30 09:21 UTC #0 lore raw

Hello,

The following program deadlocks kernel:

// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <syscall.h>
#include <string.h>
#include <stdint.h>
#include <pthread.h>

void *thr0(void *arg)

{
        syscall(SYS_ioctl, arg, 0x2403ul, 0x5ul, 0, 0, 0);
        return 0;
}

void *thr1(void *arg)

{
        *(uint64_t*)0x20002000 = 0x8;
        syscall(SYS_ioctl, arg, 0x40082404ul, 0x20002000ul, 0, 0, 0);
        return 0;
}

int main()

{
        long r0 = syscall(SYS_mmap, 0x20000000ul, 0x10000ul, 0x3ul,
0x32ul, 0xfffffffffffffffful, 0x0ul);
        *(uint32_t*)0x20000fcd = 0x1;
        *(uint32_t*)0x20000fd1 = 0x78;
        *(uint64_t*)0x20000fd5 = 0x0;
        *(uint64_t*)0x20000fdd = 0x7a;
        *(uint64_t*)0x20000fe5 = 0x1a;
        *(uint64_t*)0x20000fed = 0x4;
        *(uint8_t*)0x20000ff5 = 0x1;
        *(uint8_t*)0x20000ff6 = 0x2;
        *(uint8_t*)0x20000ff7 = 0xb4;
        *(uint8_t*)0x20000ff8 = 0x4;
        *(uint32_t*)0x20000ff9 = 0x0;
        *(uint32_t*)0x20000ffd = 0x2;
        *(uint32_t*)0x20001001 = 0x3;
        *(uint64_t*)0x20001005 = 0x6;
        *(uint64_t*)0x2000100d = 0xd4d3;
        *(uint64_t*)0x20001015 = 0x53;
        *(uint64_t*)0x2000101d = 0x8;
        *(uint64_t*)0x20001025 = 0x6;
        *(uint32_t*)0x2000102d = 0x7;
        *(uint32_t*)0x20001031 = 0x0;
        *(uint64_t*)0x20001035 = 0x7;
        *(uint32_t*)0x2000103d = 0x0;
        *(uint32_t*)0x20001041 = 0x0;
        long r25 = syscall(SYS_perf_event_open, 0x20000fcdul, 0x0ul,
0x3ul, 0xfffffffffffffffful, 0x1ul, 0);
        pthread_t th[4];
        pthread_create(&th[0], 0, thr0, (void*)r25);
        pthread_create(&th[1], 0, thr1, (void*)r25);
        pthread_create(&th[2], 0, thr0, (void*)r25);
        pthread_create(&th[3], 0, thr1, (void*)r25);
        return 0;
}

It causes possible deadlock message followed by full hang up:

=============================================
[ INFO: possible recursive locking detected ] 4.4.0-rc1+ #129 Not tainted
---------------------------------------------
a.out/6283 is trying to acquire lock:
(&ctx->lock){-.....}, at: [<ffffffff815072ce>]
__perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156

but task is already holding lock:
(&ctx->lock){-.....}, at: [< inline >] perf_event_period
kernel/events/core.c:4212
(&ctx->lock){-.....}, at: [< inline >] _perf_ioctl
kernel/events/core.c:4266
(&ctx->lock){-.....}, at: [<ffffffff8152331c>] perf_ioctl+0x7bc/0xcc0
kernel/events/core.c:4320

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0
       ----

lock(&ctx->lock);
lock(&ctx->lock);

*** DEADLOCK ***

May be due to missing lock nesting notation

2 locks held by a.out/6283:
#0: (&ctx->mutex){+.+...}, at: [<ffffffff8150b2e8>]

perf_event_ctx_lock_nested+0x148/0x2e0 kernel/events/core.c:961
 #1:  (&ctx->lock){-.....}, at: [<     inline     >] perf_event_period

kernel/events/core.c:4212
#1: (&ctx->lock){-.....}, at: [< inline >] _perf_ioctl
kernel/events/core.c:4266
#1: (&ctx->lock){-.....}, at: [<ffffffff8152331c>]

perf_ioctl+0x7bc/0xcc0 kernel/events/core.c:4320

stack backtrace:
CPU: 2 PID: 6283 Comm: a.out Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 00000000ffffffff ffff88003a1f7a20 ffffffff82745526 0000000000000000
 ffffffff87c63e30 ffffffff87c63e30 ffff88003a1f7bb0 ffffffff81344e93
 0000048f00000002 ffffffff8758a920 ffff88003906b588 ffffffff00006700
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff82745526>] dump_stack+0x68/0x92 lib/dump_stack.c:50
 [<     inline     >] print_deadlock_bug kernel/locking/lockdep.c:1752
 [<     inline     >] check_deadlock kernel/locking/lockdep.c:1796
 [<     inline     >] validate_chain kernel/locking/lockdep.c:2128
 [<ffffffff81344e93>] __lock_acquire+0x1c73/0x3f00 kernel/locking/lockdep.c:3206
 [<ffffffff8134949d>] lock_acquire+0x16d/0x2f0 kernel/locking/lockdep.c:3585
 [<     inline     >] __raw_spin_lock include/linux/spinlock_api_smp.h:144
 [<ffffffff85987aa1>] _raw_spin_lock+0x31/0x40 kernel/locking/spinlock.c:151
 [<ffffffff815072ce>] __perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156
 [<     inline     >] perf_event_period kernel/events/core.c:4219
 [<     inline     >] _perf_ioctl kernel/events/core.c:4266
 [<ffffffff815234a4>] perf_ioctl+0x944/0xcc0 kernel/events/core.c:4320
 [<     inline     >] vfs_ioctl fs/ioctl.c:43
 [<ffffffff816a5be1>] do_vfs_ioctl+0x681/0xe40 fs/ioctl.c:607
 [<     inline     >] SYSC_ioctl fs/ioctl.c:622
 [<ffffffff816a642f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:613
 [<ffffffff85988836>] entry_SYSCALL_64_fastpath+0x16/0x7a

arch/x86/entry/entry_64.S:185

BUG: spinlock lockup suspected on CPU#2, a.out/6283
 lock: 0xffff880038de9528, .magic: dead4ead, .owner: a.out/6283, .owner_cpu: 2
CPU: 2 PID: 6283 Comm: a.out Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 00000000ffffffff ffff88003a1f7bb8 ffffffff82745526 ffff880038de9528
 ffff88003906b380 0000000000000002 ffff88003a1f7be8 ffffffff81352f5d
 ffff880038de9528 ffff880038de9530 000000009a9d2d40 ffff880038de9538
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff82745526>] dump_stack+0x68/0x92 lib/dump_stack.c:50
 [<ffffffff81352f5d>] spin_dump+0x16d/0x270
kernel/locking/spinlock_debug.c:67 (discriminator 8)
 [<     inline     >] __spin_lock_debug kernel/locking/spinlock_debug.c:117
 [<ffffffff8135328e>] do_raw_spin_lock+0x19e/0x320
kernel/locking/spinlock_debug.c:137
 [<     inline     >] __raw_spin_lock include/linux/spinlock_api_smp.h:145
 [<ffffffff85987aa9>] _raw_spin_lock+0x39/0x40 kernel/locking/spinlock.c:151
 [<ffffffff815072ce>] ? __perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156
 [<ffffffff815072ce>] __perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156
 [<     inline     >] perf_event_period kernel/events/core.c:4219
 [<     inline     >] _perf_ioctl kernel/events/core.c:4266
 [<ffffffff815234a4>] perf_ioctl+0x944/0xcc0 kernel/events/core.c:4320
 [<ffffffff81522b60>] ? SYSC_perf_event_open+0x2060/0x2060

kernel/events/core.c:8192
[<ffffffff81343220>] ? debug_check_no_locks_freed+0x310/0x310
kernel/locking/lockdep.c:4123
[< inline >] ? arch_local_irq_restore
./arch/x86/include/asm/paravirt.h:806
[<ffffffff81349f9d>] ? lock_release+0x7cd/0xbb0 kernel/locking/lockdep.c:3607 [<ffffffff8133a630>] ? check_chain_key+0x2b0/0x4b0
kernel/locking/lockdep.c:2192 (discriminator 9)
[<ffffffff81522b60>] ? SYSC_perf_event_open+0x2060/0x2060
kernel/events/core.c:8192

 [<     inline     >] vfs_ioctl fs/ioctl.c:43
 [<ffffffff816a5be1>] do_vfs_ioctl+0x681/0xe40 fs/ioctl.c:607
 [<ffffffff816a5560>] ? ioctl_preallocate+0x1d0/0x1d0 fs/ioctl.c:442
 [<     inline     >] ? rcu_lock_release include/linux/rcupdate.h:482
 [<     inline     >] ? rcu_read_unlock include/linux/rcupdate.h:917
 [<ffffffff816c4d92>] ? __fget+0x222/0x3a0 fs/file.c:711
 [<ffffffff816c4bb7>] ? __fget+0x47/0x3a0 fs/file.c:695
 [<     inline     >] ? __up_read ./arch/x86/include/asm/rwsem.h:156
 [<ffffffff813372e5>] ? up_read+0x35/0x40 kernel/locking/rwsem.c:81
 [<ffffffff82537ec9>] ? security_file_ioctl+0x89/0xb0
security/security.c:752 (discriminator 6)
BUG: spinlock lockup suspected on CPU#0, a.out/6281
 lock: 0xffff880038de9528, .magic: dead4ead, .owner: a.out/6283, .owner_cpu: 2
 [<     inline     >] SYSC_ioctl fs/ioctl.c:622
 [<ffffffff816a642f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:613
 [<ffffffff85988836>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185
CPU: 0 PID: 6281 Comm: a.out Not tainted 4.4.0-rc1+ #129
Sending NMI to all CPUs:
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
NMI backtrace for cpu 0
CPU: 0 PID: 6281 Comm: a.out Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003906c440 ti: ffff8800392a0000 task.ti: ffff8800392a0000
RIP: 0010:[<ffffffff82aedbfb>]  [<ffffffff82aedbfb>] io_serial_in+0x6b/0x90
RSP: 0018:ffff8800392a7650  EFLAGS: 00000006
RAX: dffffc0000000000 RBX: 00000000000003f9 RCX: 0000000000000000
RDX: 00000000000003f9 RSI: 0000000000000001 RDI: ffffffff8821d378
RBP: ffff8800392a7660 R08: 0000000000000001 R09: 0000000000000000
R10: fffffbfff10297a5 R11: 1ffffffff102979d R12: ffffffff8821d340
R13: 0000000000000001 R14: ffffffff82ae84f0 R15: ffffffff86beb880
FS:  0000000000f11880(0063) GS:ffff88003ec00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007f371237ed90 CR3: 0000000039046000 CR4: 00000000000006f0
Stack:
 ffffffff8821d340 ffffffff8821d560 ffff8800392a7788 ffffffff82af9985
 0000000000000046 ffff8800392a7758 ffffffff8821d388 ffffffff8814bce0
 1ffff10007254ed4 ffffed0000000048 0000000041b58ab3 ffffffff8673a970
Call Trace:
 [<     inline     >] serial_port_in include/linux/serial_core.h:254
 [<ffffffff82af9985>] serial8250_console_write+0x1c5/0x800

drivers/tty/serial/8250/8250_port.c:2862
[<ffffffff82af97c0>] ? exar_handle_irq+0x1a0/0x1a0
include/linux/serial_core.h:254
[<ffffffff8276f5a7>] ? sprintf+0xa7/0xd0 lib/vsprintf.c:2109 [<ffffffff8276f500>] ? scnprintf+0x100/0x100 lib/vsprintf.c:2015
[< inline >] ? arch_local_irq_restore
./arch/x86/include/asm/paravirt.h:806
[<ffffffff81349f9d>] ? lock_release+0x7cd/0xbb0 kernel/locking/lockdep.c:3607
[< inline >] ? arch_local_irq_restore
./arch/x86/include/asm/paravirt.h:806
[<ffffffff81349f9d>] ? lock_release+0x7cd/0xbb0 kernel/locking/lockdep.c:3607 [<ffffffff82ae84f0>] ? univ8250_console_setup+0x100/0x100
drivers/tty/serial/8250/8250_core.c:610
[<ffffffff82ae8554>] univ8250_console_write+0x64/0x80
drivers/tty/serial/8250/8250_core.c:594
[<ffffffff81370751>] call_console_drivers.constprop.26+0x231/0x280
kernel/printk/printk.c:1459

 [<ffffffff81372362>] console_unlock+0x502/0x9a0 kernel/printk/printk.c:2311
 [<ffffffff81372d33>] vprintk_emit+0x533/0x830 kernel/printk/printk.c:1824
 [<ffffffff81373308>] vprintk_default+0x28/0x30 kernel/printk/printk.c:1864
 [<ffffffff81534308>] printk+0xb2/0xd2 kernel/printk/printk.c:1914
 [<ffffffff81534256>] ? power_down+0x11b/0x11b kernel/power/hibernate.c:642
 [<ffffffff8162a836>] ? memcpy+0x36/0x40 mm/kasan/kasan.c:299
 [<ffffffff81375d9a>] dump_stack_print_info+0x9a/0x100
kernel/printk/printk.c:3114
 [<     inline     >] __dump_stack lib/dump_stack.c:14
 [<ffffffff8274551d>] dump_stack+0x5f/0x92 lib/dump_stack.c:50
 [<ffffffff81352f5d>] spin_dump+0x16d/0x270
kernel/locking/spinlock_debug.c:67 (discriminator 8)
 [<     inline     >] __spin_lock_debug kernel/locking/spinlock_debug.c:117
 [<ffffffff8135328e>] do_raw_spin_lock+0x19e/0x320
kernel/locking/spinlock_debug.c:137
 [<     inline     >] __raw_spin_lock include/linux/spinlock_api_smp.h:145
 [<ffffffff85987aa9>] _raw_spin_lock+0x39/0x40 kernel/locking/spinlock.c:151
 [<     inline     >] ? perf_ctx_lock kernel/events/core.c:351
 [<ffffffff8150f75d>] ? perf_event_context_sched_in+0xbd/0x380
kernel/events/core.c:2817
 [<     inline     >] perf_ctx_lock kernel/events/core.c:351
 [<ffffffff8150f75d>] perf_event_context_sched_in+0xbd/0x380

kernel/events/core.c:2817
[<ffffffff81519067>] __perf_event_task_sched_in+0x307/0x490
kernel/events/core.c:2857
[<ffffffff81518d60>] ? perf_sched_cb_inc+0x20/0x20 kernel/events/core.c:2607
[< inline >] ? load_sp0 ./arch/x86/include/asm/paravirt.h:25
[<ffffffff8114950d>] ? __switch_to+0x7bd/0xdf0 arch/x86/kernel/process_64.c:405
[< inline >] ? arch_local_irq_restore
./arch/x86/include/asm/paravirt.h:806
[<ffffffff81349f9d>] ? lock_release+0x7cd/0xbb0 kernel/locking/lockdep.c:3607

 [<     inline     >] perf_event_task_sched_in include/linux/perf_event.h:929
 [<ffffffff812c42cd>] finish_task_switch+0x3ad/0x5e0 kernel/sched/core.c:2552
 [<     inline     >] context_switch kernel/sched/core.c:2682
 [<ffffffff8597941b>] __schedule+0x87b/0x1a00 kernel/sched/core.c:3156
 [<ffffffff8597a630>] schedule+0x90/0x1a0 kernel/sched/core.c:3185
(discriminator 1)
 [<ffffffff859852fd>] rwsem_down_write_failed+0x3dd/0x950
kernel/locking/rwsem-xadd.c:489
 [<     inline     >] ? rwsem_can_spin_on_owner kernel/locking/rwsem-xadd.c:304
 [<     inline     >] ? rwsem_optimistic_spin kernel/locking/rwsem-xadd.c:373

[<ffffffff85984fdc>] ? rwsem_down_write_failed+0xbc/0x950
kernel/locking/rwsem-xadd.c:447
[<ffffffff85984f20>] ? rwsem_down_read_failed+0x270/0x270
include/linux/list.h:77
[<ffffffff8133a630>] ? check_chain_key+0x2b0/0x4b0
kernel/locking/lockdep.c:2192 (discriminator 9)
[< inline >] ? arch_local_irq_restore
./arch/x86/include/asm/paravirt.h:806
[<ffffffff813494f1>] ? lock_acquire+0x1c1/0x2f0 kernel/locking/lockdep.c:3588 [<ffffffff827762a3>] call_rwsem_down_write_failed+0x13/0x20
arch/x86/lib/rwsem.S:99

 [<     inline     >] ? __down_write_nested ./arch/x86/include/asm/rwsem.h:105
 [<     inline     >] ? __down_write ./arch/x86/include/asm/rwsem.h:121
 [<ffffffff85984023>] ? down_write+0x53/0x90 kernel/locking/rwsem.c:51
 [<     inline     >] ? SYSC_mprotect mm/mprotect.c:378
 [<ffffffff815dcced>] ? SyS_mprotect+0x15d/0x650 mm/mprotect.c:347
 [<     inline     >] SYSC_mprotect mm/mprotect.c:378
 [<ffffffff815dcced>] SyS_mprotect+0x15d/0x650 mm/mprotect.c:347
 [<ffffffff815dcb90>] ? mprotect_fixup+0x5b0/0x5b0 include/linux/mman.h:25
 [<ffffffff8134284d>] ? trace_hardirqs_on_caller+0x2fd/0x660

kernel/locking/lockdep.c:2613
[<ffffffff81003017>] ? trace_hardirqs_on_thunk+0x17/0x19
arch/x86/entry/thunk_64.S:39
[<ffffffff85988836>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185

Code: 24 c1 00 00 00 49 8d 7c 24 38 48 b8 00 00 00 00 00 fc ff df 48
89 fa 48 c1 ea 03 d3 e3 80 3c 02 00 75 17 41 03 5c 24 38 89 da ec <5b>
0f b6 c0 41 5c 5d c3 e8 78 d6 b3 fe eb c2 e8 31 d7 b3 fe eb
NMI backtrace for cpu 1
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003ebb2d80 ti: ffff88003ebd8000 task.ti: ffff88003ebd8000
RIP: 0010:[<ffffffff8120c596>]  [<ffffffff8120c596>] native_safe_halt+0x6/0x10
RSP: 0018:ffff88003ebdfe58  EFLAGS: 00000246
RAX: ffff88003ebb2d80 RBX: ffff88003ebe0000 RCX: 0000000000000001
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff86b64740
RBP: ffff88003ebdfe58 R08: 0000000000000000 R09: 0000000000000001
R10: ffffed000fffec0b R11: 0000000000000000 R12: ffff88003ebd8000
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffffff600400 CR3: 0000000062542000 CR4: 00000000000006e0
Stack:
 ffff88003ebdfe88 ffffffff81165ba2 ffff88003ebe0000 ffff88003ebd8000
 0000000000000000 0000000000000000 ffff88003ebdfe98 ffffffff81166d7a
 ffff88003ebdfeb0 ffffffff81329a88 dffffc0000000000 ffff88003ebdff18
Call Trace:
 [<     inline     >] arch_safe_halt ./arch/x86/include/asm/paravirt.h:111
 [<ffffffff81165ba2>] default_idle+0x22/0x1e0 arch/x86/kernel/process.c:304
 [<ffffffff81166d7a>] arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:295
 [<ffffffff81329a88>] default_idle_call+0x48/0x70 kernel/sched/idle.c:92
 [<     inline     >] cpuidle_idle_call kernel/sched/idle.c:156
 [<     inline     >] cpu_idle_loop kernel/sched/idle.c:251
 [<ffffffff81329fad>] cpu_startup_entry+0x41d/0x570 kernel/sched/idle.c:299
 [<ffffffff811e9323>] start_secondary+0x243/0x2d0 arch/x86/kernel/smpboot.c:251
Code: 00 00 00 00 00 55 48 89 e5 fa 5d c3 66 0f 1f 84 00 00 00 00 00
55 48 89 e5 fb 5d c3 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 fb f4 <5d>
c3 0f 1f 84 00 00 00 00 00 55 48 89 e5 f4 5d c3 66 0f 1f 84
NMI backtrace for cpu 2
CPU: 2 PID: 6283 Comm: a.out Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003906ad80 ti: ffff88003a1f0000 task.ti: ffff88003a1f0000
RIP: 0010:[<ffffffff811ff7a1>]  [<ffffffff811ff7a1>]
flat_send_IPI_mask+0x111/0x1e0
RSP: 0018:ffff88003a1f7b30  EFLAGS: 00000046
RAX: ffff88003906ad80 RBX: ffffffff868aece0 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffffffff5fb300
RBP: ffff88003a1f7b58 R08: 0000000000000001 R09: 0000000000000000
R10: fffffbfff0e957f2 R11: ffffed000fffec11 R12: 0000000000000c00
R13: 000000000f000000 R14: 0000000000000046 R15: 0000000000000002
FS:  00007f3712b7f700(0000) GS:ffff88006da00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000020002000 CR3: 0000000039046000 CR4: 00000000000006e0
Stack:
 ffffffff868aece0 ffffffff8723e740 0000000000000040 fffffbfff0e476f4
 ffff88006db19540 ffff88003a1f7b78 ffffffff811f5360 ffffffff85c79560
 dffffc0000000000 ffff88003a1f7bd0 ffffffff8275012d 00000000ffffffff
Call Trace:
 [<ffffffff811f5360>] nmi_raise_cpu_backtrace+0x60/0x80

arch/x86/kernel/apic/hw_nmi.c:33
[<ffffffff8275012d>] nmi_trigger_all_cpu_backtrace+0x49d/0x530
lib/nmi_backtrace.c:85
[<ffffffff811f5300>] ? irq_force_complete_move+0x70/0x70 ??:? [<ffffffff811f53bb>] arch_trigger_all_cpu_backtrace+0x1b/0x20
arch/x86/kernel/apic/hw_nmi.c:38

 [<     inline     >] trigger_all_cpu_backtrace include/linux/nmi.h:41
 [<     inline     >] __spin_lock_debug kernel/locking/spinlock_debug.c:119
 [<ffffffff81353298>] do_raw_spin_lock+0x1a8/0x320
kernel/locking/spinlock_debug.c:137
 [<     inline     >] __raw_spin_lock include/linux/spinlock_api_smp.h:145
 [<ffffffff85987aa9>] _raw_spin_lock+0x39/0x40 kernel/locking/spinlock.c:151
 [<ffffffff815072ce>] ? __perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156
 [<ffffffff815072ce>] __perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156
 [<     inline     >] perf_event_period kernel/events/core.c:4219
 [<     inline     >] _perf_ioctl kernel/events/core.c:4266
 [<ffffffff815234a4>] perf_ioctl+0x944/0xcc0 kernel/events/core.c:4320
 [<ffffffff81522b60>] ? SYSC_perf_event_open+0x2060/0x2060

 [<     inline     >] vfs_ioctl fs/ioctl.c:43
 [<ffffffff816a5be1>] do_vfs_ioctl+0x681/0xe40 fs/ioctl.c:607
 [<ffffffff816a5560>] ? ioctl_preallocate+0x1d0/0x1d0 fs/ioctl.c:442
 [<     inline     >] ? rcu_lock_release include/linux/rcupdate.h:482
 [<     inline     >] ? rcu_read_unlock include/linux/rcupdate.h:917
 [<ffffffff816c4d92>] ? __fget+0x222/0x3a0 fs/file.c:711
 [<ffffffff816c4bb7>] ? __fget+0x47/0x3a0 fs/file.c:695
 [<     inline     >] ? __up_read ./arch/x86/include/asm/rwsem.h:156
 [<ffffffff813372e5>] ? up_read+0x35/0x40 kernel/locking/rwsem.c:81
 [<ffffffff82537ec9>] ? security_file_ioctl+0x89/0xb0
security/security.c:752 (discriminator 6)
 [<     inline     >] SYSC_ioctl fs/ioctl.c:622
 [<ffffffff816a642f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:613
 [<ffffffff85988836>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185
Code: 41 c1 e5 18 44 89 2c 25 10 b3 5f ff 41 83 ff 02 75 6a 41 81 cc
00 04 00 00 e8 bc 1f 26 00 e8 b7 1f 26 00 44 89 24 25 00 b3 5f ff <41>
f7 c6 00 02 00 00 74 24 e8 a1 1f 26 00 e8 fc 33 14 00 4c 89
NMI backtrace for cpu 3
CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.4.0-rc1+ #129
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003ebe5b00 ti: ffff88003ebf0000 task.ti: ffff88003ebf0000
RIP: 0010:[<ffffffff8120c596>]  [<ffffffff8120c596>] native_safe_halt+0x6/0x10
RSP: 0018:ffff88003ebf7e58  EFLAGS: 00000246
RAX: ffff88003ebe5b00 RBX: ffff88003ebf8000 RCX: 0000000000000001
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff86b64740
RBP: ffff88003ebf7e58 R08: 0000000000000000 R09: 0000000000000001
R10: ffffed000fffec1b R11: 0000000000000000 R12: ffff88003ebf0000
R13: 0000000000000000 R14: 0000000000000003 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff88006db00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007f91314b79de CR3: 0000000006836000 CR4: 00000000000006e0
Stack:
 ffff88003ebf7e88 ffffffff81165ba2 ffff88003ebf8000 ffff88003ebf0000
 0000000000000000 0000000000000000 ffff88003ebf7e98 ffffffff81166d7a
 ffff88003ebf7eb0 ffffffff81329a88 dffffc0000000000 ffff88003ebf7f18
Call Trace:
 [<     inline     >] arch_safe_halt ./arch/x86/include/asm/paravirt.h:111
 [<ffffffff81165ba2>] default_idle+0x22/0x1e0 arch/x86/kernel/process.c:304
 [<ffffffff81166d7a>] arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:295
 [<ffffffff81329a88>] default_idle_call+0x48/0x70 kernel/sched/idle.c:92
 [<     inline     >] cpuidle_idle_call kernel/sched/idle.c:156
 [<     inline     >] cpu_idle_loop kernel/sched/idle.c:251
 [<ffffffff81329fad>] cpu_startup_entry+0x41d/0x570 kernel/sched/idle.c:299
 [<ffffffff811e9323>] start_secondary+0x243/0x2d0 arch/x86/kernel/smpboot.c:251
Code: 00 00 00 00 00 55 48 89 e5 fa 5d c3 66 0f 1f 84 00 00 00 00 00

55 48 89 e5 fb 5d c3 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 fb f4 <5d> c3 0f 1f 84 00 00 00 00 00 55 48 89 e5 f4 5d c3 66 0f 1f 84
00000000ffffffff ffff8800392a7a48 ffffffff82745526 ffff880038de9528 ffff88003906b380 0000000000000002 ffff8800392a7a78 ffffffff81352f5d ffff880038de9528 ffff880038de9530 000000009a9d2d40 ffff880038de9538

Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff82745526>] dump_stack+0x68/0x92 lib/dump_stack.c:50
 [<ffffffff81352f5d>] spin_dump+0x16d/0x270
kernel/locking/spinlock_debug.c:67 (discriminator 8)
 [<     inline     >] __spin_lock_debug kernel/locking/spinlock_debug.c:117
 [<ffffffff8135328e>] do_raw_spin_lock+0x19e/0x320
kernel/locking/spinlock_debug.c:137
 [<     inline     >] __raw_spin_lock include/linux/spinlock_api_smp.h:145
 [<ffffffff85987aa9>] _raw_spin_lock+0x39/0x40 kernel/locking/spinlock.c:151
 [<     inline     >] ? perf_ctx_lock kernel/events/core.c:351
 [<ffffffff8150f75d>] ? perf_event_context_sched_in+0xbd/0x380
kernel/events/core.c:2817
 [<     inline     >] perf_ctx_lock kernel/events/core.c:351
 [<ffffffff8150f75d>] perf_event_context_sched_in+0xbd/0x380

 [<     inline     >] perf_event_task_sched_in include/linux/perf_event.h:929
 [<ffffffff812c42cd>] finish_task_switch+0x3ad/0x5e0 kernel/sched/core.c:2552
 [<     inline     >] context_switch kernel/sched/core.c:2682
 [<ffffffff8597941b>] __schedule+0x87b/0x1a00 kernel/sched/core.c:3156
 [<ffffffff8597a630>] schedule+0x90/0x1a0 kernel/sched/core.c:3185
(discriminator 1)
 [<ffffffff859852fd>] rwsem_down_write_failed+0x3dd/0x950
kernel/locking/rwsem-xadd.c:489
 [<     inline     >] ? rwsem_can_spin_on_owner kernel/locking/rwsem-xadd.c:304
 [<     inline     >] ? rwsem_optimistic_spin kernel/locking/rwsem-xadd.c:373

 [<     inline     >] ? __down_write_nested ./arch/x86/include/asm/rwsem.h:105
 [<     inline     >] ? __down_write ./arch/x86/include/asm/rwsem.h:121
 [<ffffffff85984023>] ? down_write+0x53/0x90 kernel/locking/rwsem.c:51
 [<     inline     >] ? SYSC_mprotect mm/mprotect.c:378
 [<ffffffff815dcced>] ? SyS_mprotect+0x15d/0x650 mm/mprotect.c:347
 [<     inline     >] SYSC_mprotect mm/mprotect.c:378
 [<ffffffff815dcced>] SyS_mprotect+0x15d/0x650 mm/mprotect.c:347
 [<ffffffff815dcb90>] ? mprotect_fixup+0x5b0/0x5b0 include/linux/mman.h:25
 [<ffffffff8134284d>] ? trace_hardirqs_on_caller+0x2fd/0x660

On commit 90b55590c43258a157a2a143748455dcc50fbb53 (Nov 25).

Thank you

Peter Zijlstra

maintainer

2015-11-30 11:56 UTC #1 lore raw

Quoted 8 lines · Dmitry Vyukov

=============================================
[ INFO: possible recursive locking detected ] 4.4.0-rc1+ #129 Not tainted
---------------------------------------------
a.out/6283 is trying to acquire lock:
(&ctx->lock){-.....}, at: [<ffffffff815072ce>]
__perf_event_period+0x8e/0x4b0 kernel/events/core.c:4156

Quoted 8 lines

but task is already holding lock:
(&ctx->lock){-.....}, at: [< inline >] perf_event_period
kernel/events/core.c:4212
(&ctx->lock){-.....}, at: [< inline >] _perf_ioctl
kernel/events/core.c:4266
(&ctx->lock){-.....}, at: [<ffffffff8152331c>] perf_ioctl+0x7bc/0xcc0
kernel/events/core.c:4320

Indeed so. I suppose the below should fix this, I'll go try in a bit.

---
Subject: perf: Fix PERF_EVENT_IOC_PERIOD deadlock

Dmitry reported a fairly silly recursive lock deadlock for PERF_EVENT_IOC_PERIOD, fix this by explicitly doing the inactive part of __perf_event_period() instead of calling that function.

Reported-by Dmitry Vyukov <[email protected]>

Fixes c7999c6f3fed ("perf: Fix PERF_EVENT_IOC_PERIOD migration race")

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

---
 kernel/events/core.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

kernel/events/core.c +8 -1

index 36babfd20648..a991e12e4d0d 100644
@@ -4216,7 +4216,14 @@ static int perf_event_period(struct perf_event *event, u64 __user *arg)
 		goto retry;
 	}
 
-	__perf_event_period(&pe);
+	if (event->attr.freq) {
+		event->attr.sample_freq = value;
+	} else {
+		event->attr.sample_period = value;
+		event->hw.sample_period = value;
+	}
+
+	local64_set(&event->hw.period_left, 0);
 	raw_spin_unlock_irq(&ctx->lock);
 
 	return 0;

tip-bot for Peter Zijlstra

merge bot

2015-12-04 11:50 UTC #2 lore raw

[tip:perf/core] perf: Fix PERF_EVENT_IOC_PERIOD deadlock

perf: Fix PERF_EVENT_IOC_PERIOD deadlock

Commit-ID:  642c2d671ceff40e9453203ea0c66e991e11e249
Gitweb:     http://git.kernel.org/tip/642c2d671ceff40e9453203ea0c66e991e11e249
Author:     Peter Zijlstra <[email protected]>
AuthorDate: Mon, 30 Nov 2015 12:56:15 +0100
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 4 Dec 2015 10:08:03 +0100

perf: Fix PERF_EVENT_IOC_PERIOD deadlock

Dmitry reported a fairly silly recursive lock deadlock for PERF_EVENT_IOC_PERIOD, fix this by explicitly doing the inactive part of __perf_event_period() instead of calling that function.

Reported-by Dmitry Vyukov <[email protected]>

Signed-off-by Peter Zijlstra (Intel) <[email protected]>

Cc <[email protected]>

Cc Alexander Potapenko <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc Eric Dumazet <[email protected]>

Cc Jiri Olsa <[email protected]>

Cc Kostya Serebryany <[email protected]>

Cc Linus Torvalds <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Sasha Levin <[email protected]>

Cc Stephane Eranian <[email protected]>

Cc Thomas Gleixner <[email protected]>

Cc Vince Weaver <[email protected]>

Fixes c7999c6f3fed ("perf: Fix PERF_EVENT_IOC_PERIOD migration race")

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Ingo Molnar <[email protected]>

---
 kernel/events/core.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

kernel/events/core.c +8 -1

index 5854fcf..49a5118 100644
@@ -4225,7 +4225,14 @@ retry:
 		goto retry;
 	}
 
-	__perf_event_period(&pe);
+	if (event->attr.freq) {
+		event->attr.sample_freq = value;
+	} else {
+		event->attr.sample_period = value;
+		event->hw.sample_period = value;
+	}
+
+	local64_set(&event->hw.period_left, 0);
 	raw_spin_unlock_irq(&ctx->lock);
 
 	return 0;