snd_pcm lockdep report from 3.3-rc6

snd_pcm lockdep report from 3.3-rc6

[Dave Jones]

I just hit this..


[ INFO: possible recursive locking detected ]
3.3.0-rc6+ #5 Not tainted
---------------------------------------------
pulseaudio/1306 is trying to acquire lock:
 (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]

but task is already holding lock:
 (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&(&substream->self_group.lock)->rlock/1);
  lock(&(&substream->self_group.lock)->rlock/1);

 *** DEADLOCK ***

 May be due to missing lock nesting notation

4 locks held by pulseaudio/1306:
 #0:  (snd_pcm_link_rwlock){......}, at: [<ffffffffa046ab90>] snd_pcm_drop+0x60/0x100 [snd_pcm]
 #1:  (&(&substream->self_group.lock)->rlock){......}, at: [<ffffffffa046ab98>] snd_pcm_drop+0x68/0x100 [snd_pcm]
 #2:  (&(&substream->group->lock)->rlock){......}, at: [<ffffffffa0469ffe>] snd_pcm_action+0x3e/0xb0 [snd_pcm]
 #3:  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]

stack backtrace:
Pid: 1306, comm: pulseaudio Not tainted 3.3.0-rc6+ #5
Call Trace:
 [<ffffffff810cee87>] __lock_acquire+0xe47/0x1bb0
 [<ffffffff810a62b8>] ? sched_clock_cpu+0xb8/0x130
 [<ffffffff810d030d>] lock_acquire+0x9d/0x220
 [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 [<ffffffff810ca91e>] ? put_lock_stats+0xe/0x40
 [<ffffffff8169d3cd>] _raw_spin_lock_nested+0x4d/0x90
 [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 [<ffffffffa046a031>] snd_pcm_action+0x71/0xb0 [snd_pcm]
 [<ffffffffa046a08a>] snd_pcm_stop+0x1a/0x20 [snd_pcm]
 [<ffffffffa046abb1>] snd_pcm_drop+0x81/0x100 [snd_pcm]
 [<ffffffffa046cdf8>] snd_pcm_common_ioctl1+0x678/0xc00 [snd_pcm]
 [<ffffffffa046d7d7>] snd_pcm_playback_ioctl1+0x147/0x2e0 [snd_pcm]
 [<ffffffff812c1cbc>] ? file_has_perm+0xdc/0xf0
 [<ffffffffa046d9a4>] snd_pcm_playback_ioctl+0x34/0x40 [snd_pcm]
 [<ffffffff811d2398>] do_vfs_ioctl+0x98/0x570
 [<ffffffff811d2901>] sys_ioctl+0x91/0xa0
 [<ffffffff816a5de9>] system_call_fastpath+0x16/0x1b


I suspect this ..

static int snd_pcm_action(struct action_ops *ops,
                          struct snd_pcm_substream *substream,
                          int state)
{
        int res;

        if (snd_pcm_stream_linked(substream)) {
-->             if (!spin_trylock(&substream->group->lock)) {
                        spin_unlock(&substream->self_group.lock);
                        spin_lock(&substream->group->lock);
                        spin_lock(&substream->self_group.lock);
                }
                res = snd_pcm_action_group(ops, substream, state, 1);
                spin_unlock(&substream->group->lock);
        } else {
                res = snd_pcm_action_single(ops, substream, state);
        }
        return res;
}

Should that trylock be on self_group.lock ?

	Dave

Re: snd_pcm lockdep report from 3.3-rc6

[Takashi Iwai]

Hi Dave,

At Mon, 12 Mar 2012 10:35:15 -0400,
Dave Jones wrote:
> 
> I just hit this..
> 
> 
> [ INFO: possible recursive locking detected ]
> 3.3.0-rc6+ #5 Not tainted
> ---------------------------------------------
> pulseaudio/1306 is trying to acquire lock:
>  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> but task is already holding lock:
>  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> other info that might help us debug this:
>  Possible unsafe locking scenario:
> 
>        CPU0
>        ----
>   lock(&(&substream->self_group.lock)->rlock/1);
>   lock(&(&substream->self_group.lock)->rlock/1);
> 
>  *** DEADLOCK ***
> 
>  May be due to missing lock nesting notation
> 
> 4 locks held by pulseaudio/1306:
>  #0:  (snd_pcm_link_rwlock){......}, at: [<ffffffffa046ab90>] snd_pcm_drop+0x60/0x100 [snd_pcm]
>  #1:  (&(&substream->self_group.lock)->rlock){......}, at: [<ffffffffa046ab98>] snd_pcm_drop+0x68/0x100 [snd_pcm]
>  #2:  (&(&substream->group->lock)->rlock){......}, at: [<ffffffffa0469ffe>] snd_pcm_action+0x3e/0xb0 [snd_pcm]
>  #3:  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> stack backtrace:
> Pid: 1306, comm: pulseaudio Not tainted 3.3.0-rc6+ #5
> Call Trace:
>  [<ffffffff810cee87>] __lock_acquire+0xe47/0x1bb0
>  [<ffffffff810a62b8>] ? sched_clock_cpu+0xb8/0x130
>  [<ffffffff810d030d>] lock_acquire+0x9d/0x220
>  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffff810ca91e>] ? put_lock_stats+0xe/0x40
>  [<ffffffff8169d3cd>] _raw_spin_lock_nested+0x4d/0x90
>  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffffa046a031>] snd_pcm_action+0x71/0xb0 [snd_pcm]
>  [<ffffffffa046a08a>] snd_pcm_stop+0x1a/0x20 [snd_pcm]
>  [<ffffffffa046abb1>] snd_pcm_drop+0x81/0x100 [snd_pcm]
>  [<ffffffffa046cdf8>] snd_pcm_common_ioctl1+0x678/0xc00 [snd_pcm]
>  [<ffffffffa046d7d7>] snd_pcm_playback_ioctl1+0x147/0x2e0 [snd_pcm]
>  [<ffffffff812c1cbc>] ? file_has_perm+0xdc/0xf0
>  [<ffffffffa046d9a4>] snd_pcm_playback_ioctl+0x34/0x40 [snd_pcm]
>  [<ffffffff811d2398>] do_vfs_ioctl+0x98/0x570
>  [<ffffffff811d2901>] sys_ioctl+0x91/0xa0
>  [<ffffffff816a5de9>] system_call_fastpath+0x16/0x1b
> 
> 
> I suspect this ..
> 
> static int snd_pcm_action(struct action_ops *ops,
>                           struct snd_pcm_substream *substream,
>                           int state)
> {
>         int res;
> 
>         if (snd_pcm_stream_linked(substream)) {
> -->             if (!spin_trylock(&substream->group->lock)) {
>                         spin_unlock(&substream->self_group.lock);
>                         spin_lock(&substream->group->lock);
>                         spin_lock(&substream->self_group.lock);
>                 }
>                 res = snd_pcm_action_group(ops, substream, state, 1);
>                 spin_unlock(&substream->group->lock);
>         } else {
>                 res = snd_pcm_action_single(ops, substream, state);
>         }
>         return res;
> }
> 
> Should that trylock be on self_group.lock ?

