sound: deadlock involving snd_hrtimer_callback

130 views
Skip to first unread message

Dmitry Vyukov

unread,
Apr 23, 2016, 9:40:41 AM4/23/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
Hi Takashi,

I've incorporated your hrtimer fixes (but also updated to
ddce192106e4f984123884f8e878f66ace94b573) and now I am seeing lots of
the following deadlock messages:


[ INFO: possible circular locking dependency detected ]
4.6.0-rc4+ #351 Not tainted
-------------------------------------------------------
swapper/0/0 is trying to acquire lock:
(&(&timer->lock)->rlock){-.-...}, at: [<ffffffff8537a749>]
snd_timer_interrupt+0xa9/0xd30 sound/core/timer.c:701

but task is already holding lock:
(&(&stime->lock)->rlock){-.....}, at: [<ffffffff85383d3f>]
snd_hrtimer_callback+0x4f/0x2b0 sound/core/hrtimer.c:54

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (&(&stime->lock)->rlock){-.....}:
[<ffffffff81477693>] lock_acquire+0x1e3/0x460
kernel/locking/lockdep.c:3677
[< inline >] __raw_spin_lock_irqsave
include/linux/spinlock_api_smp.h:112
[<ffffffff867c005f>] _raw_spin_lock_irqsave+0x9f/0xd0
kernel/locking/spinlock.c:159
[<ffffffff85383baa>] snd_hrtimer_start+0x4a/0xf0 sound/core/hrtimer.c:112
[<ffffffff85379c74>] snd_timer_start1+0x2b4/0x5a0 sound/core/timer.c:457
[<ffffffff8537d33d>] snd_timer_start+0x5d/0xa0 sound/core/timer.c:571
[< inline >] seq_timer_start sound/core/seq/seq_timer.c:393
[<ffffffff853fc260>] 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
[<ffffffff853f6f14>] snd_seq_control_queue+0x304/0x8b0
sound/core/seq/seq_queue.c:748
[<ffffffff853fcbb5>] event_input_timer+0x25/0x30
sound/core/seq/seq_system.c:118
[<ffffffff853ef7d4>]
snd_seq_deliver_single_event.constprop.11+0x3f4/0x740
sound/core/seq/seq_clientmgr.c:636
[<ffffffff853efc38>] snd_seq_deliver_event+0x118/0x800
sound/core/seq/seq_clientmgr.c:833
[<ffffffff853f1026>] snd_seq_kernel_client_dispatch+0x126/0x170
sound/core/seq/seq_clientmgr.c:2418
[<ffffffff85405c2b>] send_timer_event.isra.0+0x10b/0x150
sound/core/seq/oss/seq_oss_timer.c:153
[<ffffffff8540615a>] snd_seq_oss_timer_start+0x1ca/0x310
sound/core/seq/oss/seq_oss_timer.c:174
[< inline >] old_event sound/core/seq/oss/seq_oss_event.c:125
[<ffffffff854095ff>] snd_seq_oss_process_event+0xa1f/0x2ce0
sound/core/seq/oss/seq_oss_event.c:100
[< inline >] insert_queue sound/core/seq/oss/seq_oss_rw.c:179
[<ffffffff8540c201>] snd_seq_oss_write+0x321/0x810
sound/core/seq/oss/seq_oss_rw.c:148
[<ffffffff85403f99>] odev_write+0x59/0xa0
sound/core/seq/oss/seq_oss.c:177
[<ffffffff817f3fc3>] __vfs_write+0x113/0x4b0 fs/read_write.c:529
[<ffffffff817f5a97>] vfs_write+0x167/0x4a0 fs/read_write.c:578
[< inline >] SYSC_write fs/read_write.c:625
[<ffffffff817f98d1>] SyS_write+0x111/0x220 fs/read_write.c:617
[<ffffffff867c0440>] entry_SYSCALL_64_fastpath+0x23/0xc1
arch/x86/entry/entry_64.S:207

