usb-audio: not submit urb for stopped endpoint
diff mbox series

Message ID 20191112065108.7766-1-henryl@nvidia.com
State New
Headers show
Series
  • usb-audio: not submit urb for stopped endpoint
Related show

Commit Message

Henry Lin Nov. 12, 2019, 6:51 a.m. UTC
While output urb's snd_complete_urb() is executing, calling
prepare_outbound_urb() may cause endpoint stopped before
prepare_outbound_urb() returns and result in next urb submitted
to stopped endpoint. usb-audio driver cannot re-use it afterwards as
the urb is still hold by usb stack.

This change checks EP_FLAG_RUNNING flag after prepare_outbound_urb() again
to let snd_complete_urb() know the endpoint already stopped and does not
submit next urb.

We observed two scenario have this issue:
1. While executing snd_complete_urb() to complete an output urb, calling
   prepare_outbound_urb() let deactive_urbs() get called to unlink all
   active urbs.

[  268.097066] [<ffffffc000af7638>] deactivate_urbs+0xd4/0x108
[  268.102633] [<ffffffc000af87fc>] snd_usb_endpoint_stop+0x30/0x58
[  268.108636] [<ffffffc000b0272c>] snd_usb_substream_playback_trigger+0xa4/0xf4
[  268.115765] [<ffffffc000acdbd0>] snd_pcm_do_stop+0x4c/0x58
[  268.121245] [<ffffffc000acda24>] snd_pcm_action_single+0x40/0x88
[  268.127245] [<ffffffc000ace984>] snd_pcm_action+0x30/0xf0
[  268.132632] [<ffffffc000acea68>] snd_pcm_stop+0x24/0x2c
[  268.137851] [<ffffffc000ad5e14>] xrun+0x60/0x6c
[  268.142374] [<ffffffc000ad7a98>] snd_pcm_update_state+0xa8/0x10c
[  268.148374] [<ffffffc000ad7e24>] snd_pcm_update_hw_ptr0+0x328/0x344
[  268.154635] [<ffffffc000ad7ed8>] snd_pcm_period_elapsed+0x98/0xb0
[  268.160723] [<ffffffc000b02510>] prepare_playback_urb+0x46c/0x488
[  268.166810] [<ffffffc000af7d60>] prepare_outbound_urb+0x60/0x1d4
[  268.172805] [<ffffffc000af8d60>] snd_complete_urb+0x244/0x264
[  268.178548] [<ffffffc00081fb38>] __usb_hcd_giveback_urb+0x94/0x104
[  268.184721] [<ffffffc00081fbe4>] usb_hcd_giveback_urb+0x3c/0x114
[  268.190724] [<ffffffc00084d4b4>] handle_tx_event+0x1304/0x1434
[  268.196552] [<ffffffc00084dbc0>] xhci_handle_event+0x5dc/0x788
[  268.202378] [<ffffffc00084dee4>] xhci_irq+0x178/0x280

2. Userspace application stops playback from sound subsystem with below
   call stack:

[   28.506477] CPU: 5 PID: 1274 Comm: AudioOut_25 Not tainted 4.4.38-tegra #31
[   28.513430] Hardware name: quill (DT)
[   28.517085] Call trace:
[   28.519531] [<ffffffc000089a84>] dump_backtrace+0x0/0xf8
[   28.524837] [<ffffffc000089c44>] show_stack+0x14/0x1c
[   28.529885] [<ffffffc000401c54>] dump_stack+0xac/0xe0
[   28.534931] [<ffffffc000b35f94>] deactivate_urbs+0x148/0x180
[   28.540578] [<ffffffc000b37160>] snd_usb_endpoint_stop+0x30/0x58
[   28.546571] [<ffffffc000b410d8>] snd_usb_substream_playback_trigger+0xa4/0xf4
[   28.553699] [<ffffffc000b0c160>] snd_pcm_do_stop+0x4c/0x58
[   28.559179] [<ffffffc000b0bfb4>] snd_pcm_action_single+0x40/0x88
[   28.565178] [<ffffffc000b0cf14>] snd_pcm_action+0x30/0xf0
[   28.570568] [<ffffffc000b0fbc8>] snd_pcm_drop+0xac/0x140
[   28.575873] [<ffffffc000b0fc84>] snd_pcm_release_substream+0x28/0xb0
[   28.582212] [<ffffffc000b0fd48>] snd_pcm_release+0x3c/0x98
[   28.587686] [<ffffffc0001e3210>] __fput+0xe0/0x1ac
[   28.592469] [<ffffffc0001e3334>] ____fput+0xc/0x14
[   28.597253] [<ffffffc0000c2904>] task_work_run+0xa0/0xc0
[   28.602558] [<ffffffc0000897bc>] do_notify_resume+0x48/0x60
[   28.608123] [<ffffffc000084ee8>] work_pending+0x1c/0x20

