sound: spinlock lockup in snd_timer_user_tinterrupt

[Dmitry Vyukov]

Hello,

The following program locks up system:
https://gist.githubusercontent.com/dvyukov/1b5cdca7f0fc6254afd4816901160e4c/raw/024c53be2112c83e5d64f3e4d5e8aa38ded727e3/gistfile1.txt


BUG: spinlock lockup suspected on CPU#1, syz-executor0/6018
lock: kvm_count_lock+0x0/0x60, .magic: dead4ead, .owner:
syz-executor0/6001, .owner_cpu: 2
CPU: 1 PID: 6018 Comm: syz-executor0 Not tainted 4.10.0-rc8+ #228
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:15 [inline]
dump_stack+0x2ee/0x3ef lib/dump_stack.c:51
spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67
__spin_lock_debug kernel/locking/spinlock_debug.c:117 [inline]
do_raw_spin_lock+0x2c1/0x5b0 kernel/locking/spinlock_debug.c:137
__raw_spin_lock include/linux/spinlock_api_smp.h:145 [inline]
_raw_spin_lock+0x3b/0x50 kernel/locking/spinlock.c:151
hardware_enable_all arch/x86/kvm/../../../virt/kvm/kvm_main.c:3324 [inline]
kvm_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:632 [inline]
kvm_dev_ioctl_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:3173 [inline]
kvm_dev_ioctl+0x984/0x11b0 arch/x86/kvm/../../../virt/kvm/kvm_main.c:3217
vfs_ioctl fs/ioctl.c:43 [inline]
do_vfs_ioctl+0x1bf/0x1790 fs/ioctl.c:683
SYSC_ioctl fs/ioctl.c:698 [inline]
SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x4458b9
RSP: 002b:00007fb0cb7b7b58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000017 RCX: 00000000004458b9
RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 0000000000000017
RBP: 00000000006dfa10 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000708150
R13: 0000000020000000 R14: 0000000000fff000 R15: 0000000000000003
NMI backtrace for cpu 1
CPU: 1 PID: 6018 Comm: syz-executor0 Not tainted 4.10.0-rc8+ #228
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:15 [inline]
dump_stack+0x2ee/0x3ef lib/dump_stack.c:51
nmi_cpu_backtrace+0xfd/0x120 lib/nmi_backtrace.c:99
nmi_trigger_cpumask_backtrace+0x11d/0x170 lib/nmi_backtrace.c:60
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:37
trigger_all_cpu_backtrace include/linux/nmi.h:58 [inline]
__spin_lock_debug kernel/locking/spinlock_debug.c:119 [inline]
do_raw_spin_lock+0x2cf/0x5b0 kernel/locking/spinlock_debug.c:137
__raw_spin_lock include/linux/spinlock_api_smp.h:145 [inline]
_raw_spin_lock+0x3b/0x50 kernel/locking/spinlock.c:151
hardware_enable_all arch/x86/kvm/../../../virt/kvm/kvm_main.c:3324 [inline]
kvm_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:632 [inline]
kvm_dev_ioctl_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:3173 [inline]
kvm_dev_ioctl+0x984/0x11b0 arch/x86/kvm/../../../virt/kvm/kvm_main.c:3217
vfs_ioctl fs/ioctl.c:43 [inline]
do_vfs_ioctl+0x1bf/0x1790 fs/ioctl.c:683
SYSC_ioctl fs/ioctl.c:698 [inline]
SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x4458b9
RSP: 002b:00007fb0cb7b7b58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000017 RCX: 00000000004458b9
RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 0000000000000017
RBP: 00000000006dfa10 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000708150
R13: 0000000020000000 R14: 0000000000fff000 R15: 0000000000000003
Sending NMI from CPU 1 to CPUs 0,2-3:
NMI backtrace for cpu 0 skipped: idling at pc 0xffffffff84288cb6
NMI backtrace for cpu 2
CPU: 2 PID: 6001 Comm: syz-executor0 Not tainted 4.10.0-rc8+ #228
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff880049720640 task.stack: ffff880024a38000
RIP: 0010:rep_nop arch/x86/include/asm/processor.h:616 [inline]
RIP: 0010:cpu_relax arch/x86/include/asm/processor.h:621 [inline]
RIP: 0010:csd_lock_wait kernel/smp.c:99 [inline]
RIP: 0010:smp_call_function_many+0x75c/0x930 kernel/smp.c:455
RSP: 0018:ffff880024a3f6a0 EFLAGS: 00000246
RAX: 0000000000010000 RBX: ffffe8ffffd052d0 RCX: ffffc90000ab5000
RDX: 0000000000010000 RSI: ffffffff8167f79a RDI: ffffffff84ba1ad8
RBP: ffff880024a3f8c0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000006 R11: 0000000000000000 R12: ffffe8ffffd052e8
R13: dffffc0000000000 R14: 0000000000000003 R15: ffffed0004947eeb
FS: 00007fb0cb7fa700(0000) GS:ffff880089e00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000006dfa10 CR3: 0000000051171000 CR4: 00000000000006e0
DR0: 0000000020000000 DR1: 0000000020000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
Call Trace:
smp_call_function kernel/smp.c:479 [inline]
on_each_cpu+0x109/0x330 kernel/smp.c:589
hardware_enable_all arch/x86/kvm/../../../virt/kvm/kvm_main.c:3329 [inline]
kvm_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:632 [inline]
kvm_dev_ioctl_create_vm arch/x86/kvm/../../../virt/kvm/kvm_main.c:3173 [inline]
kvm_dev_ioctl+0xbe2/0x11b0 arch/x86/kvm/../../../virt/kvm/kvm_main.c:3217
vfs_ioctl fs/ioctl.c:43 [inline]
do_vfs_ioctl+0x1bf/0x1790 fs/ioctl.c:683
SYSC_ioctl fs/ioctl.c:698 [inline]
SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x4458b9
RSP: 002b:00007fb0cb7f9b58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000017 RCX: 00000000004458b9
RDX: 0000000000000000 RSI: 000000000000ae01 RDI: 0000000000000017
RBP: 00000000006dfa10 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000708000
R13: 0000000020000000 R14: 0000000000fff000 R15: 0000000000000003
Code: 3c 03 0f 8e d0 01 00 00 44 89 b5 98 fe ff ff 41 83 e6 01 41 c6
07 f8 74 51 4d 89 e6 41 83 e6 07 41 83 c6 03 e8 66 af 0a 00 f3 90 <4c>
89 e0 41 c6 07 04 48 c1 e8 03 42 0f b6 04 28 41 38 c6 7c 08
NMI backtrace for cpu 3
CPU: 3 PID: 5984 Comm: syz-executor3 Not tainted 4.10.0-rc8+ #228
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88004a566500 task.stack: ffff88002f9f0000
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:767 [inline]
RIP: 0010:lock_release+0x86c/0xe90 kernel/locking/lockdep.c:3775
RSP: 0018:ffff880089f073e8 EFLAGS: 00000082
RAX: dffffc0000000000 RBX: ffff88004a566500 RCX: 1ffff100113e0ea2
RDX: 1ffffffff09d8a95 RSI: 0000000000000001 RDI: 0000000000000082
RBP: ffff880089f07638 R08: ffffe8ffffd32500 R09: 0000000000000001
R10: 1ffff100113e0e6e R11: ffff88009fff70dd R12: ffff880086136d60
R13: 0000000000000001 R14: ffff88004a566d20 R15: 0000000000000002
FS: 00007f366abbe700(0000) GS:ffff880089f00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00005642b47a21e8 CR3: 000000003d684000 CR4: 00000000000006e0
Call Trace:
<IRQ>
__raw_spin_unlock include/linux/spinlock_api_smp.h:152 [inline]
_raw_spin_unlock+0x1a/0x30 kernel/locking/spinlock.c:183
spin_unlock include/linux/spinlock.h:347 [inline]
snd_timer_user_tinterrupt+0x54d/0x950 sound/core/timer.c:1322
snd_timer_interrupt.part.12+0xa8f/0x1480 sound/core/timer.c:799
snd_timer_interrupt+0x88/0xb0 sound/core/timer.c:719
snd_hrtimer_callback+0x1f0/0x3c0 sound/core/hrtimer.c:64
__run_hrtimer kernel/time/hrtimer.c:1238 [inline]
__hrtimer_run_queues+0x385/0xf80 kernel/time/hrtimer.c:1302
hrtimer_interrupt+0x1c2/0x5e0 kernel/time/hrtimer.c:1336
local_apic_timer_interrupt+0x6f/0xe0 arch/x86/kernel/apic/apic.c:936
smp_apic_timer_interrupt+0x71/0xa0 arch/x86/kernel/apic/apic.c:960
apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:487
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:767 [inline]
RIP: 0010:__raw_spin_unlock_irqrestore
include/linux/spinlock_api_smp.h:162 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0x144/0x200 kernel/locking/spinlock.c:191
RSP: 0018:ffff88002f9f7568 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff09d8a95 RBX: 1ffff10005f3eead RCX: 0000000000000006
RDX: 1ffff10005f3eed1 RSI: ffff88004a566cf8 RDI: 0000000000000282
RBP: ffff88002f9f7728 R08: ffffe8ffffd32500 R09: 0000000000000000
R10: 0000000000000006 R11: 0000000000000000 R12: dffffc0000000000
R13: 0000000000000282 R14: ffff88004c077bf0 R15: 0000000000000000
</IRQ>
spin_unlock_irqrestore include/linux/spinlock.h:362 [inline]
snd_timer_start1+0x1e3/0x950 sound/core/timer.c:480
snd_timer_start+0x5d/0xa0 sound/core/timer.c:589
snd_timer_user_start.isra.7+0xde/0x130 sound/core/timer.c:1823
__snd_timer_user_ioctl sound/core/timer.c:1910 [inline]
snd_timer_user_ioctl+0x79d/0x34a0 sound/core/timer.c:1931
vfs_ioctl fs/ioctl.c:43 [inline]
do_vfs_ioctl+0x1bf/0x1790 fs/ioctl.c:683
SYSC_ioctl fs/ioctl.c:698 [inline]
SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x4458b9
RSP: 002b:00007f366abbdb58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000017 RCX: 00000000004458b9
RDX: 0000000000000000 RSI: 00000000000054a0 RDI: 0000000000000017
RBP: 00000000006e0680 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000286 R12: 00000000007080a8
R13: 000000002002f000 R14: 0000000000001000 R15: 0000000000000003
Code: 04 02 f8 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 99 03 00 00 48
83 3d fb 94 92 03 00 0f 84 c4 02 00 00 48 8b bd 00 fe ff ff 57 9d <0f>
1f 44 00 00 48 b8 00 00 00 00 00 fc ff df 48 03 85 10 fe ff



