3.18.0-rc1 pulseaudio possible recursive locking

3.18.0-rc1 pulseaudio possible recursive locking

[Arthur Marsh]

Hi, I have been seeing this a few times lately, and noticed that it was 
still present

Is this the right place to report it or should I be reporting a bug 
against pulseaudio?


[  182.273991] =============================================
[  182.273996] [ INFO: possible recursive locking detected ]
[  182.274003] 3.18.0-rc1 #1297 Not tainted
[  182.274008] ---------------------------------------------
[  182.274013] pulseaudio/5183 is trying to acquire lock:
[  182.274018]  (&(&substream->self_group.lock)->rlock/1){......}, at: 
[<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274063]
but task is already holding lock:
[  182.274069]  (&(&substream->self_group.lock)->rlock/1){......}, at: 
[<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274092]
other info that might help us debug this:
[  182.274098]  Possible unsafe locking scenario:

[  182.274104]        CPU0
[  182.274108]        ----
[  182.274112]   lock(&(&substream->self_group.lock)->rlock/1);
[  182.274122]   lock(&(&substream->self_group.lock)->rlock/1);
[  182.274132]
  *** DEADLOCK ***

[  182.274138]  May be due to missing lock nesting notation

[  182.274146] 4 locks held by pulseaudio/5183:
[  182.274151]  #0:  (snd_pcm_link_rwlock){......}, at: [<f8432fe3>] 
snd_pcm_stream_lock+0x1b/0x43 [snd_pcm]
[  182.274177]  #1:  (&(&substream->self_group.lock)->rlock){......}, 
at: [<f8432fee>] snd_pcm_stream_lock+0x26/0x43 [snd_pcm]
[  182.274202]  #2:  (&(&substream->group->lock)->rlock){......}, at: 
[<f8432cf4>] snd_pcm_action+0x34/0x10b [snd_pcm]
[  182.274227]  #3:  (&(&substream->self_group.lock)->rlock/1){......}, 
at: [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274254]
stack backtrace:
[  182.274263] CPU: 1 PID: 5183 Comm: pulseaudio Not tainted 3.18.0-rc1 
#1297
[  182.274269] Hardware name: System Manufacturer System Name/P4S800, 
BIOS ASUS P4S800 ACPI BIOS Revision 1011 Beta 001 08/30/2005
[  182.274275]  c1bfc4e0 00000000 e55c9d50 c145d969 c1bfc4e0 e55c9dd4 
c1082b7b c15b7f9a
[  182.274295]  e55b630c 0000143f 00000000 e55b6010 e55b6070 00000000 
5402a095 00000004
[  182.274315]  c17a4034 c1bfc4e0 e55b6508 e55b6520 00000000 00000008 
00000000 e55b6508
[  182.274335] Call Trace:
[  182.274353]  [<c145d969>] dump_stack+0x4b/0x75
[  182.274366]  [<c1082b7b>] __lock_acquire+0x187c/0x19b3
[  182.274378]  [<c10834ad>] lock_acquire+0xa1/0x126
[  182.274394]  [<f8432284>] ? snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274404]  [<c1463a9d>] _raw_spin_lock_nested+0x41/0x4e
[  182.274420]  [<f8432284>] ? snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274436]  [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[  182.274445]  [<c146393b>] ? _raw_spin_trylock+0x6b/0x80
[  182.274462]  [<f8432d0f>] snd_pcm_action+0x4f/0x10b [snd_pcm]
[  182.274479]  [<f843332a>] snd_pcm_drop+0x4a/0x7d [snd_pcm]
[  182.274496]  [<f84351d9>] snd_pcm_common_ioctl1+0x7b0/0xcc4 [snd_pcm]
[  182.274514]  [<f84357ce>] snd_pcm_playback_ioctl1+0xe1/0x3a8 [snd_pcm]
[  182.274532]  [<f8435ab7>] snd_pcm_playback_ioctl+0x22/0x35 [snd_pcm]
[  182.274549]  [<f8435a95>] ? snd_pcm_playback_ioctl1+0x3a8/0x3a8 [snd_pcm]
[  182.274561]  [<c1171e82>] do_vfs_ioctl+0x306/0x576
[  182.274573]  [<c117d3ca>] ? mntput_no_expire+0x61/0x1e7
[  182.274583]  [<c117d377>] ? mntput_no_expire+0xe/0x1e7
[  182.274594]  [<c117d56b>] ? mntput+0x1b/0x29
[  182.274603]  [<c1161438>] ? __fput+0x144/0x1aa
[  182.274614]  [<c1172147>] SyS_ioctl+0x55/0x75
[  182.274624]  [<c14646e0>] sysenter_do_call+0x12/0x12

Regards,

Arthur.

Re: 3.18.0-rc1 pulseaudio possible recursive locking

[Takashi Iwai]

At Tue, 21 Oct 2014 00:30:59 +1030,
Arthur Marsh wrote:
> 
> Hi, I have been seeing this a few times lately, and noticed that it was 
> still present
> 
> Is this the right place to report it or should I be reporting a bug 
> against pulseaudio?

This is likely a false-positive report, so ignore it unless you really
encounter the deadlock by this.


Takashi

> 
> 
> [  182.273991] =============================================
> [  182.273996] [ INFO: possible recursive locking detected ]
> [  182.274003] 3.18.0-rc1 #1297 Not tainted
> [  182.274008] ---------------------------------------------
> [  182.274013] pulseaudio/5183 is trying to acquire lock:
> [  182.274018]  (&(&substream->self_group.lock)->rlock/1){......}, at: 
> [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274063]
> but task is already holding lock:
> [  182.274069]  (&(&substream->self_group.lock)->rlock/1){......}, at: 
> [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274092]
> other info that might help us debug this:
> [  182.274098]  Possible unsafe locking scenario:
> 
> [  182.274104]        CPU0
> [  182.274108]        ----
> [  182.274112]   lock(&(&substream->self_group.lock)->rlock/1);
> [  182.274122]   lock(&(&substream->self_group.lock)->rlock/1);
> [  182.274132]
>   *** DEADLOCK ***
> 
> [  182.274138]  May be due to missing lock nesting notation
> 
> [  182.274146] 4 locks held by pulseaudio/5183:
> [  182.274151]  #0:  (snd_pcm_link_rwlock){......}, at: [<f8432fe3>] 
> snd_pcm_stream_lock+0x1b/0x43 [snd_pcm]
> [  182.274177]  #1:  (&(&substream->self_group.lock)->rlock){......}, 
> at: [<f8432fee>] snd_pcm_stream_lock+0x26/0x43 [snd_pcm]
> [  182.274202]  #2:  (&(&substream->group->lock)->rlock){......}, at: 
> [<f8432cf4>] snd_pcm_action+0x34/0x10b [snd_pcm]
> [  182.274227]  #3:  (&(&substream->self_group.lock)->rlock/1){......}, 
> at: [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274254]
> stack backtrace:
> [  182.274263] CPU: 1 PID: 5183 Comm: pulseaudio Not tainted 3.18.0-rc1 
> #1297
> [  182.274269] Hardware name: System Manufacturer System Name/P4S800, 
> BIOS ASUS P4S800 ACPI BIOS Revision 1011 Beta 001 08/30/2005
> [  182.274275]  c1bfc4e0 00000000 e55c9d50 c145d969 c1bfc4e0 e55c9dd4 
> c1082b7b c15b7f9a
> [  182.274295]  e55b630c 0000143f 00000000 e55b6010 e55b6070 00000000 
> 5402a095 00000004
> [  182.274315]  c17a4034 c1bfc4e0 e55b6508 e55b6520 00000000 00000008 
> 00000000 e55b6508
> [  182.274335] Call Trace:
> [  182.274353]  [<c145d969>] dump_stack+0x4b/0x75
> [  182.274366]  [<c1082b7b>] __lock_acquire+0x187c/0x19b3
> [  182.274378]  [<c10834ad>] lock_acquire+0xa1/0x126
> [  182.274394]  [<f8432284>] ? snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274404]  [<c1463a9d>] _raw_spin_lock_nested+0x41/0x4e
> [  182.274420]  [<f8432284>] ? snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274436]  [<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
> [  182.274445]  [<c146393b>] ? _raw_spin_trylock+0x6b/0x80
> [  182.274462]  [<f8432d0f>] snd_pcm_action+0x4f/0x10b [snd_pcm]
> [  182.274479]  [<f843332a>] snd_pcm_drop+0x4a/0x7d [snd_pcm]
> [  182.274496]  [<f84351d9>] snd_pcm_common_ioctl1+0x7b0/0xcc4 [snd_pcm]
> [  182.274514]  [<f84357ce>] snd_pcm_playback_ioctl1+0xe1/0x3a8 [snd_pcm]
> [  182.274532]  [<f8435ab7>] snd_pcm_playback_ioctl+0x22/0x35 [snd_pcm]
> [  182.274549]  [<f8435a95>] ? snd_pcm_playback_ioctl1+0x3a8/0x3a8 [snd_pcm]
> [  182.274561]  [<c1171e82>] do_vfs_ioctl+0x306/0x576
> [  182.274573]  [<c117d3ca>] ? mntput_no_expire+0x61/0x1e7
> [  182.274583]  [<c117d377>] ? mntput_no_expire+0xe/0x1e7
> [  182.274594]  [<c117d56b>] ? mntput+0x1b/0x29
> [  182.274603]  [<c1161438>] ? __fput+0x144/0x1aa
> [  182.274614]  [<c1172147>] SyS_ioctl+0x55/0x75
> [  182.274624]  [<c14646e0>] sysenter_do_call+0x12/0x12
> 
> Regards,
> 
> Arthur.
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
> 

Re: 3.18.0-rc1 pulseaudio possible recursive locking

[Takashi Iwai]

At Tue, 21 Oct 2014 07:27:34 +0200,
Takashi Iwai wrote:
> 
> At Tue, 21 Oct 2014 00:30:59 +1030,
> Arthur Marsh wrote:
> > 
> > Hi, I have been seeing this a few times lately, and noticed that it was 
> > still present
> > 
> > Is this the right place to report it or should I be reporting a bug 
> > against pulseaudio?
> 
> This is likely a false-positive report, so ignore it unless you really
> encounter the deadlock by this.

Or try the patch below.  This seems hitting more often, so it's maybe
worth to put into 3.18-rc2.  Let me know if this solves the problem.


Takashi

-- 8< --
From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH] ALSA: pcm: Fix false lockdep warnings

