strange call stack when running uvc-gadget application

Peter Chen

author

2020-11-02 09:50 UTC #0 lore raw

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

Signature · 2 lines

Thanks,
Peter Chen

Sriharsha Allenki

2020-11-03 13:28 UTC #1 lore raw

Hi Peter,

Quoted 36 lines · Peter Chen

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

Quoted 8 lines

[ 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.

drivers/usb/gadget/composite.c +0 -0

index 05b176c82cc5..5fced737e4ef 100644
@@ -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

Quoted 1 line

Signature · 2 lines

The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Peter Chen

author

2020-11-04 10:05 UTC #2 lore raw

Quoted 74 lines · Sriharsha Allenki

Hi Peter,

Quoted 36 lines · Peter Chen

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

Quoted 8 lines

[ 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.

drivers/usb/gadget/composite.c +4 -1

index 05b176c82cc5..5fced737e4ef 100644
@@ -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 {

drivers/usb/gadget/composite.c int usb_function_activate(struct usb_function *function) · line 437

Quoted 10 lines

drivers/usb/gadget/composite.c +4 -1

                 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/

Signature · 2 lines

Thanks,
Peter Chen

Sriharsha Allenki

2020-11-05 05:29 UTC #3 lore raw

Hi Peter,

Quoted 91 lines · Peter Chen

Quoted 74 lines · Sriharsha Allenki

Hi Peter,

Quoted 36 lines · Peter Chen

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

Quoted 8 lines

[ 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.

drivers/usb/gadget/composite.c +4 -1

index 05b176c82cc5..5fced737e4ef 100644
@@ -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 {

drivers/usb/gadget/composite.c int usb_function_activate(struct usb_function *function) · line 437

Quoted 10 lines

drivers/usb/gadget/composite.c +4 -1

                 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.

Quoted 1 line

https://lore.kernel.org/linux-usb/20191115070122.GF30608@b29397-desktop/T/

Thanks for the testing and confirmation, will raise the patch soon.

Regards,
Sriharsha

Quoted 1 line

Signature · 2 lines

The Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project