-> #0 (&(&timer->lock)->rlock){-.-...}:
[< inline >] check_prev_add kernel/locking/lockdep.c:1823
[< inline >] check_prevs_add kernel/locking/lockdep.c:1933
[< inline >] validate_chain kernel/locking/lockdep.c:2238
[<ffffffff81474035>] __lock_acquire+0x3625/0x4d00
kernel/locking/lockdep.c:3298
[<ffffffff81477693>] lock_acquire+0x1e3/0x460
kernel/locking/lockdep.c:3677
[< inline >] __raw_spin_lock_irqsave
include/linux/spinlock_api_smp.h:112
[<ffffffff867c005f>] _raw_spin_lock_irqsave+0x9f/0xd0
kernel/locking/spinlock.c:159
[<ffffffff8537a749>] snd_timer_interrupt+0xa9/0xd30
sound/core/timer.c:701
[<ffffffff85383e75>] snd_hrtimer_callback+0x185/0x2b0
sound/core/hrtimer.c:59
[< inline >] __run_hrtimer kernel/time/hrtimer.c:1242
[<ffffffff814d1071>] __hrtimer_run_queues+0x331/0xe90
kernel/time/hrtimer.c:1306
[<ffffffff814d3a42>] hrtimer_interrupt+0x182/0x430
kernel/time/hrtimer.c:1340
[<ffffffff8125aa52>] local_apic_timer_interrupt+0x72/0xe0
arch/x86/kernel/apic/apic.c:907
[<ffffffff867c2d59>] smp_apic_timer_interrupt+0x79/0xa0
arch/x86/kernel/apic/apic.c:931
[<ffffffff867c10ac>] apic_timer_interrupt+0x8c/0xa0
arch/x86/entry/entry_64.S:454
[< inline >] arch_safe_halt ./arch/x86/include/asm/paravirt.h:118
[<ffffffff8120f402>] default_idle+0x52/0x370
arch/x86/kernel/process.c:307
[<ffffffff81210bba>] arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:298
[<ffffffff81454c28>] default_idle_call+0x48/0xa0 kernel/sched/idle.c:93
[< inline >] cpuidle_idle_call kernel/sched/idle.c:151
[< inline >] cpu_idle_loop kernel/sched/idle.c:242
[<ffffffff8145520f>] cpu_startup_entry+0x58f/0x7b0
kernel/sched/idle.c:291
[<ffffffff8679ac6d>] rest_init+0x18d/0x1a0 init/main.c:408
[<ffffffff88ce7759>] start_kernel+0x63a/0x660 init/main.c:661
[<ffffffff88ce6364>] x86_64_start_reservations+0x38/0x3a
arch/x86/kernel/head64.c:195
[<ffffffff88ce64be>] x86_64_start_kernel+0x158/0x167
arch/x86/kernel/head64.c:176

other info that might help us debug this:

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&(&stime->lock)->rlock);
lock(&(&timer->lock)->rlock);
lock(&(&stime->lock)->rlock);
lock(&(&timer->lock)->rlock);

*** DEADLOCK ***

