[alsa-devel] [PATCH] usb-audio: not submit urb for stopped endpoint
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(+)
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 */
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:
- 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
- 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?
Thanks!
Takashi
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:
- 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
- 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
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:
- 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
- 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
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.
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
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. Below kind of error will be fixed:
[ 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
Signed-off-by: Henry Lin henryl@nvidia.com --- sound/usb/endpoint.c | 3 +++ 1 file changed, 3 insertions(+)
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 */
participants (2)
-
Henry Lin -
Takashi Iwai