Or:

[ 393.912269] NMI backtrace for cpu 2
[ 393.912271] CPU: 2 PID: 2937 Comm: a.out Not tainted 4.10.0+ #229
[ 393.912274] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS Bochs 01/01/2011
[ 393.912276] task: ffff88006353c400 task.stack: ffff880066da0000
[ 393.912277] RIP: 0010:__lock_acquire+0xc9/0x3430
kernel/locking/lockdep.c:3204
[ 393.912279] RSP: 0018:ffff88006d106f68 EFLAGS: 00000086
[ 393.912282] RAX: ffffed000da20e03 RBX: 1ffff1000da20ea0 RCX: 0000000000000000
[ 393.912285] RDX: dffffc0000000000 RSI: 0000000000000000 RDI: ffff8800681416c8
[ 393.912287] RBP: ffff88006d1074a0 R08: 0000000000000001 R09: 0000000000000001
[ 393.912289] R10: ffff8800681416c8 R11: 0000000000000000 R12: ffff88006d107720
[ 393.912291] R13: ffff88006353c400 R14: 0000000000000000 R15: 0000000000000001
[ 393.912294] FS: 000000000082f880(0000) GS:ffff88006d100000(0000)
knlGS:0000000000000000
[ 393.912295] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 393.912298] CR2: 000000002001cfb0 CR3: 000000006ae13000 CR4: 00000000001406e0
[ 393.912299] Call Trace:
[ 393.912300] <IRQ>
[ 393.912336] lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3753
[ 393.912359] __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
[ 393.912359] _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
[ 393.912362] spin_lock include/linux/spinlock.h:299 [inline]
[ 393.912362] snd_timer_interrupt.part.12+0xaa0/0x1480 sound/core/timer.c:800
[ 393.912401] snd_timer_interrupt+0x88/0xb0 sound/core/timer.c:719
[ 393.912403] snd_hrtimer_callback+0x1f0/0x3c0 sound/core/hrtimer.c:64
[ 393.912404] __run_hrtimer kernel/time/hrtimer.c:1210 [inline]
[ 393.912404] __hrtimer_run_queues+0x349/0xe50 kernel/time/hrtimer.c:1274
[ 393.912422] hrtimer_interrupt+0x1c2/0x5e0 kernel/time/hrtimer.c:1308
[ 393.912424] local_apic_timer_interrupt+0x6f/0xe0
arch/x86/kernel/apic/apic.c:937
[ 393.912425] smp_apic_timer_interrupt+0x71/0xa0
arch/x86/kernel/apic/apic.c:961
[ 393.912427] apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:487
[ 393.912429] RIP: 0010:arch_local_irq_restore
arch/x86/include/asm/paravirt.h:778 [inline]
[ 393.912429] RIP: 0010:__raw_spin_unlock_irqrestore
include/linux/spinlock_api_smp.h:160 [inline]
[ 393.912429] RIP: 0010:_raw_spin_unlock_irqrestore+0x144/0x200
kernel/locking/spinlock.c:191
[ 393.912431] RSP: 0018:ffff880066da7568 EFLAGS: 00000286 ORIG_RAX:
ffffffffffffff10
[ 393.912436] RAX: 1ffffffff09d8eb9 RBX: 1ffff1000cdb4ead RCX: 0000000000000006
[ 393.912438] RDX: 1ffff1000cdb4ed1 RSI: ffff88006353cbe0 RDI: 0000000000000286
[ 393.912440] RBP: ffff880066da7728 R08: ffff88007fff709c R09: 0000000000000000
[ 393.912443] R10: 0000000000000006 R11: 0000000000000000 R12: dffffc0000000000
[ 393.912445] R13: 0000000000000286 R14: ffff8800681416b0 R15: 0000000000000000
[ 393.912446] </IRQ>
[ 393.912467] spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
[ 393.912467] snd_timer_start1+0x1e3/0x950 sound/core/timer.c:480
[ 393.912479] snd_timer_start+0x5d/0xa0 sound/core/timer.c:589
[ 393.912481] snd_timer_user_start.isra.7+0xde/0x130 sound/core/timer.c:1823
[ 393.912482] __snd_timer_user_ioctl sound/core/timer.c:1910 [inline]
[ 393.912482] snd_timer_user_ioctl+0x79d/0x34a0 sound/core/timer.c:1931
[ 393.912509] vfs_ioctl fs/ioctl.c:43 [inline]
[ 393.912509] do_vfs_ioctl+0x1bf/0x1790 fs/ioctl.c:683
[ 393.912524] SYSC_ioctl fs/ioctl.c:698 [inline]
[ 393.912524] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
[ 393.912525] entry_SYSCALL_64_fastpath+0x1f/0xc2
[ 393.912527] RIP: 0033:0x434d89
[ 393.912528] RSP: 002b:00007ffd0ad83a48 EFLAGS: 00000217 ORIG_RAX:
0000000000000010
[ 393.912532] RAX: ffffffffffffffda RBX: 0000000000401ae0 RCX: 0000000000434d89
[ 393.912534] RDX: 0000000000000000 RSI: 00000000000054a0 RDI: 0000000000000003
[ 393.912536] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[ 393.912538] R10: 0000000000000000 R11: 0000000000000217 R12: 00000000004002b0
[ 393.912540] R13: 0000000000401ae0 R14: 0000000000401b70 R15: 0000000000000000
[ 393.912542] Code: f2 c7 40 28 f2 f2 f2 f2 c7 40 2c 04 f2 f2 f2 c7
40 30 f2 f2 f2 f2 c7 40 34 00 f2 f2 f2 c7 40 38 f2 f2 f2 f2 c7 40 3c
00 f2 f2 f2 <c7> 40 40 f2 f2 f2 f2 c7 40 44 00 f2 f2 f2 c7 40 48 f2 f2
f2 f2