1 lock held by swapper/0/0:
#0: (&(&stime->lock)->rlock){-.....}, at: [<ffffffff85383d3f>]
snd_hrtimer_callback+0x4f/0x2b0 sound/core/hrtimer.c:54

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.6.0-rc4+ #351
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
ffffffff87eb25c0 ffff88003ec07a50 ffffffff82c8f92f ffffffff00000000
fffffbfff0fd64b8 ffffffff8997bad0 ffffffff8997bad0 ffffffff8998aa70
ffffffff87e27510 ffffffff87e26d00 ffff88003ec07aa0 ffffffff8146cf58
Call Trace:
<IRQ> [< inline >] __dump_stack lib/dump_stack.c:15
<IRQ> [<ffffffff82c8f92f>] dump_stack+0x12e/0x18f lib/dump_stack.c:51
[<ffffffff8146cf58>] print_circular_bug+0x288/0x340
kernel/locking/lockdep.c:1196
[< inline >] check_prev_add kernel/locking/lockdep.c:1823
[< inline >] check_prevs_add kernel/locking/lockdep.c:1933
[< inline >] validate_chain kernel/locking/lockdep.c:2238
[<ffffffff81474035>] __lock_acquire+0x3625/0x4d00 kernel/locking/lockdep.c:3298
[<ffffffff81477693>] lock_acquire+0x1e3/0x460 kernel/locking/lockdep.c:3677
[< inline >] __raw_spin_lock_irqsave
include/linux/spinlock_api_smp.h:112
[<ffffffff867c005f>] _raw_spin_lock_irqsave+0x9f/0xd0
kernel/locking/spinlock.c:159
[<ffffffff8537a749>] snd_timer_interrupt+0xa9/0xd30 sound/core/timer.c:701
[<ffffffff85383e75>] snd_hrtimer_callback+0x185/0x2b0 sound/core/hrtimer.c:59
[< inline >] __run_hrtimer kernel/time/hrtimer.c:1242
[<ffffffff814d1071>] __hrtimer_run_queues+0x331/0xe90
kernel/time/hrtimer.c:1306
[<ffffffff814d3a42>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1340
[<ffffffff8125aa52>] local_apic_timer_interrupt+0x72/0xe0
arch/x86/kernel/apic/apic.c:907
[<ffffffff867c2d59>] smp_apic_timer_interrupt+0x79/0xa0
arch/x86/kernel/apic/apic.c:931
[<ffffffff867c10ac>] apic_timer_interrupt+0x8c/0xa0
arch/x86/entry/entry_64.S:454
[< inline >] arch_safe_halt ./arch/x86/include/asm/paravirt.h:118
[<ffffffff8120f402>] default_idle+0x52/0x370 arch/x86/kernel/process.c:307
[<ffffffff81210bba>] arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:298
[<ffffffff81454c28>] default_idle_call+0x48/0xa0 kernel/sched/idle.c:93
[< inline >] cpuidle_idle_call kernel/sched/idle.c:151
[< inline >] cpu_idle_loop kernel/sched/idle.c:242
[<ffffffff8145520f>] cpu_startup_entry+0x58f/0x7b0 kernel/sched/idle.c:291
[<ffffffff8679ac6d>] rest_init+0x18d/0x1a0 init/main.c:408
[<ffffffff88ce7759>] start_kernel+0x63a/0x660 init/main.c:661
[<ffffffff88ce6364>] x86_64_start_reservations+0x38/0x3a
arch/x86/kernel/head64.c:195
[<ffffffff88ce64be>] x86_64_start_kernel+0x158/0x167
arch/x86/kernel/head64.c:176


They are also followed by rcu stalls and actual spinlock lockups:

BUG: spinlock lockup suspected on CPU#3, syz-fuzzer/7040
lock: 0xffff880032ae2bd8, .magic: dead4ead, .owner:
syz-executor/11206, .owner_cpu: 0
CPU: 3 PID: 7040 Comm: syz-fuzzer Not tainted 4.6.0-rc4+ #351
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
ffffffff87eb25c0 ffff88006d507c40 ffffffff82c8f92f ffffffff2c963698
fffffbfff0fd64b8 ffff880032ae2bd8 ffff88002c963040 ffff880061238040
ffff880032ae2be0 000000009a9d0630 ffff88006d507c78 ffffffff8147f58d
Call Trace:
<IRQ> [< inline >] __dump_stack lib/dump_stack.c:15
<IRQ> [<ffffffff82c8f92f>] dump_stack+0x12e/0x18f lib/dump_stack.c:51
[<ffffffff8147f58d>] spin_dump+0x14d/0x280 kernel/locking/spinlock_debug.c:67
[< inline >] __spin_lock_debug kernel/locking/spinlock_debug.c:117
[<ffffffff8147f8ad>] do_raw_spin_lock+0x15d/0x2b0
kernel/locking/spinlock_debug.c:137
[< inline >] __raw_spin_lock_irqsave
include/linux/spinlock_api_smp.h:119
[<ffffffff867c0067>] _raw_spin_lock_irqsave+0xa7/0xd0
kernel/locking/spinlock.c:159
[<ffffffff8537a749>] snd_timer_interrupt+0xa9/0xd30 sound/core/timer.c:701
[<ffffffff85383e75>] snd_hrtimer_callback+0x185/0x2b0 sound/core/hrtimer.c:59
[< inline >] __run_hrtimer kernel/time/hrtimer.c:1242
[<ffffffff814d1071>] __hrtimer_run_queues+0x331/0xe90
kernel/time/hrtimer.c:1306
[<ffffffff814d3a42>] hrtimer_interrupt+0x182/0x430 kernel/time/hrtimer.c:1340
[<ffffffff8125aa52>] local_apic_timer_interrupt+0x72/0xe0
arch/x86/kernel/apic/apic.c:907
[<ffffffff867c2d59>] smp_apic_timer_interrupt+0x79/0xa0
arch/x86/kernel/apic/apic.c:931
[<ffffffff867c10ac>] apic_timer_interrupt+0x8c/0xa0
arch/x86/entry/entry_64.S:454
<EOI>

Takashi Iwai

unread,
Apr 23, 2016, 5:02:19 PM4/23/16
to Dmitry Vyukov, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
On Sat, 23 Apr 2016 15:40:21 +0200,
Dmitry Vyukov wrote:
>
> Hi Takashi,
>
> I've incorporated your hrtimer fixes (but also updated to
> ddce192106e4f984123884f8e878f66ace94b573) and now I am seeing lots of
> the following deadlock messages:
>
>
> [ INFO: possible circular locking dependency detected ]
> 4.6.0-rc4+ #351 Not tainted
> -------------------------------------------------------
> swapper/0/0 is trying to acquire lock:
> (&(&timer->lock)->rlock){-.-...}, at: [<ffffffff8537a749>]
> snd_timer_interrupt+0xa9/0xd30 sound/core/timer.c:701
>
> but task is already holding lock:
> (&(&stime->lock)->rlock){-.....}, at: [<ffffffff85383d3f>]
> snd_hrtimer_callback+0x4f/0x2b0 sound/core/hrtimer.c:54
>
> which lock already depends on the new lock.

