At Thu, 13 Dec 2012 21:36:05 +0100, Andreas Fenkart wrote:

Hi,

Seen this error when stopping playback to loopback.

# aplay -Dhw:0 -fcd /dev/urandom Playing raw data '/dev/urandom' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo ^CAborted by signa[ 65.562992] [ 65.565493] ================================= [ 65.570044] [ INFO: inconsistent lock state ] [ 65.574601] 3.7.0-rc8+ #303 Not tainted [ 65.578605] --------------------------------- [ 65.583156] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. [ 65.589436] aplay/156 [HC0[0]:SC0[0]:HE1:SE1] takes: [ 65.594620] (&(&dpcm->timer_lock)->rlock){+.?...}, at: [<c02e90cd>] loopback_close+0x29/0x98 [ 65.603604] {IN-SOFTIRQ-W} state was registered at: [ 65.608699] [<c005d8ef>] mark_irqflags+0xa3/0x11c [ 65.613820] [<c005dca1>] __lock_acquire+0x339/0x77c [ 65.619112] [<c005e575>] lock_acquire+0x65/0xac [ 65.624038] [<c03e0c17>] _raw_spin_lock+0x1f/0x2c [ 65.629155] [<c02e8cdd>] loopback_timer_start+0x3d/0x108 [ 65.634899] [<c02e9455>] loopback_timer_function+0x21/0x3c [ 65.640821] [<c0035f3f>] call_timer_fn+0x63/0xfc [ 65.645849] [<c0036127>] run_timer_softirq+0x14f/0x190 [ 65.651410] [<c00311d1>] __do_softirq+0xb1/0x174 [ 65.656426] [<c0031529>] irq_exit+0x6d/0x70 [ 65.660989] [<c000dde9>] handle_IRQ+0x2d/0x60 [ 65.665743] [<c000848d>] omap3_intc_handle_irq+0x59/0x60 [ 65.671484] [<c000cfff>] __irq_svc+0x3f/0x64 [ 65.676138] [<c000de86>] default_idle+0x22/0x24 [ 65.681063] [<c000df89>] cpu_idle+0x89/0x94 [ 65.685626] [<c05cf5bb>] start_kernel+0x25b/0x264 [ 65.690743] irq event stamp: 74155 [ 65.694296] hardirqs last enabled at (74155): [<c03df9b5>] __mutex_unlock_slowpath+0x85/0xec [ 65.703215] hardirqs last disabled at (74154): [<c03df96b>] __mutex_unlock_slowpath+0x3b/0xec [ 65.712132] softirqs last enabled at (72724): [<c0031215>] __do_softirq+0xf5/0x174 [ 65.720141] softirqs last disabled at (72717): [<c0031529>] irq_exit+0x6d/0x70 [ 65.727697] [ 65.727697] other info that might help us debug this: [ 65.734516] Possible unsafe locking scenario: [ 65.734516] [ 65.740697] CPU0 [ 65.743250] ---- [ 65.745802] lock(&(&dpcm->timer_lock)->rlock); [ 65.750639] <Interrupt> [ 65.753373] lock(&(&dpcm->timer_lock)->rlock); [ 65.758392] [ 65.758392] *** DEADLOCK *** [ 65.758392] [ 65.764581] 1 lock held by aplay/156: [ 65.768404] #0: (&pcm->open_mutex){+.+.+.}, at: [<c02e0c49>] snd_pcm_release+0x1d/0x7c [ 65.776907] [ 65.776907] stack backtrace: [ 65.781487] [<c0011a15>] (unwind_backtrace+0x1/0xa0) from [<c005d2c9>] (print_usage_bug+0x149/0x184) [ 65.791039] [<c005d2c9>] (print_usage_bug+0x149/0x184) from [<c005d4c5>] (mark_lock_irq+0x1c1/0x1e0) [ 65.800590] [<c005d4c5>] (mark_lock_irq+0x1c1/0x1e0) from [<c005d5f7>] (mark_lock+0x113/0x368) [ 65.809597] [<c005d5f7>] (mark_lock+0x113/0x368) from [<c005d915>] (mark_irqflags+0xc9/0x11c) [ 65.818514] [<c005d915>] (mark_irqflags+0xc9/0x11c) from [<c005dca1>] (__lock_acquire+0x339/0x77c) [ 65.827884] [<c005dca1>] (__lock_acquire+0x339/0x77c) from [<c005e575>] (lock_acquire+0x65/0xac) [ 65.846083] [<c03e0c17>] (_raw_spin_lock+0x1f/0x2c) from [<c02e90cd>] (loopback_close+0x29/0x98) [ 65.855273] [<c02e90cd>] (loopback_close+0x29/0x98) from [<c02e0bf1>] (snd_pcm_release_substream+0x39/0x74) [ 65.865458] [<c02e0bf1>] (snd_pcm_release_substream+0x39/0x74) from [<c02e0c4f>] (snd_pcm_release+0x23/0x7c) [ 65.875748] [<c02e0c4f>] (snd_pcm_release+0x23/0x7c) from [<c00b4dad>] (__fput+0x61/0x170) [ 65.884409] [<c00b4dad>] (__fput+0x61/0x170) from [<c0040485>] (task_work_run+0x5d/0x8c) [ 65.892879] [<c0040485>] (task_work_run+0x5d/0x8c) from [<c001017f>] (do_work_pending+0x67/0x7c) [ 65.902069] [<c001017f>] (do_work_pending+0x67/0x7c) from [<c000d569>] (work_pending+0x9/0x18)

This seems to be a real deadlock, since loopback_timer_stop is triggered from ioctl, while loopback_timer_start can be called from softirq.

Could you check the latest Linus tree? The spinlocks of aloop have been already fixed there.

Takashi