No, the check above should be correct.  The code tries to re-lock when
the stream is linked like group-lock -> stream-lock.

However, that code is known to be too tricky and messy for long time.
It'd be really better to get rid of this complexity.  I tried some
times but failed to reach to the final goal due to lack of time.

OK, let me respin my old patch.  The refreshed one is attached below.
(Note that it's totally untested.  I have to leave my office now,
 sorry for that.  Let me know if the wonder happens and it works :)


thanks,

Takashi

---
From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH] ALSA: pcm - Simplify linked PCM substream spinlocks

The spinlocks held for PCM substreams have been always messy.  For the
better concurrent accessibility, we took always the substream's lock
first.  When substreams are linked, we need a group-wide lock, but
this should be applied outside substream's lock.  So, we unlock the
substream's lock first, then do locks twice.

This scheme is known to be problematic with lockdep.  Maybe because
the nested lock isn't marked properly, and partly because the lock and
unlock sequences are different (A/B -> A/B).

This patch tries to simplify the scheme.  Instead of holding the
substream's lock, we take the group lock always at first.  A drawback
of this is that the access to the individual substream in a same group
won't be allowed any longer.  But, the code looks much easier, and
likely less buggy.

Note that the group lock is identical with the substream's lock
initially before the substream is linked with others.  So, in the case
of non-linked PCM, the new code behaves exactly same as before.

Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
 include/sound/pcm.h     |   12 ++++++------
 sound/core/pcm_native.c |   36 ++++++++++++++----------------------
 2 files changed, 20 insertions(+), 28 deletions(-)