Oh crap, my second patch is buggy, it leads to ABBA lock, indeed.
The first patch is still OK, as it just adds a new behavior mode.

Could you replace the second patch with the below one?


thanks,

Takashi

-- 8< --
From: Takashi Iwai <ti...@suse.de>
Subject: [PATCH] ALSA: hrtimer: Use manual start/stop in callback (v2)

With the new SNDRV_TIMER_HW_RET_CTRL flag, hrtimer can manage the
callback behavior more correctly. Now it gets a return value from
snd_timer_interrupt() whether to reprogram or stop the timer, and it
can choose the right return value.

Thanks to this change, we can revert the long-standing hack to work
around the hrtimer_cancel() call at stopping. Since the stop is
called only explicitly outside the callback, hrtimer_cancel() can be
called safely now.

This fix essentially reverts the old commit [fcfdebe70759: ALSA:
hrtimer - Fix lock-up] while converting to use the new framework with
SNDRV_TIMER_HW_RET_CTRL.

Signed-off-by: Takashi Iwai <ti...@suse.de>
---
sound/core/hrtimer.c | 21 +++++++--------------
1 file changed, 7 insertions(+), 14 deletions(-)

diff --git a/sound/core/hrtimer.c b/sound/core/hrtimer.c
index 656d9a9032dc..27e2493c94e4 100644
--- a/sound/core/hrtimer.c
+++ b/sound/core/hrtimer.c
@@ -38,7 +38,6 @@ static unsigned int resolution;
struct snd_hrtimer {
struct snd_timer *timer;
struct hrtimer hrt;
- atomic_t running;
};