As PCM core handles the multiple linked streams in parallel, lockdep
gets confused (partly because of weak annotations) and spews the
false-positive warnings.  This hasn't been a problem for long time but
the latest PCM lock path update seems to have woken up a sleeping
dog.

Here is an attempt to paper over this issue: pass the lock subclass
just calculated from the depth in snd_pcm_action_group().  Also, a
(possibly) wrong lock subclass set in snd_pcm_action_lock_mutex() is
dropped, too.

Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
 sound/core/pcm_native.c | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c
index 815396d8427f..166d59cdc86b 100644
--- a/sound/core/pcm_native.c
+++ b/sound/core/pcm_native.c
@@ -781,16 +781,15 @@ static int snd_pcm_action_group(struct action_ops *ops,
 {
 	struct snd_pcm_substream *s = NULL;
 	struct snd_pcm_substream *s1;
-	int res = 0;
+	int res = 0, depth = 1;
 
 	snd_pcm_group_for_each_entry(s, substream) {
 		if (do_lock && s != substream) {
 			if (s->pcm->nonatomic)
-				mutex_lock_nested(&s->self_group.mutex,
-						  SINGLE_DEPTH_NESTING);
+				mutex_lock_nested(&s->self_group.mutex, depth);
 			else
-				spin_lock_nested(&s->self_group.lock,
-						 SINGLE_DEPTH_NESTING);
+				spin_lock_nested(&s->self_group.lock, depth);
+			depth++;
 		}
 		res = ops->pre_action(s, state);
 		if (res < 0)
@@ -906,8 +905,7 @@ static int snd_pcm_action_lock_mutex(struct action_ops *ops,
 	down_read(&snd_pcm_link_rwsem);
 	if (snd_pcm_stream_linked(substream)) {
 		mutex_lock(&substream->group->mutex);
-		mutex_lock_nested(&substream->self_group.mutex,
-				  SINGLE_DEPTH_NESTING);
+		mutex_lock(&substream->self_group.mutex);
 		res = snd_pcm_action_group(ops, substream, state, 1);
 		mutex_unlock(&substream->self_group.mutex);
 		mutex_unlock(&substream->group->mutex);
-- 
2.1.2

Re: 3.18.0-rc1 pulseaudio possible recursive locking

[Arthur Marsh]

Takashi Iwai wrote, on 22/10/14 00:08:
> At Tue, 21 Oct 2014 07:27:34 +0200,
> Takashi Iwai wrote:
>>
>> At Tue, 21 Oct 2014 00:30:59 +1030,
>> Arthur Marsh wrote:
>>>
>>> Hi, I have been seeing this a few times lately, and noticed that it was
>>> still present
>>>
>>> Is this the right place to report it or should I be reporting a bug
>>> against pulseaudio?
>>
>> This is likely a false-positive report, so ignore it unless you really
>> encounter the deadlock by this.
>
> Or try the patch below.  This seems hitting more often, so it's maybe
> worth to put into 3.18-rc2.  Let me know if this solves the problem.
>
>
> Takashi
>
> -- 8< --
> From: Takashi Iwai <tiwai@suse.de>
> Subject: [PATCH] ALSA: pcm: Fix false lockdep warnings
>
> As PCM core handles the multiple linked streams in parallel, lockdep
> gets confused (partly because of weak annotations) and spews the
> false-positive warnings.  This hasn't been a problem for long time but
> the latest PCM lock path update seems to have woken up a sleeping
> dog.
>
> Here is an attempt to paper over this issue: pass the lock subclass
> just calculated from the depth in snd_pcm_action_group().  Also, a
> (possibly) wrong lock subclass set in snd_pcm_action_lock_mutex() is
> dropped, too.
>
> Signed-off-by: Takashi Iwai <tiwai@suse.de>
> ---
>   sound/core/pcm_native.c | 12 +++++-------
>   1 file changed, 5 insertions(+), 7 deletions(-)
>
> diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c
> index 815396d8427f..166d59cdc86b 100644
> --- a/sound/core/pcm_native.c
> +++ b/sound/core/pcm_native.c
> @@ -781,16 +781,15 @@ static int snd_pcm_action_group(struct action_ops *ops,
>   {
>   	struct snd_pcm_substream *s = NULL;
>   	struct snd_pcm_substream *s1;
> -	int res = 0;
> +	int res = 0, depth = 1;
>
>   	snd_pcm_group_for_each_entry(s, substream) {
>   		if (do_lock && s != substream) {
>   			if (s->pcm->nonatomic)
> -				mutex_lock_nested(&s->self_group.mutex,
> -						  SINGLE_DEPTH_NESTING);
> +				mutex_lock_nested(&s->self_group.mutex, depth);
>   			else
> -				spin_lock_nested(&s->self_group.lock,
> -						 SINGLE_DEPTH_NESTING);
> +				spin_lock_nested(&s->self_group.lock, depth);
> +			depth++;
>   		}
>   		res = ops->pre_action(s, state);
>   		if (res < 0)
> @@ -906,8 +905,7 @@ static int snd_pcm_action_lock_mutex(struct action_ops *ops,
>   	down_read(&snd_pcm_link_rwsem);
>   	if (snd_pcm_stream_linked(substream)) {
>   		mutex_lock(&substream->group->mutex);
> -		mutex_lock_nested(&substream->self_group.mutex,
> -				  SINGLE_DEPTH_NESTING);
> +		mutex_lock(&substream->self_group.mutex);
>   		res = snd_pcm_action_group(ops, substream, state, 1);
>   		mutex_unlock(&substream->self_group.mutex);
>   		mutex_unlock(&substream->group->mutex);
>

Hi, I applied this patch, rebuilt the kernel and am running it now and 
have not seen the "pulseaudio possible recursive locking" message yet.

For the previous 4 reboots with earlier kernels 3.17.0+ / 3.18.0-rc1 I 
saw the "pulseaudio possible recursive locking" message appear about 5 
minutes after boot-up.

Thanks for your help!

Arthur.