* strange call stack when running uvc-gadget application
@ 2020-11-02 9:50 Peter Chen
2020-11-03 6:20 ` Sriharsha Allenki
0 siblings, 1 reply; 4+ messages in thread
From: Peter Chen @ 2020-11-02 9:50 UTC (permalink / raw)
To: linux-usb; +Cc: laurent.pinchart
Hi all,
When running run uvc-gadget application at HS using dwc3 gadget at Linux
v5.10-rc1, the video stream will be stopped after 1-2 minutes running. The
trace log like below, I wonder how _raw_spin_lock_irqsave calls __switch_to?
Any hints? Thanks.
usb_test# [ 4757.322728] configfs-gadget gadget: uvc: VS request completed with status -18.
[ 4757.329971] configfs-gadget gadget: uvc: VS request completed with status -18.
UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
usb_test# [ 4812.376465] check_interval: 37 callbacks suppressed
[ 4825.307665] configfs-gadget gadget: uvc: VS request completed with status -18.
[ 4825.314912] configfs-gadget gadget: uvc: VS request completed with status -18.
UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
[ 4826.231392] check_interval: 3 callbacks suppressed
select timeout
[ 4827.336088] dwc3 38100000.dwc3: request 0000000080ebefd3 was not queued to ep2in
[ 4827.343547] dwc3 38100000.dwc3: request 00000000b578605c was not queued to ep2in
[ 4827.350989] dwc3 38100000.dwc3: request 00000000c6d191cd was not queued to ep2in
[ 4827.358422] dwc3 38100000.dwc3: request 0000000085205409 was not queued to ep2in
UVC: Stopping video stream.
[ 4848.381718] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 4848.387824] rcu: 3-...0: (1 GPs behind) idle=162/1/0x4000000000000000 softirq=10819/10819 fqs=2356
[ 4848.396956] (detected by 2, t=5252 jiffies, g=20129, q=3770)
[ 4848.396959] Task dump for CPU 3:
[ 4848.405925] task:uvc-gadget_wlhe state:R running task stack: 0 pid: 674 ppid: 636 flags:0x00000202
[ 4848.415842] Call trace:
[ 4848.418294] __switch_to+0xc0/0x170
[ 4848.421785] _raw_spin_lock_irqsave+0x84/0xb0
[ 4848.426143] composite_disconnect+0x28/0x78
[ 4848.430327] configfs_composite_disconnect+0x68/0x70
[ 4848.435290] usb_gadget_disconnect+0x10c/0x128
[ 4848.439733] usb_gadget_deactivate+0xd4/0x108
[ 4848.444089] usb_function_deactivate+0x6c/0x80
[ 4848.448534] uvc_function_disconnect+0x20/0x58
[ 4848.452976] uvc_v4l2_release+0x30/0x88
[ 4848.456812] v4l2_release+0xbc/0xf0
[ 4848.460301] __fput+0x7c/0x230
[ 4848.463353] ____fput+0x14/0x20
[ 4848.466495] task_work_run+0x88/0x140
[ 4848.470157] do_notify_resume+0x240/0x6f0
[ 4848.474166] work_pending+0x8/0x200
--
Thanks,
Peter Chen
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: strange call stack when running uvc-gadget application
2020-11-02 9:50 strange call stack when running uvc-gadget application Peter Chen
@ 2020-11-03 6:20 ` Sriharsha Allenki
2020-11-04 10:05 ` Peter Chen
0 siblings, 1 reply; 4+ messages in thread
From: Sriharsha Allenki @ 2020-11-03 6:20 UTC (permalink / raw)
To: Peter Chen, linux-usb; +Cc: laurent.pinchart
Hi Peter,
On 11/2/2020 3:20 PM, Peter Chen wrote:
> Hi all,
>
> When running run uvc-gadget application at HS using dwc3 gadget at Linux
> v5.10-rc1, the video stream will be stopped after 1-2 minutes running. The
> trace log like below, I wonder how _raw_spin_lock_irqsave calls __switch_to?
> Any hints? Thanks.
>
> usb_test# [ 4757.322728] configfs-gadget gadget: uvc: VS request completed with status -18.
> [ 4757.329971] configfs-gadget gadget: uvc: VS request completed with status -18.
> UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
>
> usb_test# [ 4812.376465] check_interval: 37 callbacks suppressed
> [ 4825.307665] configfs-gadget gadget: uvc: VS request completed with status -18.
> [ 4825.314912] configfs-gadget gadget: uvc: VS request completed with status -18.
> UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
> [ 4826.231392] check_interval: 3 callbacks suppressed
> select timeout
> [ 4827.336088] dwc3 38100000.dwc3: request 0000000080ebefd3 was not queued to ep2in
> [ 4827.343547] dwc3 38100000.dwc3: request 00000000b578605c was not queued to ep2in
> [ 4827.350989] dwc3 38100000.dwc3: request 00000000c6d191cd was not queued to ep2in
> [ 4827.358422] dwc3 38100000.dwc3: request 0000000085205409 was not queued to ep2in
> UVC: Stopping video stream.
>
> [ 4848.381718] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [ 4848.387824] rcu: 3-...0: (1 GPs behind) idle=162/1/0x4000000000000000 softirq=10819/10819 fqs=2356
> [ 4848.396956] (detected by 2, t=5252 jiffies, g=20129, q=3770)
> [ 4848.396959] Task dump for CPU 3:
> [ 4848.405925] task:uvc-gadget_wlhe state:R running task stack: 0 pid: 674 ppid: 636 flags:0x00000202
> [ 4848.415842] Call trace:
> [ 4848.418294] __switch_to+0xc0/0x170
> [ 4848.421785] _raw_spin_lock_irqsave+0x84/0xb0
> [ 4848.426143] composite_disconnect+0x28/0x78
> [ 4848.430327] configfs_composite_disconnect+0x68/0x70
> [ 4848.435290] usb_gadget_disconnect+0x10c/0x128
> [ 4848.439733] usb_gadget_deactivate+0xd4/0x108
> [ 4848.444089] usb_function_deactivate+0x6c/0x80
> [ 4848.448534] uvc_function_disconnect+0x20/0x58
> [ 4848.452976] uvc_v4l2_release+0x30/0x88
> [ 4848.456812] v4l2_release+0xbc/0xf0
> [ 4848.460301] __fput+0x7c/0x230
> [ 4848.463353] ____fput+0x14/0x20
> [ 4848.466495] task_work_run+0x88/0x140
> [ 4848.470157] do_notify_resume+0x240/0x6f0
> [ 4848.474166] work_pending+0x8/0x200
The reason for this seems to be that the usb_gadget_deactivate is being called with
spinlock held from the usb_function_deactivate and the same lock is being used
in the composite_disconnect (&cdev->lock).
This should be able to resolve it.
diff --git a/drivers/usb/gadget/composite.c b/drivers/usb/gadget/composite.c
index 05b176c82cc5..5fced737e4ef 100644
--- a/drivers/usb/gadget/composite.c
+++ b/drivers/usb/gadget/composite.c
@@ -392,8 +392,11 @@ int usb_function_deactivate(struct usb_function *function)
spin_lock_irqsave(&cdev->lock, flags);
- if (cdev->deactivations == 0)
+ if (cdev->deactivations == 0) {
+ spin_unlock_irqrestore(&cdev->lock, flags);
status = usb_gadget_deactivate(cdev->gadget);
+ spin_lock_irqsave(&cdev->lock, flags);
+ }
if (status == 0)
cdev->deactivations++;
@@ -424,8 +427,11 @@ int usb_function_activate(struct usb_function *function)
status = -EINVAL;
else {
cdev->deactivations--;
- if (cdev->deactivations == 0)
+ if (cdev->deactivations == 0) {
+ spin_unlock_irqrestore(&cdev->lock, flags);
status = usb_gadget_activate(cdev->gadget);
+ spin_lock_irqsave(&cdev->lock, flags);
+ }
}
spin_unlock_irqrestore(&cdev->lock, flags);
This should also protect the cdev->deactivations as well which was the
primary reason for the spinlock here. Hope this helps.
Regards,
Sriharsha
>
--
The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: strange call stack when running uvc-gadget application
2020-11-03 6:20 ` Sriharsha Allenki
@ 2020-11-04 10:05 ` Peter Chen
2020-11-05 5:29 ` Sriharsha Allenki
0 siblings, 1 reply; 4+ messages in thread
From: Peter Chen @ 2020-11-04 10:05 UTC (permalink / raw)
To: Sriharsha Allenki; +Cc: linux-usb, laurent.pinchart
On 20-11-03 11:50:17, Sriharsha Allenki wrote:
> Hi Peter,
>
> On 11/2/2020 3:20 PM, Peter Chen wrote:
> > Hi all,
> >
> > When running run uvc-gadget application at HS using dwc3 gadget at Linux
> > v5.10-rc1, the video stream will be stopped after 1-2 minutes running. The
> > trace log like below, I wonder how _raw_spin_lock_irqsave calls __switch_to?
> > Any hints? Thanks.
> >
> > usb_test# [ 4757.322728] configfs-gadget gadget: uvc: VS request completed with status -18.
> > [ 4757.329971] configfs-gadget gadget: uvc: VS request completed with status -18.
> > UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
> >
> > usb_test# [ 4812.376465] check_interval: 37 callbacks suppressed
> > [ 4825.307665] configfs-gadget gadget: uvc: VS request completed with status -18.
> > [ 4825.314912] configfs-gadget gadget: uvc: VS request completed with status -18.
> > UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
> > [ 4826.231392] check_interval: 3 callbacks suppressed
> > select timeout
> > [ 4827.336088] dwc3 38100000.dwc3: request 0000000080ebefd3 was not queued to ep2in
> > [ 4827.343547] dwc3 38100000.dwc3: request 00000000b578605c was not queued to ep2in
> > [ 4827.350989] dwc3 38100000.dwc3: request 00000000c6d191cd was not queued to ep2in
> > [ 4827.358422] dwc3 38100000.dwc3: request 0000000085205409 was not queued to ep2in
> > UVC: Stopping video stream.
> >
> > [ 4848.381718] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > [ 4848.387824] rcu: 3-...0: (1 GPs behind) idle=162/1/0x4000000000000000 softirq=10819/10819 fqs=2356
> > [ 4848.396956] (detected by 2, t=5252 jiffies, g=20129, q=3770)
> > [ 4848.396959] Task dump for CPU 3:
> > [ 4848.405925] task:uvc-gadget_wlhe state:R running task stack: 0 pid: 674 ppid: 636 flags:0x00000202
> > [ 4848.415842] Call trace:
> > [ 4848.418294] __switch_to+0xc0/0x170
> > [ 4848.421785] _raw_spin_lock_irqsave+0x84/0xb0
> > [ 4848.426143] composite_disconnect+0x28/0x78
> > [ 4848.430327] configfs_composite_disconnect+0x68/0x70
> > [ 4848.435290] usb_gadget_disconnect+0x10c/0x128
> > [ 4848.439733] usb_gadget_deactivate+0xd4/0x108
> > [ 4848.444089] usb_function_deactivate+0x6c/0x80
> > [ 4848.448534] uvc_function_disconnect+0x20/0x58
> > [ 4848.452976] uvc_v4l2_release+0x30/0x88
> > [ 4848.456812] v4l2_release+0xbc/0xf0
> > [ 4848.460301] __fput+0x7c/0x230
> > [ 4848.463353] ____fput+0x14/0x20
> > [ 4848.466495] task_work_run+0x88/0x140
> > [ 4848.470157] do_notify_resume+0x240/0x6f0
> > [ 4848.474166] work_pending+0x8/0x200
> The reason for this seems to be that the usb_gadget_deactivate is being called with
> spinlock held from the usb_function_deactivate and the same lock is being used
> in the composite_disconnect (&cdev->lock).
>
> This should be able to resolve it.
>
> diff --git a/drivers/usb/gadget/composite.c b/drivers/usb/gadget/composite.c
> index 05b176c82cc5..5fced737e4ef 100644
> --- a/drivers/usb/gadget/composite.c
> +++ b/drivers/usb/gadget/composite.c
> @@ -392,8 +392,11 @@ int usb_function_deactivate(struct usb_function *function)
>
> spin_lock_irqsave(&cdev->lock, flags);
>
> - if (cdev->deactivations == 0)
> + if (cdev->deactivations == 0) {
> + spin_unlock_irqrestore(&cdev->lock, flags);
> status = usb_gadget_deactivate(cdev->gadget);
> + spin_lock_irqsave(&cdev->lock, flags);
> + }
> if (status == 0)
> cdev->deactivations++;
>
> @@ -424,8 +427,11 @@ int usb_function_activate(struct usb_function *function)
> status = -EINVAL;
> else {
> cdev->deactivations--;
> - if (cdev->deactivations == 0)
> + if (cdev->deactivations == 0) {
> + spin_unlock_irqrestore(&cdev->lock, flags);
> status = usb_gadget_activate(cdev->gadget);
> + spin_lock_irqsave(&cdev->lock, flags);
> + }
> }
>
> spin_unlock_irqrestore(&cdev->lock, flags);
>
Thanks, Sriharsha. It fixed the kernel dump after video stream has
stopped, I did not check the whole trace carefully, and not found this
spin recursion issue. You could add my Tested-by for it. Meanwhile,
this issue was reported before, and unlock at usb_function_activate
could also fix the possible sleep at atomic context issue for dwc3.
https://lore.kernel.org/linux-usb/20191115070122.GF30608@b29397-desktop/T/
--
Thanks,
Peter Chen
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: strange call stack when running uvc-gadget application
2020-11-04 10:05 ` Peter Chen
@ 2020-11-05 5:29 ` Sriharsha Allenki
0 siblings, 0 replies; 4+ messages in thread
From: Sriharsha Allenki @ 2020-11-05 5:29 UTC (permalink / raw)
To: Peter Chen; +Cc: linux-usb, laurent.pinchart
Hi Peter,
On 11/4/2020 3:35 PM, Peter Chen wrote:
> On 20-11-03 11:50:17, Sriharsha Allenki wrote:
>> Hi Peter,
>>
>> On 11/2/2020 3:20 PM, Peter Chen wrote:
>>> Hi all,
>>>
>>> When running run uvc-gadget application at HS using dwc3 gadget at Linux
>>> v5.10-rc1, the video stream will be stopped after 1-2 minutes running. The
>>> trace log like below, I wonder how _raw_spin_lock_irqsave calls __switch_to?
>>> Any hints? Thanks.
>>>
>>> usb_test# [ 4757.322728] configfs-gadget gadget: uvc: VS request completed with status -18.
>>> [ 4757.329971] configfs-gadget gadget: uvc: VS request completed with status -18.
>>> UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
>>>
>>> usb_test# [ 4812.376465] check_interval: 37 callbacks suppressed
>>> [ 4825.307665] configfs-gadget gadget: uvc: VS request completed with status -18.
>>> [ 4825.314912] configfs-gadget gadget: uvc: VS request completed with status -18.
>>> UVC: Possible USB shutdown requested from Host, seen during VIDIOC_DQBUF
>>> [ 4826.231392] check_interval: 3 callbacks suppressed
>>> select timeout
>>> [ 4827.336088] dwc3 38100000.dwc3: request 0000000080ebefd3 was not queued to ep2in
>>> [ 4827.343547] dwc3 38100000.dwc3: request 00000000b578605c was not queued to ep2in
>>> [ 4827.350989] dwc3 38100000.dwc3: request 00000000c6d191cd was not queued to ep2in
>>> [ 4827.358422] dwc3 38100000.dwc3: request 0000000085205409 was not queued to ep2in
>>> UVC: Stopping video stream.
>>>
>>> [ 4848.381718] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
>>> [ 4848.387824] rcu: 3-...0: (1 GPs behind) idle=162/1/0x4000000000000000 softirq=10819/10819 fqs=2356
>>> [ 4848.396956] (detected by 2, t=5252 jiffies, g=20129, q=3770)
>>> [ 4848.396959] Task dump for CPU 3:
>>> [ 4848.405925] task:uvc-gadget_wlhe state:R running task stack: 0 pid: 674 ppid: 636 flags:0x00000202
>>> [ 4848.415842] Call trace:
>>> [ 4848.418294] __switch_to+0xc0/0x170
>>> [ 4848.421785] _raw_spin_lock_irqsave+0x84/0xb0
>>> [ 4848.426143] composite_disconnect+0x28/0x78
>>> [ 4848.430327] configfs_composite_disconnect+0x68/0x70
>>> [ 4848.435290] usb_gadget_disconnect+0x10c/0x128
>>> [ 4848.439733] usb_gadget_deactivate+0xd4/0x108
>>> [ 4848.444089] usb_function_deactivate+0x6c/0x80
>>> [ 4848.448534] uvc_function_disconnect+0x20/0x58
>>> [ 4848.452976] uvc_v4l2_release+0x30/0x88
>>> [ 4848.456812] v4l2_release+0xbc/0xf0
>>> [ 4848.460301] __fput+0x7c/0x230
>>> [ 4848.463353] ____fput+0x14/0x20
>>> [ 4848.466495] task_work_run+0x88/0x140
>>> [ 4848.470157] do_notify_resume+0x240/0x6f0
>>> [ 4848.474166] work_pending+0x8/0x200
>> The reason for this seems to be that the usb_gadget_deactivate is being called with
>> spinlock held from the usb_function_deactivate and the same lock is being used
>> in the composite_disconnect (&cdev->lock).
>>
>> This should be able to resolve it.
>>
>> diff --git a/drivers/usb/gadget/composite.c b/drivers/usb/gadget/composite.c
>> index 05b176c82cc5..5fced737e4ef 100644
>> --- a/drivers/usb/gadget/composite.c
>> +++ b/drivers/usb/gadget/composite.c
>> @@ -392,8 +392,11 @@ int usb_function_deactivate(struct usb_function *function)
>>
>> spin_lock_irqsave(&cdev->lock, flags);
>>
>> - if (cdev->deactivations == 0)
>> + if (cdev->deactivations == 0) {
>> + spin_unlock_irqrestore(&cdev->lock, flags);
>> status = usb_gadget_deactivate(cdev->gadget);
>> + spin_lock_irqsave(&cdev->lock, flags);
>> + }
>> if (status == 0)
>> cdev->deactivations++;
>>
>> @@ -424,8 +427,11 @@ int usb_function_activate(struct usb_function *function)
>> status = -EINVAL;
>> else {
>> cdev->deactivations--;
>> - if (cdev->deactivations == 0)
>> + if (cdev->deactivations == 0) {
>> + spin_unlock_irqrestore(&cdev->lock, flags);
>> status = usb_gadget_activate(cdev->gadget);
>> + spin_lock_irqsave(&cdev->lock, flags);
>> + }
>> }
>>
>> spin_unlock_irqrestore(&cdev->lock, flags);
>>
> Thanks, Sriharsha. It fixed the kernel dump after video stream has
> stopped, I did not check the whole trace carefully, and not found this
> spin recursion issue. You could add my Tested-by for it. Meanwhile,
> this issue was reported before, and unlock at usb_function_activate
> could also fix the possible sleep at atomic context issue for dwc3.
>
> https://lore.kernel.org/linux-usb/20191115070122.GF30608@b29397-desktop/T/
Thanks for the testing and confirmation, will raise the patch soon.
Regards,
Sriharsha
>
--
The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2020-11-05 5:29 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-11-02 9:50 strange call stack when running uvc-gadget application Peter Chen
2020-11-03 6:20 ` Sriharsha Allenki
2020-11-04 10:05 ` Peter Chen
2020-11-05 5:29 ` Sriharsha Allenki
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).