static enum hrtimer_restart snd_hrtimer_callback(struct hrtimer *hrt)
@@ -46,14 +45,11 @@ static enum hrtimer_restart snd_hrtimer_callback(struct hrtimer *hrt)
struct snd_hrtimer *stime = container_of(hrt, struct snd_hrtimer, hrt);
struct snd_timer *t = stime->timer;
unsigned long oruns;
-
- if (!atomic_read(&stime->running))
- return HRTIMER_NORESTART;
+ int ret;

oruns = hrtimer_forward_now(hrt, ns_to_ktime(t->sticks * resolution));
- snd_timer_interrupt(stime->timer, t->sticks * oruns);
-
- if (!atomic_read(&stime->running))
+ ret = snd_timer_interrupt(stime->timer, t->sticks * oruns);
+ if (ret == SNDRV_TIMER_RET_STOP)
return HRTIMER_NORESTART;
return HRTIMER_RESTART;
}
@@ -68,7 +64,6 @@ static int snd_hrtimer_open(struct snd_timer *t)
hrtimer_init(&stime->hrt, CLOCK_MONOTONIC, HRTIMER_MODE_REL);
stime->timer = t;
stime->hrt.function = snd_hrtimer_callback;
- atomic_set(&stime->running, 0);
t->private_data = stime;
return 0;
}
@@ -89,24 +84,22 @@ static int snd_hrtimer_start(struct snd_timer *t)
{
struct snd_hrtimer *stime = t->private_data;

- atomic_set(&stime->running, 0);
- hrtimer_try_to_cancel(&stime->hrt);
hrtimer_start(&stime->hrt, ns_to_ktime(t->sticks * resolution),
HRTIMER_MODE_REL);
- atomic_set(&stime->running, 1);
return 0;
}

static int snd_hrtimer_stop(struct snd_timer *t)
{
struct snd_hrtimer *stime = t->private_data;
- atomic_set(&stime->running, 0);
- hrtimer_try_to_cancel(&stime->hrt);
+
+ hrtimer_cancel(&stime->hrt);
return 0;
}

static struct snd_timer_hardware hrtimer_hw = {
- .flags = SNDRV_TIMER_HW_AUTO | SNDRV_TIMER_HW_TASKLET,
+ .flags = SNDRV_TIMER_HW_AUTO | SNDRV_TIMER_HW_TASKLET |
+ SNDRV_TIMER_HW_RET_CTRL,
.open = snd_hrtimer_open,
.close = snd_hrtimer_close,
.start = snd_hrtimer_start,
--
2.8.1

Dmitry Vyukov

unread,
Apr 24, 2016, 11:16:53 AM4/24/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
On Sat, Apr 23, 2016 at 11:02 PM, Takashi Iwai <ti...@suse.de> wrote:
> On Sat, 23 Apr 2016 15:40:21 +0200,
> Dmitry Vyukov wrote:
>>
>> Hi Takashi,
>>
>> I've incorporated your hrtimer fixes (but also updated to
>> ddce192106e4f984123884f8e878f66ace94b573) and now I am seeing lots of
>> the following deadlock messages:
>>
>>
>> [ INFO: possible circular locking dependency detected ]
>> 4.6.0-rc4+ #351 Not tainted
>> -------------------------------------------------------
>> swapper/0/0 is trying to acquire lock:
>> (&(&timer->lock)->rlock){-.-...}, at: [<ffffffff8537a749>]
>> snd_timer_interrupt+0xa9/0xd30 sound/core/timer.c:701
>>
>> but task is already holding lock:
>> (&(&stime->lock)->rlock){-.....}, at: [<ffffffff85383d3f>]
>> snd_hrtimer_callback+0x4f/0x2b0 sound/core/hrtimer.c:54
>>
>> which lock already depends on the new lock.
>
> Oh crap, my second patch is buggy, it leads to ABBA lock, indeed.
> The first patch is still OK, as it just adds a new behavior mode.
>
> Could you replace the second patch with the below one?