In the call path, snd_pcm_stream spinlock has been acquired in
snd_pcm_drop(). If an output urb is completed between the spinlock
acquired and deactivate_urbs() clears EP_FLAG_RUNNING for the endpoint,
its executing of snd_complete_urb() will be blocked for acquiring
snd_pcm_stream spinlock in snd_pcm_period_elapsed() until the lock is
released in snd_pcm_drop(). When snd_complete_urb() continues, all jobs
for deactivate_urbs() are finished.

Signed-off-by: Henry Lin <henryl@nvidia.com>
---
 sound/usb/endpoint.c | 3 +++
 1 file changed, 3 insertions(+)

Comments

Takashi Iwai Nov. 12, 2019, 4:25 p.m. UTC | #1
On Tue, 12 Nov 2019 17:13:37 +0100,
Henry Lin wrote:
> 
> >On Tue, 12 Nov 2019 07:51:06 +0100,
> >Henry Lin wrote:
> >>
> >> While output urb's snd_complete_urb() is executing, calling
> >> prepare_outbound_urb() may cause endpoint stopped before
> >> prepare_outbound_urb() returns and result in next urb submitted
> >> to stopped endpoint. usb-audio driver cannot re-use it afterwards as
> >> the urb is still hold by usb stack.
> >>
> >> This change checks EP_FLAG_RUNNING flag after prepare_outbound_urb() again
> >> to let snd_complete_urb() know the endpoint already stopped and does not
> >> submit next urb.
> 
> >OK, this part looks good and understandable.
> 
> 
> >> We observed two scenario have this issue:
> >> 1. While executing snd_complete_urb() to complete an output urb, calling
> >>    prepare_outbound_urb() let deactive_urbs() get called to unlink all
> >>    active urbs.
> >>
> >> [  268.097066] [<ffffffc000af7638>] deactivate_urbs+0xd4/0x108
> >> [  268.102633] [<ffffffc000af87fc>] snd_usb_endpoint_stop+0x30/0x58
> >> [  268.108636] [<ffffffc000b0272c>] snd_usb_substream_playback_trigger+0xa4/0xf4
> >> [  268.115765] [<ffffffc000acdbd0>] snd_pcm_do_stop+0x4c/0x58
> >> [  268.121245] [<ffffffc000acda24>] snd_pcm_action_single+0x40/0x88
> >> [  268.127245] [<ffffffc000ace984>] snd_pcm_action+0x30/0xf0
> >> [  268.132632] [<ffffffc000acea68>] snd_pcm_stop+0x24/0x2c
> >> [  268.137851] [<ffffffc000ad5e14>] xrun+0x60/0x6c
> >> [  268.142374] [<ffffffc000ad7a98>] snd_pcm_update_state+0xa8/0x10c
> >> [  268.148374] [<ffffffc000ad7e24>] snd_pcm_update_hw_ptr0+0x328/0x344
> >> [  268.154635] [<ffffffc000ad7ed8>] snd_pcm_period_elapsed+0x98/0xb0
> >> [  268.160723] [<ffffffc000b02510>] prepare_playback_urb+0x46c/0x488
> >> [  268.166810] [<ffffffc000af7d60>] prepare_outbound_urb+0x60/0x1d4
> >> [  268.172805] [<ffffffc000af8d60>] snd_complete_urb+0x244/0x264
> >> [  268.178548] [<ffffffc00081fb38>] __usb_hcd_giveback_urb+0x94/0x104
> >> [  268.184721] [<ffffffc00081fbe4>] usb_hcd_giveback_urb+0x3c/0x114
> >> [  268.190724] [<ffffffc00084d4b4>] handle_tx_event+0x1304/0x1434
> >> [  268.196552] [<ffffffc00084dbc0>] xhci_handle_event+0x5dc/0x788
> >> [  268.202378] [<ffffffc00084dee4>] xhci_irq+0x178/0x280
> >>
> >> 2. Userspace application stops playback from sound subsystem with below
> >>    call stack:
> >>
> >> [   28.506477] CPU: 5 PID: 1274 Comm: AudioOut_25 Not tainted 4.4.38-tegra #31
> >> [   28.513430] Hardware name: quill (DT)
> >> [   28.517085] Call trace:
> >> [   28.519531] [<ffffffc000089a84>] dump_backtrace+0x0/0xf8
> >> [   28.524837] [<ffffffc000089c44>] show_stack+0x14/0x1c
> >> [   28.529885] [<ffffffc000401c54>] dump_stack+0xac/0xe0
> >> [   28.534931] [<ffffffc000b35f94>] deactivate_urbs+0x148/0x180
> >> [   28.540578] [<ffffffc000b37160>] snd_usb_endpoint_stop+0x30/0x58
> >> [   28.546571] [<ffffffc000b410d8>] snd_usb_substream_playback_trigger+0xa4/0xf4
> >> [   28.553699] [<ffffffc000b0c160>] snd_pcm_do_stop+0x4c/0x58
> >> [   28.559179] [<ffffffc000b0bfb4>] snd_pcm_action_single+0x40/0x88
> >> [   28.565178] [<ffffffc000b0cf14>] snd_pcm_action+0x30/0xf0
> >> [   28.570568] [<ffffffc000b0fbc8>] snd_pcm_drop+0xac/0x140
> >> [   28.575873] [<ffffffc000b0fc84>] snd_pcm_release_substream+0x28/0xb0
> >> [   28.582212] [<ffffffc000b0fd48>] snd_pcm_release+0x3c/0x98
> >> [   28.587686] [<ffffffc0001e3210>] __fput+0xe0/0x1ac
> >> [   28.592469] [<ffffffc0001e3334>] ____fput+0xc/0x14
> >> [   28.597253] [<ffffffc0000c2904>] task_work_run+0xa0/0xc0
> >> [   28.602558] [<ffffffc0000897bc>] do_notify_resume+0x48/0x60
> >> [   28.608123] [<ffffffc000084ee8>] work_pending+0x1c/0x20
> >>
> >> In the call path, snd_pcm_stream spinlock has been acquired in
> >> snd_pcm_drop(). If an output urb is completed between the spinlock
> >> acquired and deactivate_urbs() clears EP_FLAG_RUNNING for the endpoint,
> >> its executing of snd_complete_urb() will be blocked for acquiring
> >> snd_pcm_stream spinlock in snd_pcm_period_elapsed() until the lock is
> >> released in snd_pcm_drop(). When snd_complete_urb() continues, all jobs
> >> for deactivate_urbs() are finished.
> 
> >... but this part is unclear to me.  Do you mean that we have a
> >deadlock in these two concurrent calls without your patch?
> Above describes two different cases that endpoint is stopped before prepare_outbound_urb() returns in details. Listed two call stacks belong to different cases. Without this patch, both two cases will result in below error messages afterwards:
> 
> [  213.153103] usb 1-2: timeout: still 1 active urbs on EP #1
> [  213.164121] usb 1-2: cannot submit urb 0, error -16: unknown error

