[alsa-devel] ALSA:aloop -- inconsistent {in-softirq-W} -> {softirq-on-W} usage

[Takashi Iwai]

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