I've replaced the second path with this one. The deadlocks has gone,
but I've hit these two hangs that look related:

https://gist.githubusercontent.com/dvyukov/805718ea249c49d17ae759d1b0160684/raw/20891f7e87fe9af3967565559d465d296469244b/gistfile1.txt
https://gist.githubusercontent.com/dvyukov/7f397ea4aeb9e35596e0c8053cf35a11/raw/3fc22f24f7bab5941e47bab604f96487b5f1944d/gistfile1.txt

Dmitry Vyukov

unread,
Apr 24, 2016, 11:22:40 AM4/24/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
Another one:

[ 509.169244] BUG: spinlock lockup suspected on CPU#2, syz-executor/23652
[ 509.169244] lock: 0xffff880065662038, .magic: dead4ead, .owner:
syz-executor/23642, .owner_cpu: 0
[ 509.169244] CPU: 2 PID: 23652 Comm: syz-executor Not tainted 4.6.0-rc4+ #352
[ 509.169244] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS Bochs 01/01/2011
[ 509.169244] ffffffff87eb25c0 ffff88006d407c58 ffffffff82c8fe0f
ffffffff5f369e98
[ 509.169244] fffffbfff0fd64b8 ffff880065662038 ffff88005f369840
ffff88005e806040
[ 509.169244] ffff880065662040 000000009a9d0630 ffff88006d407c90
ffffffff8147f75d
[ 509.169244] Call Trace:
[ 509.169244] <IRQ> [<ffffffff82c8fe0f>] dump_stack+0x12e/0x18f
[ 509.169244] [<ffffffff8147f75d>] spin_dump+0x14d/0x280
[ 509.169244] [<ffffffff8537ad39>] ? snd_timer_interrupt+0xa9/0xd30
[ 509.169244] [<ffffffff8147fa7d>] do_raw_spin_lock+0x15d/0x2b0
[ 509.169244] [<ffffffff867c04e7>] _raw_spin_lock_irqsave+0xa7/0xd0
[ 509.169244] [<ffffffff8537ad39>] ? snd_timer_interrupt+0xa9/0xd30
[ 509.169244] [<ffffffff8537ad39>] snd_timer_interrupt+0xa9/0xd30
[ 509.169244] [<ffffffff8127c405>] ? kvm_clock_get_cycles+0x25/0x30
[ 509.169244] [<ffffffff814e53ba>] ? ktime_get+0x32a/0x550
[ 509.169244] [<ffffffff853842e7>] ? snd_hrtimer_callback+0xb7/0x180
[ 509.169244] [<ffffffff814cff2c>] ? hrtimer_forward+0x1cc/0x3e0
[ 509.169244] [<ffffffff85384338>] snd_hrtimer_callback+0x108/0x180
[ 509.169244] [<ffffffff814d1241>] __hrtimer_run_queues+0x331/0xe90
[ 509.169244] [<ffffffff85384230>] ? snd_hrtimer_close+0xa0/0xa0
[ 509.169244] [<ffffffff814d0f10>] ? enqueue_hrtimer+0x3d0/0x3d0
[ 509.169244] [<ffffffff814d3c12>] hrtimer_interrupt+0x182/0x430
[ 509.169244] [<ffffffff8125aa62>] local_apic_timer_interrupt+0x72/0xe0
[ 509.169244] [<ffffffff867c31d9>] smp_apic_timer_interrupt+0x79/0xa0
[ 509.169244] [<ffffffff867c152c>] apic_timer_interrupt+0x8c/0xa0
[ 509.169244] <EOI> [<ffffffff8171902e>] ? unmap_page_range+0x8be/0x19f0

Takashi Iwai

unread,
Apr 24, 2016, 12:16:14 PM4/24/16
to Dmitry Vyukov, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
Hmm, so it wasn't a good idea to call hrtimer_cancel() in the
spinlock, in anyway. Scratch the previous one.