On commit e5d56efc97f8240d0b5d66c03949382b6d7e5570

[Takashi Iwai]

On Mon, 27 Feb 2017 21:46:48 +0100,
Dmitry Vyukov wrote:
>
> Hello,
>
> The following program locks up system:
> https://gist.githubusercontent.com/dvyukov/1b5cdca7f0fc6254afd4816901160e4c/raw/024c53be2112c83e5d64f3e4d5e8aa38ded727e3/gistfile1.txt

Thanks. It doesn't look like the hard lockup, but it keeps the IRQs
too busy, resulting in a quasi-lockup.

The problem is that the timer accepted the too low resolution. A
simple fix would be to give an error for a too short parameter.
The fix patch is attached below. Please give it a try.


thanks,

Takashi

-- 8< --
From: Takashi Iwai <ti...@suse.de>
Subject: [PATCH] ALSA: timer: Reject user params with too small ticks

When a user sets a too small ticks with a fine-grained timer like
hrtimer, the kernel tries to fire up the timer irq too frequently.
This may lead to the condensed locks, eventually the kernel spinlock
lockup with warnings.

For avoiding such a situation, we define a lower limit of the
resolution, namely 1ms. When the user passes a too small tick value
that results in less than that, the kernel returns -EINVAL now.

Reported-by: Dmitry Vyukov <dvy...@google.com>
Cc: <sta...@vger.kernel.org>
Signed-off-by: Takashi Iwai <ti...@suse.de>
---
sound/core/timer.c | 18 +++++++++++++++---
1 file changed, 15 insertions(+), 3 deletions(-)