Ah, I see.  Then you don't have to write up the full stack trace like
the above.  It's confusing as if it were some kernel Oops or WARNING.

BTW, with your patch, is the error in the first line ("timeout: still
1 active urbs on EP #1") also fixed?


thanks,

Takashi
Henry Lin Nov. 12, 2019, 4:41 p.m. UTC | #2
> Ah, I see.  Then you don't have to write up the full stack trace like
> the above.  It's confusing as if it were some kernel Oops or WARNING.
Got it. Should I post another patch set here for removing these confusing description in commit message? Or you can help to remove them before merging?

> BTW, with your patch, is the error in the first line ("timeout: still
> 1 active urbs on EP #1") also fixed?
Yes, "timeout: still 1 active urbs on EP #1" will be fixed as well.
Takashi Iwai Nov. 12, 2019, 4:48 p.m. UTC | #3
On Tue, 12 Nov 2019 17:41:42 +0100,
Henry Lin wrote:
> 
> > Ah, I see.  Then you don't have to write up the full stack trace like
> > the above.  It's confusing as if it were some kernel Oops or WARNING.
> Got it. Should I post another patch set here for removing these confusing description in commit message? Or you can help to remove them before merging?

Please resubmit after rephrasing the patch description.

> > BTW, with your patch, is the error in the first line ("timeout: still
> > 1 active urbs on EP #1") also fixed?
> Yes, "timeout: still 1 active urbs on EP #1" will be fixed as well.

OK, then this should be mentioned in the patch description.
Actually the patch fixes this kind of error (the stall at the
concurrent stream stop).


thanks,

Takashi

Patch
diff mbox series

diff --git a/sound/usb/endpoint.c b/sound/usb/endpoint.c
index a2ab8e8d3a93..4a9a2f6ef5a4 100644
--- a/sound/usb/endpoint.c
+++ b/sound/usb/endpoint.c
@@ -388,6 +388,9 @@  static void snd_complete_urb(struct urb *urb)
 		}
 
 		prepare_outbound_urb(ep, ctx);
+		/* can be stopped during prepare callback */
+		if (unlikely(!test_bit(EP_FLAG_RUNNING, &ep->flags)))
+			goto exit_clear;
 	} else {
 		retire_inbound_urb(ep, ctx);
 		/* can be stopped during retire callback */