OK, below is the yet revised two patches. One is the simplified
version of the patch, and another is to call hrtimer_cancel() in a new
timer op without spinlock. Apply these after the first patch
"ALSA: timer: Allow backend disabling start/stop from handler".


thanks,

Takashi

0001-ALSA-hrtimer-Use-manual-start-stop-in-callback-v3.patch
0002-ALSA-timer-Introduce-stop_sync-op.patch

Dmitry Vyukov

unread,
Apr 24, 2016, 1:10:08 PM4/24/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
Done. I will let you know if I see any failures.

Takashi Iwai

unread,
Apr 24, 2016, 5:31:29 PM4/24/16
to Dmitry Vyukov, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
On Sun, 24 Apr 2016 19:09:48 +0200,
After reconsideration, I rewrote the whole patchset again.
Could you scratch all the previous three patches and replace with the
single patch below? Sorry for inconvenience!


thanks,

Takashi

-- 8< --
From: Takashi Iwai <ti...@suse.de>
Subject: [PATCH] ALSA: hrtimer: Handle start/stop more properly

This patch tries to address the still remaining issues in ALSA hrtimer
driver:
- Spurious use-after-free was detected in hrtimer callback
- Incorrect rescheduling due to delayed start
- WARN_ON() is triggered in hrtimer_forward() invoked in hrtimer
callback

The first issue happens only when the new timer is scheduled even
while hrtimer is being closed. It's related with the second and third
items; since ALSA timer core invokes hw.start callback during hrtimer
interrupt, this may result in the explicit call of hrtimer_start().

Also, the similar problem is seen for the stop; ALSA timer core
invokes hw.stop callback even in the hrtimer handler, too. Since we
must not call the synced hrtimer_cancel() in such a context, it's just
a hrtimer_try_to_cancel() call that doesn't properly work.

Another culprit of the second and third items is the call of
hrtimer_forward_now() before snd_timer_interrupt(). The timer->stick
value may change during snd_timer_interrupt() call, but this
possibility is ignored completely.

For covering these subtle and messy issues, the following changes have
been done in this patch:
- A new flag, in_callback, is introduced in the private data to
indicate that the hrtimer handler is being processed.
- Both start and stop callbacks skip when called from (during)
in_callback flag.
- The hrtimer handler returns properly HRTIMER_RESTART and NORESTART
depending on the running state now.
- The hrtimer handler reprograms the expiry properly after
snd_timer_interrupt() call, instead of before.
- The close callback clears running flag and sets in_callback flag
to block any further start/stop calls.

Signed-off-by: Takashi Iwai <ti...@suse.de>
---
sound/core/hrtimer.c | 56 ++++++++++++++++++++++++++++++++++++----------------
1 file changed, 39 insertions(+), 17 deletions(-)

diff --git a/sound/core/hrtimer.c b/sound/core/hrtimer.c
index 656d9a9032dc..e2f27022b363 100644
--- a/sound/core/hrtimer.c
+++ b/sound/core/hrtimer.c
@@ -38,37 +38,53 @@ static unsigned int resolution;
struct snd_hrtimer {
struct snd_timer *timer;
struct hrtimer hrt;
- atomic_t running;
+ bool in_callback;
};

