3.18.0-rc1 pulseaudio possible recursive locking

Discussion:

Arthur Marsh

2014-10-20 14:00:59 UTC

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.

Takashi Iwai

2014-10-21 05:27:34 UTC

Permalink

At Tue, 21 Oct 2014 00:30:59 +1030,

Post by 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?

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

Takashi

Post by Arthur Marsh
[ 182.273991] =============================================
[ 182.273996] [ INFO: possible recursive locking detected ]
[ 182.274003] 3.18.0-rc1 #1297 Not tainted
[ 182.274008] ---------------------------------------------
[<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[ 182.274063]
[<f8432284>] snd_pcm_action_group+0x96/0x215 [snd_pcm]
[ 182.274092]
[ 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.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]
[<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]
[ 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.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
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Takashi Iwai

2014-10-21 13:38:42 UTC

Permalink

At Tue, 21 Oct 2014 07:27:34 +0200,

Post by Takashi Iwai
At Tue, 21 Oct 2014 00:30:59 +1030,

Post by 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?

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 <***@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 <***@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

Arthur Marsh

2014-10-21 16:08:55 UTC

Permalink

Post by Takashi Iwai
At Tue, 21 Oct 2014 07:27:34 +0200,

Post by Takashi Iwai
At Tue, 21 Oct 2014 00:30:59 +1030,

Post by 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?

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< --
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.
---
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.