diff --git a/sound/core/timer.c b/sound/core/timer.c
index fc144f43faa6..ad153149b231 100644
--- a/sound/core/timer.c
+++ b/sound/core/timer.c
@@ -1702,9 +1702,21 @@ static int snd_timer_user_params(struct file *file,
return -EBADFD;
if (copy_from_user(&params, _params, sizeof(params)))
return -EFAULT;
- if (!(t->hw.flags & SNDRV_TIMER_HW_SLAVE) && params.ticks < 1) {
- err = -EINVAL;
- goto _end;
+ if (!(t->hw.flags & SNDRV_TIMER_HW_SLAVE)) {
+ u64 resolution;
+
+ if (params.ticks < 1) {
+ err = -EINVAL;
+ goto _end;
+ }
+
+ /* Don't allow resolution less than 1ms */
+ resolution = snd_timer_resolution(tu->timeri);
+ resolution *= params.ticks;
+ if (resolution < 1000000) {
+ err = -EINVAL;
+ goto _end;
+ }
}
if (params.queue_size > 0 &&
(params.queue_size < 32 || params.queue_size > 1024)) {
--
2.11.1

[Dmitry Vyukov]

On Tue, Feb 28, 2017 at 2:58 PM, Takashi Iwai <ti...@suse.de> wrote:
> On Mon, 27 Feb 2017 21:46:48 +0100,
> Dmitry Vyukov wrote:
>>
>> Hello,
>>
>> The following program locks up system:
>> https://gist.githubusercontent.com/dvyukov/1b5cdca7f0fc6254afd4816901160e4c/raw/024c53be2112c83e5d64f3e4d5e8aa38ded727e3/gistfile1.txt
>
> Thanks. It doesn't look like the hard lockup, but it keeps the IRQs
> too busy, resulting in a quasi-lockup.
>
> The problem is that the timer accepted the too low resolution. A
> simple fix would be to give an error for a too short parameter.
> The fix patch is attached below. Please give it a try.

Pushed to our bots. Thanks.

> --
> You received this message because you are subscribed to the Google Groups "syzkaller" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller+...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.