static enum hrtimer_restart snd_hrtimer_callback(struct hrtimer *hrt)
{
struct snd_hrtimer *stime = container_of(hrt, struct snd_hrtimer, hrt);
struct snd_timer *t = stime->timer;
- unsigned long oruns;
-
- if (!atomic_read(&stime->running))
- return HRTIMER_NORESTART;
-
- oruns = hrtimer_forward_now(hrt, ns_to_ktime(t->sticks * resolution));
- snd_timer_interrupt(stime->timer, t->sticks * oruns);
+ ktime_t delta;
+ unsigned long ticks;
+ enum hrtimer_restart ret = HRTIMER_NORESTART;
+
+ spin_lock(&t->lock);
+ if (!t->running)
+ goto out; /* fast path */
+ stime->in_callback = true;
+ ticks = t->sticks;
+ spin_unlock(&t->lock);
+
+ /* calculate the drift */
+ delta = ktime_sub(hrt->base->get_time(), hrtimer_get_expires(hrt));
+ if (delta.tv64 > 0)
+ ticks += ktime_divns(delta, ticks * resolution);
+
+ snd_timer_interrupt(stime->timer, ticks);
+
+ spin_lock(&t->lock);
+ if (t->running) {
+ hrtimer_add_expires_ns(hrt, t->sticks * resolution);
+ ret = HRTIMER_RESTART;
+ }

- if (!atomic_read(&stime->running))
- return HRTIMER_NORESTART;
- return HRTIMER_RESTART;
+ stime->in_callback = false;
+ out:
+ spin_unlock(&t->lock);
+ return ret;
}

static int snd_hrtimer_open(struct snd_timer *t)
{
struct snd_hrtimer *stime;

- stime = kmalloc(sizeof(*stime), GFP_KERNEL);
+ stime = kzalloc(sizeof(*stime), GFP_KERNEL);
if (!stime)
return -ENOMEM;
hrtimer_init(&stime->hrt, CLOCK_MONOTONIC, HRTIMER_MODE_REL);
stime->timer = t;
stime->hrt.function = snd_hrtimer_callback;
- atomic_set(&stime->running, 0);
t->private_data = stime;
return 0;
}
@@ -78,6 +94,11 @@ static int snd_hrtimer_close(struct snd_timer *t)
struct snd_hrtimer *stime = t->private_data;

if (stime) {
+ spin_lock_irq(&t->lock);
+ t->running = 0; /* just to be sure */
+ stime->in_callback = 1; /* skip start/stop */
+ spin_unlock_irq(&t->lock);
+
hrtimer_cancel(&stime->hrt);
kfree(stime);
t->private_data = NULL;
@@ -89,18 +110,19 @@ static int snd_hrtimer_start(struct snd_timer *t)
{
struct snd_hrtimer *stime = t->private_data;

- atomic_set(&stime->running, 0);
- hrtimer_try_to_cancel(&stime->hrt);
+ if (stime->in_callback)
+ return 0;
hrtimer_start(&stime->hrt, ns_to_ktime(t->sticks * resolution),
HRTIMER_MODE_REL);
- atomic_set(&stime->running, 1);
return 0;
}

static int snd_hrtimer_stop(struct snd_timer *t)
{
struct snd_hrtimer *stime = t->private_data;
- atomic_set(&stime->running, 0);
+
+ if (stime->in_callback)
+ return 0;
hrtimer_try_to_cancel(&stime->hrt);
return 0;
}
--
2.8.1

Dmitry Vyukov

unread,
Apr 25, 2016, 4:03:54 AM4/25/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller

Takashi Iwai

unread,
Apr 25, 2016, 4:34:07 AM4/25/16
to Dmitry Vyukov, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
On Mon, 25 Apr 2016 10:03:34 +0200,
The previous patches still use hrtimer_cancel() and this might causes
an issue like this. The latest revised one has no blocking behavior,
so hopefully we won't fall into that hole again.


thanks,

Takashi

Dmitry Vyukov

unread,
May 2, 2016, 7:54:58 AM5/2/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
Reapplied.
I will let you know if I see any crashes in sound.

Dmitry Vyukov

unread,
May 4, 2016, 4:34:54 AM5/4/16
to Takashi Iwai, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
No crashes over two nights. We can consider it as fixed.

Takashi Iwai

unread,
May 8, 2016, 5:17:01 AM5/8/16
to Dmitry Vyukov, Jaroslav Kysela, alsa-...@alsa-project.org, LKML, Alexander Potapenko, Kostya Serebryany, Sasha Levin, syzkaller
On Wed, 04 May 2016 10:34:33 +0200,
Good to hear. The patch will be included in 4.7.


thanks,

Takashi
Reply all
Reply to author
Forward
0 new messages