* sound: spinlock lockup in snd_seq_oss_write @ 2016-02-04 19:37 Dmitry Vyukov 2016-02-09 11:14 ` Takashi Iwai 0 siblings, 1 reply; 3+ messages in thread From: Dmitry Vyukov @ 2016-02-04 19:37 UTC (permalink / raw) To: Jaroslav Kysela, Takashi Iwai, alsa-devel, LKML Cc: syzkaller, Kostya Serebryany, Alexander Potapenko, Sasha Levin Hello, The following program hangs machine: https://gist.githubusercontent.com/dvyukov/1c9eeb67414a9e7c5e52/raw/127b660cd2efbce0e3d8a01862d38a2bc0a16bcb/gistfile1.txt BUG: spinlock lockup suspected on CPU#2, a.out/7470 lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 00000000ffffffff ffff88005f5ff660 ffffffff82be30ad ffff880036a9ef50 ffff88005d3d5f00 ffff88005d0b4740 ffff88005f5ff698 ffffffff8146768d ffffffff85241dce ffff880000000000 ffff880036a9ef50 ffff880036a9ef60 Call Trace: [< inline >] __dump_stack lib/dump_stack.c:15 [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 kernel/locking/spinlock_debug.c:137 [< inline >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:119 [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 kernel/locking/spinlock.c:159 [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 sound/core/seq/seq_timer.c:405 [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 sound/core/seq/seq_queue.c:748 [<ffffffff852c01b5>] event_input_timer+0x25/0x30 sound/core/seq/seq_system.c:118 [<ffffffff852b2de4>] snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 sound/core/seq/seq_clientmgr.c:634 [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 sound/core/seq/seq_clientmgr.c:831 [<ffffffff852b4636>] snd_seq_kernel_client_dispatch+0x126/0x170 sound/core/seq/seq_clientmgr.c:2404 [<ffffffff852c92eb>] send_timer_event.isra.0+0x10b/0x150 sound/core/seq/oss/seq_oss_timer.c:153 [<ffffffff852c981a>] snd_seq_oss_timer_start+0x1ca/0x310 sound/core/seq/oss/seq_oss_timer.c:174 [<ffffffff852c9c04>] snd_seq_oss_process_timer_event+0x2a4/0x340 sound/core/seq/oss/seq_oss_timer.c:106 [< inline >] insert_queue sound/core/seq/oss/seq_oss_rw.c:170 [<ffffffff852cf7ab>] snd_seq_oss_write+0x20b/0x810 sound/core/seq/oss/seq_oss_rw.c:148 [<ffffffff852c74f9>] odev_write+0x59/0xa0 sound/core/seq/oss/seq_oss.c:179 [<ffffffff817bacd3>] __vfs_write+0x113/0x4b0 fs/read_write.c:528 [<ffffffff817bc797>] vfs_write+0x167/0x4a0 fs/read_write.c:577 [< inline >] SYSC_write fs/read_write.c:624 [<ffffffff817bfa81>] SyS_write+0x111/0x220 fs/read_write.c:616 [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a arch/x86/entry/entry_64.S:185 Sending NMI to all CPUs: NMI backtrace for cpu 0 CPU: 0 PID: 7473 Comm: a.out Not tainted 4.5.0-rc2+ #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 task: ffff88003376df00 ti: ffff880032440000 task.ti: ffff880032440000 RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 RSP: 0018:ffff8800324479f8 EFLAGS: 00000006 RAX: 00000000a0066ab3 RBX: ffff880036a9ef50 RCX: 000000000000001e RDX: 0000000000000100 RSI: 00000100a0066a95 RDI: 0000000000000001 RBP: ffff8800324479f8 R08: 0000000000000000 R09: 0000000000000001 R10: ffff88003376df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 0000000099db9d6d FS: 00007f94a370e700(0000) GS:ffff88003ec00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 000000c82010e120 CR3: 000000003334f000 CR4: 00000000000006f0 Stack: ffff880032447a08 ffffffff82c102ea ffff880032447a40 ffffffff81467999 ffff880036a9ef50 ffff880036a9ee20 0000000000000282 ffff880035d8ab70 0000000000000000 ffff880032447a60 ffffffff8665dfbb ffffffff8523dd64 Call Trace: [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 kernel/locking/spinlock_debug.c:137 [< inline >] __raw_spin_lock include/linux/spinlock_api_smp.h:145 [<ffffffff8665dfbb>] _raw_spin_lock+0x3b/0x50 kernel/locking/spinlock.c:151 [< inline >] spin_lock include/linux/spinlock.h:302 [<ffffffff8523dd64>] snd_timer_start_slave+0xd4/0x200 sound/core/timer.c:460 [<ffffffff85241880>] snd_timer_continue+0x200/0x290 sound/core/timer.c:598 [< inline >] snd_timer_user_continue sound/core/timer.c:1822 [< inline >] __snd_timer_user_ioctl sound/core/timer.c:1889 [<ffffffff85246a9d>] snd_timer_user_ioctl+0xe1d/0x25f0 sound/core/timer.c:1904 [< inline >] vfs_ioctl fs/ioctl.c:43 [<ffffffff817faf7c>] do_vfs_ioctl+0x18c/0xfb0 fs/ioctl.c:674 [< inline >] SYSC_ioctl fs/ioctl.c:689 [<ffffffff817fbe2f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:680 [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a arch/x86/entry/entry_64.S:185 Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d NMI backtrace for cpu 1 CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 task: ffff88003330df00 ti: ffff880032230000 task.ti: ffff880032230000 RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 RSP: 0018:ffff88003ed07c80 EFLAGS: 00000006 RAX: 00000000a0066d38 RBX: ffff880036a9ef50 RCX: 000000000000001e RDX: 0000000000000100 RSI: 00000100a0066d0f RDI: 0000000000000001 RBP: ffff88003ed07c80 R08: 0000000000000001 R09: 0000000000000001 R10: ffff88003330df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 000000009a82fe90 FS: 000000c820127700(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 000000c8201004e0 CR3: 0000000032076000 CR4: 00000000000006e0 Stack: ffff88003ed07c90 ffffffff82c102ea ffff88003ed07cc8 ffffffff81467999 ffff880036a9ef50 0000000000000082 ffff880036a9ee20 00000000000f4240 ffff880032795068 ffff88003ed07cf0 ffffffff8665ea57 ffffffff85242019 Call Trace: d [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 kernel/locking/spinlock_debug.c:137 [< inline >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:119 [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 kernel/locking/spinlock.c:159 [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 kernel/time/hrtimer.c:1312 [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 arch/x86/kernel/apic/apic.c:907 [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 arch/x86/kernel/apic/apic.c:931 [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 arch/x86/entry/entry_64.S:520 [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 [< inline >] slab_post_alloc_hook mm/slub.c:1337 [< inline >] slab_alloc_node mm/slub.c:2596 [< inline >] slab_alloc mm/slub.c:2604 [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 [< inline >] copy_files kernel/fork.c:1033 [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 [< inline >] copy_process kernel/fork.c:1274 [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 [< inline >] SYSC_clone kernel/fork.c:1832 [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a arch/x86/entry/entry_64.S:185 Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d NMI backtrace for cpu 2 CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 task: ffff88005d0b4740 ti: ffff88005f5f8000 task.ti: ffff88005f5f8000 RIP: 0010:[<ffffffff81262066>] [<ffffffff81262066>] flat_send_IPI_mask+0x156/0x290 RSP: 0018:ffff88005f5ff5d0 EFLAGS: 00000046 RAX: 0000000000000000 RBX: 0000000000000c00 RCX: 0000000000000000 RDX: 0000000000000c00 RSI: 0000000000000002 RDI: ffffffffff5fc300 RBP: ffff88005f5ff5f8 R08: 0000000000000001 R09: 0000000000000000 R10: fffffbfff11c14aa R11: 1ffffffff13552ed R12: 0000000000000082 BUG: spinlock lockup suspected on CPU#1, stress/7421 lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 00000000ffffffff ffff88003ed07c58 ffffffff82be30ad ffff880036a9ef50 ffff88005d3d5f00 ffff88003330df00 ffff88003ed07c90 ffffffff8146768d ffffffff85242019 0000000000000000 ffff880036a9ef50 ffff880036a9ef60 Call Trace: <IRQ> [< inline >] __dump_stack lib/dump_stack.c:15 <IRQ> [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 kernel/locking/spinlock_debug.c:137 [< inline >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:119 [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 kernel/locking/spinlock.c:159 [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 kernel/time/hrtimer.c:1312 [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 arch/x86/kernel/apic/apic.c:907 [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 arch/x86/kernel/apic/apic.c:931 [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 arch/x86/entry/entry_64.S:520 [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 [< inline >] slab_post_alloc_hook mm/slub.c:1337 [< inline >] slab_alloc_node mm/slub.c:2596 [< inline >] slab_alloc mm/slub.c:2604 [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 [< inline >] copy_files kernel/fork.c:1033 [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 [< inline >] copy_process kernel/fork.c:1274 [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 [< inline >] SYSC_clone kernel/fork.c:1832 [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a arch/x86/entry/entry_64.S:185 R13: 000000000f000000 R14: ffffffff87b00c80 R15: 0000000000000002 FS: 00007fcabc427700(0000) GS:ffff88006d600000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 0000000020028073 CR3: 000000005c829000 CR4: 00000000000006e0 Stack: ffffffff87b00c80 ffffffff888be0a0 0000000000000007 fffffbfff111761c ffff88006d71a540 ffff88005f5ff618 ffffffff81257bfe ffffffff86ac7020 dffffc0000000000 ffff88005f5ff688 ffffffff82bee6ac ffffffff811aa610 Call Trace: [<ffffffff81257bfe>] nmi_raise_cpu_backtrace+0x5e/0x80 arch/x86/kernel/apic/hw_nmi.c:33 [<ffffffff82bee6ac>] nmi_trigger_all_cpu_backtrace+0x54c/0x5f0 lib/nmi_backtrace.c:85 [<ffffffff81257c54>] arch_trigger_all_cpu_backtrace+0x14/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 [<ffffffff814679b7>] do_raw_spin_lock+0x167/0x2b0 kernel/locking/spinlock_debug.c:137 [< inline >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:119 [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 kernel/locking/spinlock.c:159 [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 sound/core/seq/seq_timer.c:405 [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 sound/core/seq/seq_queue.c:748 [<ffffffff852c01b5>] event_input_timer+0x25/0x30 sound/core/seq/seq_system.c:118 [<ffffffff852b2de4>] snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 sound/core/seq/seq_clientmgr.c:634 [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 sound/core/seq/seq_clientmgr.c:831 On commit b37a05c083c85c2657dca9bbe1f5d79dccf756d5 + latest Takashi fixes. ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: sound: spinlock lockup in snd_seq_oss_write 2016-02-04 19:37 sound: spinlock lockup in snd_seq_oss_write Dmitry Vyukov @ 2016-02-09 11:14 ` Takashi Iwai 2016-02-15 15:19 ` Dmitry Vyukov 0 siblings, 1 reply; 3+ messages in thread From: Takashi Iwai @ 2016-02-09 11:14 UTC (permalink / raw) To: Dmitry Vyukov Cc: alsa-devel, LKML, Kostya Serebryany, syzkaller, Alexander Potapenko, Sasha Levin [-- Attachment #1: Type: text/plain, Size: 16095 bytes --] On Thu, 04 Feb 2016 20:37:13 +0100, Dmitry Vyukov wrote: > > Hello, > > The following program hangs machine: > https://gist.githubusercontent.com/dvyukov/1c9eeb67414a9e7c5e52/raw/127b660cd2efbce0e3d8a01862d38a2bc0a16bcb/gistfile1.txt > > > BUG: spinlock lockup suspected on CPU#2, a.out/7470 > lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 > CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > 00000000ffffffff ffff88005f5ff660 ffffffff82be30ad ffff880036a9ef50 > ffff88005d3d5f00 ffff88005d0b4740 ffff88005f5ff698 ffffffff8146768d > ffffffff85241dce ffff880000000000 ffff880036a9ef50 ffff880036a9ef60 > Call Trace: > [< inline >] __dump_stack lib/dump_stack.c:15 > [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 > [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 > [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 > [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 > kernel/locking/spinlock_debug.c:137 > [< inline >] __raw_spin_lock_irqsave > include/linux/spinlock_api_smp.h:119 > [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 > kernel/locking/spinlock.c:159 > [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 > [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 > [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 > sound/core/seq/seq_timer.c:405 > [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 > [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 > sound/core/seq/seq_queue.c:748 > [<ffffffff852c01b5>] event_input_timer+0x25/0x30 > sound/core/seq/seq_system.c:118 > [<ffffffff852b2de4>] > snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 > sound/core/seq/seq_clientmgr.c:634 > [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 > sound/core/seq/seq_clientmgr.c:831 > [<ffffffff852b4636>] snd_seq_kernel_client_dispatch+0x126/0x170 > sound/core/seq/seq_clientmgr.c:2404 > [<ffffffff852c92eb>] send_timer_event.isra.0+0x10b/0x150 > sound/core/seq/oss/seq_oss_timer.c:153 > [<ffffffff852c981a>] snd_seq_oss_timer_start+0x1ca/0x310 > sound/core/seq/oss/seq_oss_timer.c:174 > [<ffffffff852c9c04>] snd_seq_oss_process_timer_event+0x2a4/0x340 > sound/core/seq/oss/seq_oss_timer.c:106 > [< inline >] insert_queue sound/core/seq/oss/seq_oss_rw.c:170 > [<ffffffff852cf7ab>] snd_seq_oss_write+0x20b/0x810 > sound/core/seq/oss/seq_oss_rw.c:148 > [<ffffffff852c74f9>] odev_write+0x59/0xa0 sound/core/seq/oss/seq_oss.c:179 > [<ffffffff817bacd3>] __vfs_write+0x113/0x4b0 fs/read_write.c:528 > [<ffffffff817bc797>] vfs_write+0x167/0x4a0 fs/read_write.c:577 > [< inline >] SYSC_write fs/read_write.c:624 > [<ffffffff817bfa81>] SyS_write+0x111/0x220 fs/read_write.c:616 > [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a > arch/x86/entry/entry_64.S:185 > Sending NMI to all CPUs: > NMI backtrace for cpu 0 > CPU: 0 PID: 7473 Comm: a.out Not tainted 4.5.0-rc2+ #319 > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > task: ffff88003376df00 ti: ffff880032440000 task.ti: ffff880032440000 > RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 > RSP: 0018:ffff8800324479f8 EFLAGS: 00000006 > RAX: 00000000a0066ab3 RBX: ffff880036a9ef50 RCX: 000000000000001e > RDX: 0000000000000100 RSI: 00000100a0066a95 RDI: 0000000000000001 > RBP: ffff8800324479f8 R08: 0000000000000000 R09: 0000000000000001 > R10: ffff88003376df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 > R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 0000000099db9d6d > FS: 00007f94a370e700(0000) GS:ffff88003ec00000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b > CR2: 000000c82010e120 CR3: 000000003334f000 CR4: 00000000000006f0 > Stack: > ffff880032447a08 ffffffff82c102ea ffff880032447a40 ffffffff81467999 > ffff880036a9ef50 ffff880036a9ee20 0000000000000282 ffff880035d8ab70 > 0000000000000000 ffff880032447a60 ffffffff8665dfbb ffffffff8523dd64 > Call Trace: > [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 > [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 > [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 > kernel/locking/spinlock_debug.c:137 > [< inline >] __raw_spin_lock include/linux/spinlock_api_smp.h:145 > [<ffffffff8665dfbb>] _raw_spin_lock+0x3b/0x50 kernel/locking/spinlock.c:151 > [< inline >] spin_lock include/linux/spinlock.h:302 > [<ffffffff8523dd64>] snd_timer_start_slave+0xd4/0x200 sound/core/timer.c:460 > [<ffffffff85241880>] snd_timer_continue+0x200/0x290 sound/core/timer.c:598 > [< inline >] snd_timer_user_continue sound/core/timer.c:1822 > [< inline >] __snd_timer_user_ioctl sound/core/timer.c:1889 > [<ffffffff85246a9d>] snd_timer_user_ioctl+0xe1d/0x25f0 sound/core/timer.c:1904 > [< inline >] vfs_ioctl fs/ioctl.c:43 > [<ffffffff817faf7c>] do_vfs_ioctl+0x18c/0xfb0 fs/ioctl.c:674 > [< inline >] SYSC_ioctl fs/ioctl.c:689 > [<ffffffff817fbe2f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:680 > [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a > arch/x86/entry/entry_64.S:185 > Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d > 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> > c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d > NMI backtrace for cpu 1 > CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > task: ffff88003330df00 ti: ffff880032230000 task.ti: ffff880032230000 > RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 > RSP: 0018:ffff88003ed07c80 EFLAGS: 00000006 > RAX: 00000000a0066d38 RBX: ffff880036a9ef50 RCX: 000000000000001e > RDX: 0000000000000100 RSI: 00000100a0066d0f RDI: 0000000000000001 > RBP: ffff88003ed07c80 R08: 0000000000000001 R09: 0000000000000001 > R10: ffff88003330df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 > R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 000000009a82fe90 > FS: 000000c820127700(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 000000c8201004e0 CR3: 0000000032076000 CR4: 00000000000006e0 > Stack: > ffff88003ed07c90 ffffffff82c102ea ffff88003ed07cc8 ffffffff81467999 > ffff880036a9ef50 0000000000000082 ffff880036a9ee20 00000000000f4240 > ffff880032795068 ffff88003ed07cf0 ffffffff8665ea57 ffffffff85242019 > Call Trace: > d [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 > [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 > [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 > kernel/locking/spinlock_debug.c:137 > [< inline >] __raw_spin_lock_irqsave > include/linux/spinlock_api_smp.h:119 > [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 > kernel/locking/spinlock.c:159 > [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 > [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 > [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 > [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 > kernel/time/hrtimer.c:1312 > [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 > [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 > arch/x86/kernel/apic/apic.c:907 > [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 > arch/x86/kernel/apic/apic.c:931 > [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 > arch/x86/entry/entry_64.S:520 > [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 > [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 > [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 > [< inline >] slab_post_alloc_hook mm/slub.c:1337 > [< inline >] slab_alloc_node mm/slub.c:2596 > [< inline >] slab_alloc mm/slub.c:2604 > [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 > [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 > [< inline >] copy_files kernel/fork.c:1033 > [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 > [< inline >] copy_process kernel/fork.c:1274 > [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 > [< inline >] SYSC_clone kernel/fork.c:1832 > [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 > [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a > arch/x86/entry/entry_64.S:185 > Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d > 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> > c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d > NMI backtrace for cpu 2 > CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > task: ffff88005d0b4740 ti: ffff88005f5f8000 task.ti: ffff88005f5f8000 > RIP: 0010:[<ffffffff81262066>] [<ffffffff81262066>] > flat_send_IPI_mask+0x156/0x290 > RSP: 0018:ffff88005f5ff5d0 EFLAGS: 00000046 > RAX: 0000000000000000 RBX: 0000000000000c00 RCX: 0000000000000000 > RDX: 0000000000000c00 RSI: 0000000000000002 RDI: ffffffffff5fc300 > RBP: ffff88005f5ff5f8 R08: 0000000000000001 R09: 0000000000000000 > R10: fffffbfff11c14aa R11: 1ffffffff13552ed R12: 0000000000000082 > BUG: spinlock lockup suspected on CPU#1, stress/7421 > lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 > CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > 00000000ffffffff ffff88003ed07c58 ffffffff82be30ad ffff880036a9ef50 > ffff88005d3d5f00 ffff88003330df00 ffff88003ed07c90 ffffffff8146768d > ffffffff85242019 0000000000000000 ffff880036a9ef50 ffff880036a9ef60 > Call Trace: > <IRQ> [< inline >] __dump_stack lib/dump_stack.c:15 > <IRQ> [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 > [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 > [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 > [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 > kernel/locking/spinlock_debug.c:137 > [< inline >] __raw_spin_lock_irqsave > include/linux/spinlock_api_smp.h:119 > [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 > kernel/locking/spinlock.c:159 > [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 > [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 > [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 > [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 > kernel/time/hrtimer.c:1312 > [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 > [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 > arch/x86/kernel/apic/apic.c:907 > [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 > arch/x86/kernel/apic/apic.c:931 > [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 > arch/x86/entry/entry_64.S:520 > [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 > [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 > [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 > [< inline >] slab_post_alloc_hook mm/slub.c:1337 > [< inline >] slab_alloc_node mm/slub.c:2596 > [< inline >] slab_alloc mm/slub.c:2604 > [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 > [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 > [< inline >] copy_files kernel/fork.c:1033 > [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 > [< inline >] copy_process kernel/fork.c:1274 > [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 > [< inline >] SYSC_clone kernel/fork.c:1832 > [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 > [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a > arch/x86/entry/entry_64.S:185 > R13: 000000000f000000 R14: ffffffff87b00c80 R15: 0000000000000002 > FS: 00007fcabc427700(0000) GS:ffff88006d600000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b > CR2: 0000000020028073 CR3: 000000005c829000 CR4: 00000000000006e0 > Stack: > ffffffff87b00c80 ffffffff888be0a0 0000000000000007 fffffbfff111761c > ffff88006d71a540 ffff88005f5ff618 ffffffff81257bfe ffffffff86ac7020 > dffffc0000000000 ffff88005f5ff688 ffffffff82bee6ac ffffffff811aa610 > Call Trace: > [<ffffffff81257bfe>] nmi_raise_cpu_backtrace+0x5e/0x80 > arch/x86/kernel/apic/hw_nmi.c:33 > [<ffffffff82bee6ac>] nmi_trigger_all_cpu_backtrace+0x54c/0x5f0 > lib/nmi_backtrace.c:85 > [<ffffffff81257c54>] arch_trigger_all_cpu_backtrace+0x14/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 > [<ffffffff814679b7>] do_raw_spin_lock+0x167/0x2b0 > kernel/locking/spinlock_debug.c:137 > [< inline >] __raw_spin_lock_irqsave > include/linux/spinlock_api_smp.h:119 > [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 > kernel/locking/spinlock.c:159 > [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 > [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 > [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 > sound/core/seq/seq_timer.c:405 > [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 > [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 > sound/core/seq/seq_queue.c:748 > [<ffffffff852c01b5>] event_input_timer+0x25/0x30 > sound/core/seq/seq_system.c:118 > [<ffffffff852b2de4>] > snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 > sound/core/seq/seq_clientmgr.c:634 > [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 > sound/core/seq/seq_clientmgr.c:831 > > On commit b37a05c083c85c2657dca9bbe1f5d79dccf756d5 + latest Takashi fixes. This took really long time to finally figure out what goes wrong. Despite it showing OSS sequencer, the real culprit of this lockup was a typo: a wrong pointer was passed in the loop. @@ -422,7 +422,7 @@ static void snd_timer_notify1(struct snd_timer_instance *ti, int event) spin_lock_irqsave(&timer->lock, flags); list_for_each_entry(ts, &ti->slave_active_head, active_list) if (ts->ccallback) - ts->ccallback(ti, event + 100, &tstamp, resolution); + ts->ccallback(ts, event + 100, &tstamp, resolution); spin_unlock_irqrestore(&timer->lock, flags); The proper patch is found in the first attachment. However, this alone isn't enough. I still got a list corruption even after that fix. Chasing this also took long time, and it resulted in yet another trivial patch, as found in the second attachment. It's basically a missing spinlock for a slave timer at stopping it. @@ -518,9 +518,13 @@ static int _snd_timer_stop(struct snd_timer_instance *timeri, int event) spin_unlock_irqrestore(&slave_active_lock, flags); return -EBUSY; } + if (timeri->timer) + spin_lock(&timeri->timer->lock); timeri->flags &= ~SNDRV_TIMER_IFLG_RUNNING; list_del_init(&timeri->ack_list); list_del_init(&timeri->active_list); + if (timeri->timer) + spin_unlock(&timeri->timer->lock); spin_unlock_irqrestore(&slave_active_lock, flags); goto __end; } Could you try these two patches below? These cured the test case on my local machine, at least. If it's not enough, I have yet more patches to try, but these are the minimally needed changes I figured out. thanks, Takashi [-- Attachment #2: 0001-ALSA-timer-Fix-wrong-instance-passed-to-slave-callba.patch --] [-- Type: application/octet-stream, Size: 1383 bytes --] >From 117159f0b9d392fb433a7871426fad50317f06f7 Mon Sep 17 00:00:00 2001 From: Takashi Iwai <tiwai@suse.de> Date: Mon, 8 Feb 2016 17:36:25 +0100 Subject: [PATCH 1/2] ALSA: timer: Fix wrong instance passed to slave callbacks In snd_timer_notify1(), the wrong timer instance was passed for slave ccallback function. This leads to the access to the wrong data when an incompatible master is handled (e.g. the master is the sequencer timer and the slave is a user timer), as spotted by syzkaller fuzzer. This patch fixes that wrong assignment. BugLink: http://lkml.kernel.org/r/CACT4Y+Y_Bm+7epAb=8Wi=AaWd+DYS7qawX52qxdCfOfY49vozQ@mail.gmail.com Reported-by: Dmitry Vyukov <dvyukov@google.com> Cc: <stable@vger.kernel.org> Signed-off-by: Takashi Iwai <tiwai@suse.de> --- sound/core/timer.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sound/core/timer.c b/sound/core/timer.c index 9b513a05765a..dea932ac6165 100644 --- a/sound/core/timer.c +++ b/sound/core/timer.c @@ -422,7 +422,7 @@ static void snd_timer_notify1(struct snd_timer_instance *ti, int event) spin_lock_irqsave(&timer->lock, flags); list_for_each_entry(ts, &ti->slave_active_head, active_list) if (ts->ccallback) - ts->ccallback(ti, event + 100, &tstamp, resolution); + ts->ccallback(ts, event + 100, &tstamp, resolution); spin_unlock_irqrestore(&timer->lock, flags); } -- 2.7.1 [-- Attachment #3: 0002-ALSA-timer-Fix-race-between-stop-and-interrupt.patch --] [-- Type: application/octet-stream, Size: 1602 bytes --] >From ed8b1d6d2c741ab26d60d499d7fbb7ac801f0f51 Mon Sep 17 00:00:00 2001 From: Takashi Iwai <tiwai@suse.de> Date: Tue, 9 Feb 2016 12:02:32 +0100 Subject: [PATCH 2/2] ALSA: timer: Fix race between stop and interrupt A slave timer element also unlinks at snd_timer_stop() but it takes only slave_active_lock. When a slave is assigned to a master, however, this may become a race against the master's interrupt handling, eventually resulting in a list corruption. The actual bug could be seen with a syzkaller fuzzer test case in BugLink below. As a fix, we need to take timeri->timer->lock when timer isn't NULL, i.e. assigned to a master, while the assignment to a master itself is protected by slave_active_lock. BugLink: http://lkml.kernel.org/r/CACT4Y+Y_Bm+7epAb=8Wi=AaWd+DYS7qawX52qxdCfOfY49vozQ@mail.gmail.com Cc: <stable@vger.kernel.org> Signed-off-by: Takashi Iwai <tiwai@suse.de> --- sound/core/timer.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/sound/core/timer.c b/sound/core/timer.c index dea932ac6165..a0405b0078c6 100644 --- a/sound/core/timer.c +++ b/sound/core/timer.c @@ -518,9 +518,13 @@ static int _snd_timer_stop(struct snd_timer_instance *timeri, int event) spin_unlock_irqrestore(&slave_active_lock, flags); return -EBUSY; } + if (timeri->timer) + spin_lock(&timeri->timer->lock); timeri->flags &= ~SNDRV_TIMER_IFLG_RUNNING; list_del_init(&timeri->ack_list); list_del_init(&timeri->active_list); + if (timeri->timer) + spin_unlock(&timeri->timer->lock); spin_unlock_irqrestore(&slave_active_lock, flags); goto __end; } -- 2.7.1 [-- Attachment #4: Type: text/plain, Size: 0 bytes --] ^ permalink raw reply related [flat|nested] 3+ messages in thread
* Re: sound: spinlock lockup in snd_seq_oss_write 2016-02-09 11:14 ` Takashi Iwai @ 2016-02-15 15:19 ` Dmitry Vyukov 0 siblings, 0 replies; 3+ messages in thread From: Dmitry Vyukov @ 2016-02-15 15:19 UTC (permalink / raw) To: Takashi Iwai Cc: alsa-devel, Jaroslav Kysela, LKML, Alexander Potapenko, Kostya Serebryany, syzkaller, Sasha Levin On Tue, Feb 9, 2016 at 12:14 PM, Takashi Iwai <tiwai@suse.de> wrote: > On Thu, 04 Feb 2016 20:37:13 +0100, > Dmitry Vyukov wrote: >> >> Hello, >> >> The following program hangs machine: >> https://gist.githubusercontent.com/dvyukov/1c9eeb67414a9e7c5e52/raw/127b660cd2efbce0e3d8a01862d38a2bc0a16bcb/gistfile1.txt >> >> >> BUG: spinlock lockup suspected on CPU#2, a.out/7470 >> lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 >> CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 >> 00000000ffffffff ffff88005f5ff660 ffffffff82be30ad ffff880036a9ef50 >> ffff88005d3d5f00 ffff88005d0b4740 ffff88005f5ff698 ffffffff8146768d >> ffffffff85241dce ffff880000000000 ffff880036a9ef50 ffff880036a9ef60 >> Call Trace: >> [< inline >] __dump_stack lib/dump_stack.c:15 >> [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 >> [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 >> [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 >> [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 >> kernel/locking/spinlock_debug.c:137 >> [< inline >] __raw_spin_lock_irqsave >> include/linux/spinlock_api_smp.h:119 >> [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 >> kernel/locking/spinlock.c:159 >> [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 >> [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 >> [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 >> sound/core/seq/seq_timer.c:405 >> [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 >> [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 >> sound/core/seq/seq_queue.c:748 >> [<ffffffff852c01b5>] event_input_timer+0x25/0x30 >> sound/core/seq/seq_system.c:118 >> [<ffffffff852b2de4>] >> snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 >> sound/core/seq/seq_clientmgr.c:634 >> [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 >> sound/core/seq/seq_clientmgr.c:831 >> [<ffffffff852b4636>] snd_seq_kernel_client_dispatch+0x126/0x170 >> sound/core/seq/seq_clientmgr.c:2404 >> [<ffffffff852c92eb>] send_timer_event.isra.0+0x10b/0x150 >> sound/core/seq/oss/seq_oss_timer.c:153 >> [<ffffffff852c981a>] snd_seq_oss_timer_start+0x1ca/0x310 >> sound/core/seq/oss/seq_oss_timer.c:174 >> [<ffffffff852c9c04>] snd_seq_oss_process_timer_event+0x2a4/0x340 >> sound/core/seq/oss/seq_oss_timer.c:106 >> [< inline >] insert_queue sound/core/seq/oss/seq_oss_rw.c:170 >> [<ffffffff852cf7ab>] snd_seq_oss_write+0x20b/0x810 >> sound/core/seq/oss/seq_oss_rw.c:148 >> [<ffffffff852c74f9>] odev_write+0x59/0xa0 sound/core/seq/oss/seq_oss.c:179 >> [<ffffffff817bacd3>] __vfs_write+0x113/0x4b0 fs/read_write.c:528 >> [<ffffffff817bc797>] vfs_write+0x167/0x4a0 fs/read_write.c:577 >> [< inline >] SYSC_write fs/read_write.c:624 >> [<ffffffff817bfa81>] SyS_write+0x111/0x220 fs/read_write.c:616 >> [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a >> arch/x86/entry/entry_64.S:185 >> Sending NMI to all CPUs: >> NMI backtrace for cpu 0 >> CPU: 0 PID: 7473 Comm: a.out Not tainted 4.5.0-rc2+ #319 >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 >> task: ffff88003376df00 ti: ffff880032440000 task.ti: ffff880032440000 >> RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 >> RSP: 0018:ffff8800324479f8 EFLAGS: 00000006 >> RAX: 00000000a0066ab3 RBX: ffff880036a9ef50 RCX: 000000000000001e >> RDX: 0000000000000100 RSI: 00000100a0066a95 RDI: 0000000000000001 >> RBP: ffff8800324479f8 R08: 0000000000000000 R09: 0000000000000001 >> R10: ffff88003376df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 >> R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 0000000099db9d6d >> FS: 00007f94a370e700(0000) GS:ffff88003ec00000(0000) knlGS:0000000000000000 >> CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b >> CR2: 000000c82010e120 CR3: 000000003334f000 CR4: 00000000000006f0 >> Stack: >> ffff880032447a08 ffffffff82c102ea ffff880032447a40 ffffffff81467999 >> ffff880036a9ef50 ffff880036a9ee20 0000000000000282 ffff880035d8ab70 >> 0000000000000000 ffff880032447a60 ffffffff8665dfbb ffffffff8523dd64 >> Call Trace: >> [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 >> [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 >> [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 >> kernel/locking/spinlock_debug.c:137 >> [< inline >] __raw_spin_lock include/linux/spinlock_api_smp.h:145 >> [<ffffffff8665dfbb>] _raw_spin_lock+0x3b/0x50 kernel/locking/spinlock.c:151 >> [< inline >] spin_lock include/linux/spinlock.h:302 >> [<ffffffff8523dd64>] snd_timer_start_slave+0xd4/0x200 sound/core/timer.c:460 >> [<ffffffff85241880>] snd_timer_continue+0x200/0x290 sound/core/timer.c:598 >> [< inline >] snd_timer_user_continue sound/core/timer.c:1822 >> [< inline >] __snd_timer_user_ioctl sound/core/timer.c:1889 >> [<ffffffff85246a9d>] snd_timer_user_ioctl+0xe1d/0x25f0 sound/core/timer.c:1904 >> [< inline >] vfs_ioctl fs/ioctl.c:43 >> [<ffffffff817faf7c>] do_vfs_ioctl+0x18c/0xfb0 fs/ioctl.c:674 >> [< inline >] SYSC_ioctl fs/ioctl.c:689 >> [<ffffffff817fbe2f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:680 >> [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a >> arch/x86/entry/entry_64.S:185 >> Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d >> 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> >> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d >> NMI backtrace for cpu 1 >> CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 >> task: ffff88003330df00 ti: ffff880032230000 task.ti: ffff880032230000 >> RIP: 0010:[<ffffffff82c103a7>] [<ffffffff82c103a7>] delay_tsc+0x27/0x70 >> RSP: 0018:ffff88003ed07c80 EFLAGS: 00000006 >> RAX: 00000000a0066d38 RBX: ffff880036a9ef50 RCX: 000000000000001e >> RDX: 0000000000000100 RSI: 00000100a0066d0f RDI: 0000000000000001 >> RBP: ffff88003ed07c80 R08: 0000000000000001 R09: 0000000000000001 >> R10: ffff88003330df00 R11: ffff880036a9ef68 R12: ffff880036a9ef60 >> R13: 000000009a9d2d40 R14: ffff880036a9ef58 R15: 000000009a82fe90 >> FS: 000000c820127700(0000) GS:ffff88003ed00000(0000) knlGS:0000000000000000 >> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 >> CR2: 000000c8201004e0 CR3: 0000000032076000 CR4: 00000000000006e0 >> Stack: >> ffff88003ed07c90 ffffffff82c102ea ffff88003ed07cc8 ffffffff81467999 >> ffff880036a9ef50 0000000000000082 ffff880036a9ee20 00000000000f4240 >> ffff880032795068 ffff88003ed07cf0 ffffffff8665ea57 ffffffff85242019 >> Call Trace: >> d [<ffffffff82c102ea>] __delay+0xa/0x10 arch/x86/lib/delay.c:153 >> [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:114 >> [<ffffffff81467999>] do_raw_spin_lock+0x149/0x2b0 >> kernel/locking/spinlock_debug.c:137 >> [< inline >] __raw_spin_lock_irqsave >> include/linux/spinlock_api_smp.h:119 >> [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 >> kernel/locking/spinlock.c:159 >> [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 >> [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 >> [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 >> [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 >> kernel/time/hrtimer.c:1312 >> [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 >> [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 >> arch/x86/kernel/apic/apic.c:907 >> [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 >> arch/x86/kernel/apic/apic.c:931 >> [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 >> arch/x86/entry/entry_64.S:520 >> [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 >> [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 >> [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 >> [< inline >] slab_post_alloc_hook mm/slub.c:1337 >> [< inline >] slab_alloc_node mm/slub.c:2596 >> [< inline >] slab_alloc mm/slub.c:2604 >> [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 >> [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 >> [< inline >] copy_files kernel/fork.c:1033 >> [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 >> [< inline >] copy_process kernel/fork.c:1274 >> [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 >> [< inline >] SYSC_clone kernel/fork.c:1832 >> [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 >> [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a >> arch/x86/entry/entry_64.S:185 >> Code: 00 00 00 00 55 65 ff 05 c8 4a 40 7d 48 89 e5 65 44 8b 05 8d 2d >> 40 7d 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> >> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 f9 73 27 65 ff 0d >> NMI backtrace for cpu 2 >> CPU: 2 PID: 7470 Comm: a.out Not tainted 4.5.0-rc2+ #319 >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 >> task: ffff88005d0b4740 ti: ffff88005f5f8000 task.ti: ffff88005f5f8000 >> RIP: 0010:[<ffffffff81262066>] [<ffffffff81262066>] >> flat_send_IPI_mask+0x156/0x290 >> RSP: 0018:ffff88005f5ff5d0 EFLAGS: 00000046 >> RAX: 0000000000000000 RBX: 0000000000000c00 RCX: 0000000000000000 >> RDX: 0000000000000c00 RSI: 0000000000000002 RDI: ffffffffff5fc300 >> RBP: ffff88005f5ff5f8 R08: 0000000000000001 R09: 0000000000000000 >> R10: fffffbfff11c14aa R11: 1ffffffff13552ed R12: 0000000000000082 >> BUG: spinlock lockup suspected on CPU#1, stress/7421 >> lock: 0xffff880036a9ef50, .magic: dead4ead, .owner: a.out/7466, .owner_cpu: 3 >> CPU: 1 PID: 7421 Comm: stress Not tainted 4.5.0-rc2+ #319 >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 >> 00000000ffffffff ffff88003ed07c58 ffffffff82be30ad ffff880036a9ef50 >> ffff88005d3d5f00 ffff88003330df00 ffff88003ed07c90 ffffffff8146768d >> ffffffff85242019 0000000000000000 ffff880036a9ef50 ffff880036a9ef60 >> Call Trace: >> <IRQ> [< inline >] __dump_stack lib/dump_stack.c:15 >> <IRQ> [<ffffffff82be30ad>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50 >> [<ffffffff8146768d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67 >> [< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117 >> [<ffffffff814679ad>] do_raw_spin_lock+0x15d/0x2b0 >> kernel/locking/spinlock_debug.c:137 >> [< inline >] __raw_spin_lock_irqsave >> include/linux/spinlock_api_smp.h:119 >> [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 >> kernel/locking/spinlock.c:159 >> [<ffffffff85242019>] snd_timer_interrupt+0xa9/0xc80 sound/core/timer.c:718 >> [<ffffffff85248cb9>] snd_hrtimer_callback+0x169/0x230 sound/core/hrtimer.c:54 >> [< inline >] __run_hrtimer kernel/time/hrtimer.c:1248 >> [<ffffffff814b7dc3>] __hrtimer_run_queues+0x363/0xc20 >> kernel/time/hrtimer.c:1312 >> [<ffffffff814b9de2>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1346 >> [<ffffffff8124e1d2>] local_apic_timer_interrupt+0x72/0xe0 >> arch/x86/kernel/apic/apic.c:907 >> [<ffffffff812516f9>] smp_apic_timer_interrupt+0x79/0xa0 >> arch/x86/kernel/apic/apic.c:931 >> [<ffffffff8665feac>] apic_timer_interrupt+0x8c/0xa0 >> arch/x86/entry/entry_64.S:520 >> [<ffffffff817ab804>] create_object+0x34/0x2d0 mm/kmemleak.c:546 >> [<ffffffff86641fb3>] kmemleak_alloc+0x63/0xa0 mm/kmemleak.c:916 >> [< inline >] kmemleak_alloc_recursive include/linux/kmemleak.h:47 >> [< inline >] slab_post_alloc_hook mm/slub.c:1337 >> [< inline >] slab_alloc_node mm/slub.c:2596 >> [< inline >] slab_alloc mm/slub.c:2604 >> [<ffffffff81760843>] kmem_cache_alloc+0x153/0x2e0 mm/slub.c:2609 >> [<ffffffff8181b1b5>] dup_fd+0x85/0xa90 fs/file.c:298 >> [< inline >] copy_files kernel/fork.c:1033 >> [<ffffffff8134efed>] copy_process.part.35+0x188d/0x57a0 kernel/fork.c:1436 >> [< inline >] copy_process kernel/fork.c:1274 >> [<ffffffff8135322c>] _do_fork+0x1bc/0xcb0 kernel/fork.c:1723 >> [< inline >] SYSC_clone kernel/fork.c:1832 >> [<ffffffff81353df7>] SyS_clone+0x37/0x50 kernel/fork.c:1826 >> [<ffffffff8665f0b6>] entry_SYSCALL_64_fastpath+0x16/0x7a >> arch/x86/entry/entry_64.S:185 >> R13: 000000000f000000 R14: ffffffff87b00c80 R15: 0000000000000002 >> FS: 00007fcabc427700(0000) GS:ffff88006d600000(0000) knlGS:0000000000000000 >> CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b >> CR2: 0000000020028073 CR3: 000000005c829000 CR4: 00000000000006e0 >> Stack: >> ffffffff87b00c80 ffffffff888be0a0 0000000000000007 fffffbfff111761c >> ffff88006d71a540 ffff88005f5ff618 ffffffff81257bfe ffffffff86ac7020 >> dffffc0000000000 ffff88005f5ff688 ffffffff82bee6ac ffffffff811aa610 >> Call Trace: >> [<ffffffff81257bfe>] nmi_raise_cpu_backtrace+0x5e/0x80 >> arch/x86/kernel/apic/hw_nmi.c:33 >> [<ffffffff82bee6ac>] nmi_trigger_all_cpu_backtrace+0x54c/0x5f0 >> lib/nmi_backtrace.c:85 >> [<ffffffff81257c54>] arch_trigger_all_cpu_backtrace+0x14/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 >> [<ffffffff814679b7>] do_raw_spin_lock+0x167/0x2b0 >> kernel/locking/spinlock_debug.c:137 >> [< inline >] __raw_spin_lock_irqsave >> include/linux/spinlock_api_smp.h:119 >> [<ffffffff8665ea57>] _raw_spin_lock_irqsave+0xa7/0xd0 >> kernel/locking/spinlock.c:159 >> [<ffffffff85241dce>] snd_timer_start+0x10e/0x2b0 sound/core/timer.c:491 >> [< inline >] seq_timer_start sound/core/seq/seq_timer.c:393 >> [<ffffffff852bf860>] snd_seq_timer_start+0x1a0/0x2b0 >> sound/core/seq/seq_timer.c:405 >> [< inline >] snd_seq_queue_process_event sound/core/seq/seq_queue.c:687 >> [<ffffffff852ba514>] snd_seq_control_queue+0x304/0x8b0 >> sound/core/seq/seq_queue.c:748 >> [<ffffffff852c01b5>] event_input_timer+0x25/0x30 >> sound/core/seq/seq_system.c:118 >> [<ffffffff852b2de4>] >> snd_seq_deliver_single_event.constprop.11+0x3f4/0x740 >> sound/core/seq/seq_clientmgr.c:634 >> [<ffffffff852b3248>] snd_seq_deliver_event+0x118/0x800 >> sound/core/seq/seq_clientmgr.c:831 >> >> On commit b37a05c083c85c2657dca9bbe1f5d79dccf756d5 + latest Takashi fixes. > > This took really long time to finally figure out what goes wrong. > Despite it showing OSS sequencer, the real culprit of this lockup was > a typo: a wrong pointer was passed in the loop. > > @@ -422,7 +422,7 @@ static void snd_timer_notify1(struct snd_timer_instance *ti, int event) > spin_lock_irqsave(&timer->lock, flags); > list_for_each_entry(ts, &ti->slave_active_head, active_list) > if (ts->ccallback) > - ts->ccallback(ti, event + 100, &tstamp, resolution); > + ts->ccallback(ts, event + 100, &tstamp, resolution); > spin_unlock_irqrestore(&timer->lock, flags); > > The proper patch is found in the first attachment. > > However, this alone isn't enough. I still got a list corruption even > after that fix. Chasing this also took long time, and it resulted in > yet another trivial patch, as found in the second attachment. It's > basically a missing spinlock for a slave timer at stopping it. > > @@ -518,9 +518,13 @@ static int _snd_timer_stop(struct snd_timer_instance *timeri, int event) > spin_unlock_irqrestore(&slave_active_lock, flags); > return -EBUSY; > } > + if (timeri->timer) > + spin_lock(&timeri->timer->lock); > timeri->flags &= ~SNDRV_TIMER_IFLG_RUNNING; > list_del_init(&timeri->ack_list); > list_del_init(&timeri->active_list); > + if (timeri->timer) > + spin_unlock(&timeri->timer->lock); > spin_unlock_irqrestore(&slave_active_lock, flags); > goto __end; > } > > Could you try these two patches below? These cured the test case on > my local machine, at least. If it's not enough, I have yet more > patches to try, but these are the minimally needed changes I figured > out. I see that these patches are already merged while I was OOO. So I've just updated to 4.5-rc4. I will report if I see any sound-related crashes on 4.5-rc4. ^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2016-02-15 15:19 UTC | newest] Thread overview: 3+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2016-02-04 19:37 sound: spinlock lockup in snd_seq_oss_write Dmitry Vyukov 2016-02-09 11:14 ` Takashi Iwai 2016-02-15 15:19 ` Dmitry Vyukov
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).