diff --git a/include/sound/pcm.h b/include/sound/pcm.h
index 0cf91b2..d634dcc 100644
--- a/include/sound/pcm.h
+++ b/include/sound/pcm.h
@@ -531,36 +531,36 @@ static inline int snd_pcm_stream_linked(struct snd_pcm_substream *substream)
 static inline void snd_pcm_stream_lock(struct snd_pcm_substream *substream)
 {
 	read_lock(&snd_pcm_link_rwlock);
-	spin_lock(&substream->self_group.lock);
+	spin_lock(&substream->group->lock);
 }
 
 static inline void snd_pcm_stream_unlock(struct snd_pcm_substream *substream)
 {
-	spin_unlock(&substream->self_group.lock);
+	spin_unlock(&substream->group->lock);
 	read_unlock(&snd_pcm_link_rwlock);
 }
 
 static inline void snd_pcm_stream_lock_irq(struct snd_pcm_substream *substream)
 {
 	read_lock_irq(&snd_pcm_link_rwlock);
-	spin_lock(&substream->self_group.lock);
+	spin_lock(&substream->group->lock);
 }
 
 static inline void snd_pcm_stream_unlock_irq(struct snd_pcm_substream *substream)
 {
-	spin_unlock(&substream->self_group.lock);
+	spin_unlock(&substream->group->lock);
 	read_unlock_irq(&snd_pcm_link_rwlock);
 }
 
 #define snd_pcm_stream_lock_irqsave(substream, flags) \
 do { \
 	read_lock_irqsave(&snd_pcm_link_rwlock, (flags)); \
-	spin_lock(&substream->self_group.lock); \
+	spin_lock(&substream->group->lock); \
 } while (0)
 
 #define snd_pcm_stream_unlock_irqrestore(substream, flags) \
 do { \
-	spin_unlock(&substream->self_group.lock); \
+	spin_unlock(&substream->group->lock); \
 	read_unlock_irqrestore(&snd_pcm_link_rwlock, (flags)); \
 } while (0)
 
diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c
index 25ed9fe..c5f28ed 100644
--- a/sound/core/pcm_native.c
+++ b/sound/core/pcm_native.c
@@ -712,7 +712,7 @@ static int snd_pcm_action_group(struct action_ops *ops,
 	int res = 0;
 
 	snd_pcm_group_for_each_entry(s, substream) {
-		if (do_lock && s != substream)
+		if (do_lock)
 			spin_lock_nested(&s->self_group.lock,
 					 SINGLE_DEPTH_NESTING);
 		res = ops->pre_action(s, state);
@@ -740,8 +740,7 @@ static int snd_pcm_action_group(struct action_ops *ops,
 	if (do_lock) {
 		/* unlock streams */
 		snd_pcm_group_for_each_entry(s1, substream) {
-			if (s1 != substream)
-				spin_unlock(&s1->self_group.lock);
+			spin_unlock(&s1->self_group.lock);
 			if (s1 == s)	/* end */
 				break;
 		}
@@ -779,13 +778,7 @@ static int snd_pcm_action(struct action_ops *ops,
 	int res;
 
 	if (snd_pcm_stream_linked(substream)) {
-		if (!spin_trylock(&substream->group->lock)) {
-			spin_unlock(&substream->self_group.lock);
-			spin_lock(&substream->group->lock);
-			spin_lock(&substream->self_group.lock);
-		}
 		res = snd_pcm_action_group(ops, substream, state, 1);
-		spin_unlock(&substream->group->lock);
 	} else {
 		res = snd_pcm_action_single(ops, substream, state);
 	}
@@ -801,19 +794,13 @@ static int snd_pcm_action_lock_irq(struct action_ops *ops,
 {
 	int res;
 
-	read_lock_irq(&snd_pcm_link_rwlock);
+	snd_pcm_stream_lock_irq(substream);
 	if (snd_pcm_stream_linked(substream)) {
-		spin_lock(&substream->group->lock);
-		spin_lock(&substream->self_group.lock);
 		res = snd_pcm_action_group(ops, substream, state, 1);
-		spin_unlock(&substream->self_group.lock);
-		spin_unlock(&substream->group->lock);
 	} else {
-		spin_lock(&substream->self_group.lock);
 		res = snd_pcm_action_single(ops, substream, state);
-		spin_unlock(&substream->self_group.lock);
 	}
-	read_unlock_irq(&snd_pcm_link_rwlock);
+	snd_pcm_stream_unlock_irq(substream);
 	return res;
 }
 
@@ -1586,12 +1573,18 @@ static int snd_pcm_link(struct snd_pcm_substream *substream, int fd)
 	struct file *file;
 	struct snd_pcm_file *pcm_file;
 	struct snd_pcm_substream *substream1;
+	struct snd_pcm_group *group;
 
 	file = snd_pcm_file_fd(fd);
 	if (!file)
 		return -EBADFD;
 	pcm_file = file->private_data;
 	substream1 = pcm_file->substream;
+	group = kmalloc(sizeof(*group), GFP_KERNEL);
+	if (!group) {
+		res = -ENOMEM;
+		goto _nolock;
+	}
 	down_write(&snd_pcm_link_rwsem);
 	write_lock_irq(&snd_pcm_link_rwlock);
 	if (substream->runtime->status->state == SNDRV_PCM_STATE_OPEN ||
@@ -1604,11 +1597,7 @@ static int snd_pcm_link(struct snd_pcm_substream *substream, int fd)
 		goto _end;
 	}
 	if (!snd_pcm_stream_linked(substream)) {
-		substream->group = kmalloc(sizeof(struct snd_pcm_group), GFP_ATOMIC);
-		if (substream->group == NULL) {
-			res = -ENOMEM;
-			goto _end;
-		}
+		substream->group = group;
 		spin_lock_init(&substream->group->lock);
 		INIT_LIST_HEAD(&substream->group->substreams);
 		list_add_tail(&substream->link_list, &substream->group->substreams);
@@ -1620,7 +1609,10 @@ static int snd_pcm_link(struct snd_pcm_substream *substream, int fd)
  _end:
 	write_unlock_irq(&snd_pcm_link_rwlock);
 	up_write(&snd_pcm_link_rwsem);
+ _nolock:
 	fput(file);
+	if (res < 0)
+		kfree(group);
 	return res;
 }
 
-- 
1.7.9.2

Re: snd_pcm lockdep report from 3.3-rc6

[Dave Jones]

On Mon, Mar 12, 2012 at 06:42:48PM +0100, Takashi Iwai wrote:

 > No, the check above should be correct.  The code tries to re-lock when
 > the stream is linked like group-lock -> stream-lock.
 > 
 > However, that code is known to be too tricky and messy for long time.
 > It'd be really better to get rid of this complexity.  I tried some
 > times but failed to reach to the final goal due to lack of time.
 > 
 > OK, let me respin my old patch.  The refreshed one is attached below.
 > (Note that it's totally untested.  I have to leave my office now,
 >  sorry for that.  Let me know if the wonder happens and it works :)

it certainly makes the code look a little simpler!
I'll run with it for a while, and see if anything falls out.

thanks,

	Dave

Re: snd_pcm lockdep report from 3.3-rc6

[Maciej Rutecki]

On poniedziałek, 12 marca 2012 o 15:35:15 Dave Jones wrote:
> I just hit this..
> 
> 
> [ INFO: possible recursive locking detected ]
> 3.3.0-rc6+ #5 Not tainted
> ---------------------------------------------
> pulseaudio/1306 is trying to acquire lock:
>  (&(&substream->self_group.lock)->rlock/1){......}, at:
> [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> but task is already holding lock:
>  (&(&substream->self_group.lock)->rlock/1){......}, at:
> [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> other info that might help us debug this:
>  Possible unsafe locking scenario:
> 
>        CPU0
>        ----
>   lock(&(&substream->self_group.lock)->rlock/1);
>   lock(&(&substream->self_group.lock)->rlock/1);
> 
>  *** DEADLOCK ***
> 
>  May be due to missing lock nesting notation
> 
> 4 locks held by pulseaudio/1306:
>  #0:  (snd_pcm_link_rwlock){......}, at: [<ffffffffa046ab90>]
> snd_pcm_drop+0x60/0x100 [snd_pcm] #1: 
> (&(&substream->self_group.lock)->rlock){......}, at: [<ffffffffa046ab98>]
> snd_pcm_drop+0x68/0x100 [snd_pcm] #2: 
> (&(&substream->group->lock)->rlock){......}, at: [<ffffffffa0469ffe>]
> snd_pcm_action+0x3e/0xb0 [snd_pcm] #3: 
> (&(&substream->self_group.lock)->rlock/1){......}, at:
> [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
> 
> stack backtrace:
> Pid: 1306, comm: pulseaudio Not tainted 3.3.0-rc6+ #5
> Call Trace:
>  [<ffffffff810cee87>] __lock_acquire+0xe47/0x1bb0
>  [<ffffffff810a62b8>] ? sched_clock_cpu+0xb8/0x130
>  [<ffffffff810d030d>] lock_acquire+0x9d/0x220
>  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffff810ca91e>] ? put_lock_stats+0xe/0x40
>  [<ffffffff8169d3cd>] _raw_spin_lock_nested+0x4d/0x90
>  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
>  [<ffffffffa046a031>] snd_pcm_action+0x71/0xb0 [snd_pcm]
>  [<ffffffffa046a08a>] snd_pcm_stop+0x1a/0x20 [snd_pcm]
>  [<ffffffffa046abb1>] snd_pcm_drop+0x81/0x100 [snd_pcm]
>  [<ffffffffa046cdf8>] snd_pcm_common_ioctl1+0x678/0xc00 [snd_pcm]
>  [<ffffffffa046d7d7>] snd_pcm_playback_ioctl1+0x147/0x2e0 [snd_pcm]
>  [<ffffffff812c1cbc>] ? file_has_perm+0xdc/0xf0
>  [<ffffffffa046d9a4>] snd_pcm_playback_ioctl+0x34/0x40 [snd_pcm]
>  [<ffffffff811d2398>] do_vfs_ioctl+0x98/0x570
>  [<ffffffff811d2901>] sys_ioctl+0x91/0xa0
>  [<ffffffff816a5de9>] system_call_fastpath+0x16/0x1b
> 
> 
> I suspect this ..
> 
> static int snd_pcm_action(struct action_ops *ops,
>                           struct snd_pcm_substream *substream,
>                           int state)
> {
>         int res;
> 
>         if (snd_pcm_stream_linked(substream)) {
> -->             if (!spin_trylock(&substream->group->lock)) {
>                         spin_unlock(&substream->self_group.lock);
>                         spin_lock(&substream->group->lock);
>                         spin_lock(&substream->self_group.lock);
>                 }
>                 res = snd_pcm_action_group(ops, substream, state, 1);
>                 spin_unlock(&substream->group->lock);
>         } else {
>                 res = snd_pcm_action_single(ops, substream, state);
>         }
>         return res;
> }
> 
> Should that trylock be on self_group.lock ?
> 
> 	Dave

I created a Bugzilla entry at 
https://bugzilla.kernel.org/show_bug.cgi?id=42958
for your bug/regression report, please add your address to the CC list in 
there, thanks!
-- 
Maciej Rutecki
http://www.mrutecki.pl

Re: snd_pcm lockdep report from 3.3-rc6

[Dave Jones]

On Mon, Mar 12, 2012 at 06:42:48PM +0100, Takashi Iwai wrote:
 > However, that code is known to be too tricky and messy for long time.
 > It'd be really better to get rid of this complexity.  I tried some
 > times but failed to reach to the final goal due to lack of time.
 > 
 > OK, let me respin my old patch.  The refreshed one is attached below.
 > (Note that it's totally untested.  I have to leave my office now,
 >  sorry for that.  Let me know if the wonder happens and it works :)

I thought I was going crazy when I still saw the same trace,
and made sure the patch was actually applied, and rebuilt the kernel.
Seems this patch doesn't fix this.

The trace is slightly different (one fewer lock taken)..

	Dave

=============================================
[ INFO: possible recursive locking detected ]
3.3.0+ #15 Not tainted
---------------------------------------------
pulseaudio/1269 is trying to acquire lock:
 (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0476c00>] snd_pcm_action_group+0x90/0x250 [snd_pcm]

but task is already holding lock:
 (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0476c00>] snd_pcm_action_group+0x90/0x250 [snd_pcm]

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&(&substream->self_group.lock)->rlock/1);
  lock(&(&substream->self_group.lock)->rlock/1);

 *** DEADLOCK ***

 May be due to missing lock nesting notation

3 locks held by pulseaudio/1269:
 #0:  (snd_pcm_link_rwlock){......}, at: [<ffffffffa0478ac9>] snd_pcm_drop+0x49/0xe0 [snd_pcm]
 #1:  (&(&substream->group->lock)->rlock){......}, at: [<ffffffffa0478ad5>] snd_pcm_drop+0x55/0xe0 [snd_pcm]
 #2:  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0476c00>] snd_pcm_action_group+0x90/0x250 [snd_pcm]

stack backtrace:
Pid: 1269, comm: pulseaudio Not tainted 3.3.0+ #15
Call Trace:
 [<ffffffff810cee37>] __lock_acquire+0xe47/0x1bb0
 [<ffffffff81023322>] ? native_sched_clock+0x22/0x80
 [<ffffffff810d02bd>] lock_acquire+0x9d/0x220
 [<ffffffffa0476c00>] ? snd_pcm_action_group+0x90/0x250 [snd_pcm]
 [<ffffffff810ca8be>] ? put_lock_stats+0xe/0x40
 [<ffffffff816a1a1d>] _raw_spin_lock_nested+0x4d/0x90
 [<ffffffffa0476c00>] ? snd_pcm_action_group+0x90/0x250 [snd_pcm]
 [<ffffffffa0476c00>] snd_pcm_action_group+0x90/0x250 [snd_pcm]
 [<ffffffff812c5a46>] ? avc_has_perm_noaudit+0x46/0x500
 [<ffffffffa0477f03>] snd_pcm_action+0x23/0x40 [snd_pcm]
 [<ffffffffa0477f3a>] snd_pcm_stop+0x1a/0x20 [snd_pcm]
 [<ffffffffa0478aef>] snd_pcm_drop+0x6f/0xe0 [snd_pcm]
 [<ffffffffa047ad08>] snd_pcm_common_ioctl1+0x668/0xc30 [snd_pcm]
 [<ffffffffa047b727>] snd_pcm_playback_ioctl1+0x147/0x2e0 [snd_pcm]
 [<ffffffff812c839c>] ? file_has_perm+0xdc/0xf0
 [<ffffffffa047b8f4>] snd_pcm_playback_ioctl+0x34/0x40 [snd_pcm]
 [<ffffffff811d4858>] do_vfs_ioctl+0x98/0x570
 [<ffffffff811d4dc1>] sys_ioctl+0x91/0xa0
 [<ffffffff816aa3e9>] system_call_fastpath+0x16/0x1b

Re: snd_pcm lockdep report from 3.3-rc6

[Dave Jones]

On Mon, Mar 12, 2012 at 06:42:48PM +0100, Takashi Iwai wrote:

Hi Takashi,

 > > [ INFO: possible recursive locking detected ]
 > > 3.3.0-rc6+ #5 Not tainted
 > > ---------------------------------------------
 > > pulseaudio/1306 is trying to acquire lock:
 > >  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > > 
 > > but task is already holding lock:
 > >  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > > 
 > > other info that might help us debug this:
 > >  Possible unsafe locking scenario:
 > > 
 > >        CPU0
 > >        ----
 > >   lock(&(&substream->self_group.lock)->rlock/1);
 > >   lock(&(&substream->self_group.lock)->rlock/1);
 > > 
 > >  *** DEADLOCK ***
 > > 
 > >  May be due to missing lock nesting notation
 > > 
 > > 4 locks held by pulseaudio/1306:
 > >  #0:  (snd_pcm_link_rwlock){......}, at: [<ffffffffa046ab90>] snd_pcm_drop+0x60/0x100 [snd_pcm]
 > >  #1:  (&(&substream->self_group.lock)->rlock){......}, at: [<ffffffffa046ab98>] snd_pcm_drop+0x68/0x100 [snd_pcm]
 > >  #2:  (&(&substream->group->lock)->rlock){......}, at: [<ffffffffa0469ffe>] snd_pcm_action+0x3e/0xb0 [snd_pcm]
 > >  #3:  (&(&substream->self_group.lock)->rlock/1){......}, at: [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > > 
 > > stack backtrace:
 > > Pid: 1306, comm: pulseaudio Not tainted 3.3.0-rc6+ #5
 > > Call Trace:
 > >  [<ffffffff810cee87>] __lock_acquire+0xe47/0x1bb0
 > >  [<ffffffff810a62b8>] ? sched_clock_cpu+0xb8/0x130
 > >  [<ffffffff810d030d>] lock_acquire+0x9d/0x220
 > >  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > >  [<ffffffff810ca91e>] ? put_lock_stats+0xe/0x40
 > >  [<ffffffff8169d3cd>] _raw_spin_lock_nested+0x4d/0x90
 > >  [<ffffffffa0468c0b>] ? snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > >  [<ffffffffa0468c0b>] snd_pcm_action_group+0x9b/0x260 [snd_pcm]
 > >  [<ffffffffa046a031>] snd_pcm_action+0x71/0xb0 [snd_pcm]
 > >  [<ffffffffa046a08a>] snd_pcm_stop+0x1a/0x20 [snd_pcm]
 > >  [<ffffffffa046abb1>] snd_pcm_drop+0x81/0x100 [snd_pcm]
 > >  [<ffffffffa046cdf8>] snd_pcm_common_ioctl1+0x678/0xc00 [snd_pcm]
 > >  [<ffffffffa046d7d7>] snd_pcm_playback_ioctl1+0x147/0x2e0 [snd_pcm]
 > >  [<ffffffff812c1cbc>] ? file_has_perm+0xdc/0xf0
 > >  [<ffffffffa046d9a4>] snd_pcm_playback_ioctl+0x34/0x40 [snd_pcm]
 > >  [<ffffffff811d2398>] do_vfs_ioctl+0x98/0x570
 > >  [<ffffffff811d2901>] sys_ioctl+0x91/0xa0
 > >  [<ffffffff816a5de9>] system_call_fastpath+0x16/0x1b
 > > 
 > > 
 > > I suspect this ..
 > > 
 > > static int snd_pcm_action(struct action_ops *ops,
 > >                           struct snd_pcm_substream *substream,
 > >                           int state)
 > > {
 > >         int res;
 > > 
 > >         if (snd_pcm_stream_linked(substream)) {
 > > -->             if (!spin_trylock(&substream->group->lock)) {
 > >                         spin_unlock(&substream->self_group.lock);
 > >                         spin_lock(&substream->group->lock);
 > >                         spin_lock(&substream->self_group.lock);
 > >                 }
 > >                 res = snd_pcm_action_group(ops, substream, state, 1);
 > >                 spin_unlock(&substream->group->lock);
 > >         } else {
 > >                 res = snd_pcm_action_single(ops, substream, state);
 > >         }
 > >         return res;
 > > }
 > > 
 > > Should that trylock be on self_group.lock ?
 > 
 > No, the check above should be correct.  The code tries to re-lock when
 > the stream is linked like group-lock -> stream-lock.
 > 
 > However, that code is known to be too tricky and messy for long time.
 > It'd be really better to get rid of this complexity.  I tried some
 > times but failed to reach to the final goal due to lack of time.
 > 
 > OK, let me respin my old patch.  The refreshed one is attached below.
 > (Note that it's totally untested.  I have to leave my office now,
 >  sorry for that.  Let me know if the wonder happens and it works :)


I'm not sure if I got back to you on this, but that patch did nothing
to change this for me, and I still see this on 3.5-rc1

	Dave