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