Possible FIQ high speed isochronous transfer issue

[antonblanchard]

I have two USB webcams (a Logitech C270 and a Logitech QuickCam Pro 9000) and neither of them work on my Raspberry Pi 3 running either the 4.9 or 4.14 kernels.

I start up guvciew and the application prints an endless stream of:

V4L2_CORE: (get_v4l2_frame) video stream must be started first
V4L2_CORE: (get_v4l2_frame) video stream must be started first
V4L2_CORE: (get_v4l2_frame) video stream must be started first
V4L2_CORE: (get_v4l2_frame) video stream must be started first

and in the dmesg:

[  184.869874] usb 1-1.2: reset high-speed USB device number 4 using dwc_otg
[  187.657763] uvcvideo: Failed to set UVC probe control : -71 (exp. 26).
[  187.658183] uvcvideo: Failed to set UVC commit control : -71 (exp. 26).

If I kill and restart guvcview, both the webcam and the keyboard get reset:

[  208.147954] usb 1-1.2: USB disconnect, device number 4
[  208.247784] usb 1-1.2: new full-speed USB device number 8 using dwc_otg
[  208.347737] usb 1-1.2: device descriptor read/64, error -32
[  208.567739] usb 1-1.2: device descriptor read/64, error -32
[  208.787697] usb 1-1.2: new full-speed USB device number 9 using dwc_otg
[  208.887672] usb 1-1.2: device descriptor read/64, error -32
[  209.107689] usb 1-1.2: device descriptor read/64, error -32
[  209.227731] usb 1-1-port2: attempt power cycle
[  209.887624] usb 1-1.2: new high-speed USB device number 10 using dwc_otg
[  210.135972] usb 1-1.2: New USB device found, idVendor=046d, idProduct=0825
[  210.135983] usb 1-1.2: New USB device strings: Mfr=0, Product=0, SerialNumber=2
[  210.135988] usb 1-1.2: SerialNumber: B834B130
[  210.136520] uvcvideo: Found UVC 1.00 device <unnamed> (046d:0825)
[  210.226177] uvcvideo 1-1.2:1.0: Entity type for entity Extension 4 was not initialized!
[  210.226190] uvcvideo 1-1.2:1.0: Entity type for entity Extension 6 was not initialized!
[  210.226196] uvcvideo 1-1.2:1.0: Entity type for entity Extension 7 was not initialized!
[  210.226201] uvcvideo 1-1.2:1.0: Entity type for entity Processing 2 was not initialized!
[  210.226206] uvcvideo 1-1.2:1.0: Entity type for entity Extension 3 was not initialized!
[  210.226212] uvcvideo 1-1.2:1.0: Entity type for entity Camera 1 was not initialized!
[  210.226458] input: UVC Camera (046d:0825) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/input/input6
[  210.256390] usb 1-1.2: set resolution quirk: cval->res = 384
[  210.257178] usb 1-1.4: USB disconnect, device number 5
[  210.257190] usb 1-1.4.3: USB disconnect, device number 6
[  210.698020] usb 1-1.4.4: USB disconnect, device number 7
[  211.247528] usb 1-1.4: new full-speed USB device number 11 using dwc_otg
[  211.388420] usb 1-1.4: New USB device found, idVendor=04b3, idProduct=3016
[  211.388436] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  211.388445] usb 1-1.4: Product: USB 1.1 2 port downstream low-power hub
[  211.388453] usb 1-1.4: Manufacturer: Lite-On Tech
[  211.390591] hub 1-1.4:1.0: USB hub found
[  211.391153] hub 1-1.4:1.0: 4 ports detected
[  211.717498] usb 1-1.4.3: new low-speed USB device number 12 using dwc_otg
[  211.889044] usb 1-1.4.3: New USB device found, idVendor=04b3, idProduct=3019
[  211.889062] usb 1-1.4.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  211.889071] usb 1-1.4.3: Product: IBM USB Travel Keyboard with UltraNav
[  211.889079] usb 1-1.4.3: Manufacturer: Lite-On Tech
[  211.908362] input: Lite-On Tech IBM USB Travel Keyboard with UltraNav as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4.3/1-1.4.3:1.0/0003:04B3:3019.0005/input/input7
[  211.978313] hid-generic 0003:04B3:3019.0005: input,hidraw0: USB HID v1.00 Keyboard [Lite-On Tech IBM USB Travel Keyboard with UltraNav] on usb-3f980000.usb-1.4.3/input0
[  211.996875] input: Lite-On Tech IBM USB Travel Keyboard with UltraNav as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4.3/1-1.4.3:1.1/0003:04B3:3019.0006/input/input8
[  212.057884] hid-generic 0003:04B3:3019.0006: input,hidraw1: USB HID v1.00 Device [Lite-On Tech IBM USB Travel Keyboard with UltraNav] on usb-3f980000.usb-1.4.3/input1
[  212.157435] usb 1-1.4.4: new low-speed USB device number 13 using dwc_otg
[  212.317257] usb 1-1.4.4: New USB device found, idVendor=06cb, idProduct=0009
[  212.317266] usb 1-1.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  212.317271] usb 1-1.4.4: Product: Composite TouchPad / TrackPoint
[  212.317276] usb 1-1.4.4: Manufacturer: Synaptics Inc.
[  212.329039] input: Synaptics Inc. Composite TouchPad / TrackPoint as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4.4/1-1.4.4:1.0/0003:06CB:0009.0007/input/input9
[  212.329330] hid-generic 0003:06CB:0009.0007: input,hidraw2: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-3f980000.usb-1.4.4/input0
[  212.341553] input: Synaptics Inc. Composite TouchPad / TrackPoint as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4.4/1-1.4.4:1.1/0003:06CB:0009.0008/input/input10
[  212.341846] hid-generic 0003:06CB:0009.0008: input,hidraw3: USB HID v1.00 Mouse [Synaptics Inc. Composite TouchPad / TrackPoint] on usb-3f980000.usb-1.4.4/input1

So far I have found that disabling FIQ handling of high speed isochronous transfers fixes it:

dwc_otg.fiq_fsm_mask=0x3

I'll try and investigate it some more on the weekend.

[popcornmix]

Ping @P33M

[P33M]

I am sourcing an equivalent model webcam for me to test with.

@antonblanchard What command-line options are used with guvcview, if any?

[P33M]

Just running guvcview is enough to break communication with the camera. I appear to have seen a less bad version of breakage that results in the camera not responding to any requests on EP0 - Linux then gets unhappy and resets the device, but this has to happen several times before the camera starts responding again.

In the case where the camera is working, it appears to be streaming variable-length packets which implies that guvcview is by default configuring the cam for MJPEG/h.264. More investigation required...

[P33M]

OK it looks like whenever the camera format, framerate or resolution is changed (or stopped), the following happens:

• A SET_INTERFACE control transfer is initiated to interface 1 to set the alternate setting to 0 (i.e. disable streaming)
• An IN transfer to endpoint 1 (the streaming endpoint) occurs, presumably because the FIQ code is still crunching through the sequence of isochronous transfers
• The camera stops responding

Here's the interface descriptor in question:

    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           0
      bInterfaceClass        14 Video
      bInterfaceSubClass      2 Video Streaming
      bInterfaceProtocol      0
      iInterface              0

The interface has no endpoints when the altsetting is 0 (Isochronous endpoints aren't allowed on default altsettings) so issuing a transfer to a nonexistent endpoint makes the camera unhappy.

Edit: Linux is attempting to power cycle the port (2) which is the only one actually connected to the hub power control chip. The power control chip controls 5V to all downstream USB ports simultaneously. If you plug the webcam into any other port, it's likely that the keyboard resets will disappear.

[antonblanchard]

Thanks @P33M for looking into this! I am running guvcview without any arguments.

I was just about to report that moving the camera makes the reset of the keyboard go away, but you beat me to it.

[P33M]

The dequeue handling function in the FIQ is broken for isochronous transfers. It will immediately return, having kicked the URB off the transfer queues, but in the background the FIQ runs to completion which results in multiple outstanding transfers getting executed. I've even seen a case where URBs get killed -> next URB for endpoint gets queued -> URB gets killed which results in multiple transfers per microframe to the isochronous endpoint.

This is the stacktrace from when the URB gets dequeued immediately before the camera goes wonky:

[  158.560035] [<80760c7c>] (dump_stack) from [<805b9f04>] (dwc_otg_hcd_urb_dequeue+0xc0/0x1e8)
[  158.560042] [<805b9f04>] (dwc_otg_hcd_urb_dequeue) from [<805bd86c>] (dwc_otg_urb_dequeue+0x60/0xbc)
[  158.560051] [<805bd86c>] (dwc_otg_urb_dequeue) from [<8058ec10>] (unlink1+0x3c/0x124)
[  158.560058] [<8058ec10>] (unlink1) from [<80590cd0>] (usb_hcd_unlink_urb+0x60/0x94)
[  158.560065] [<80590cd0>] (usb_hcd_unlink_urb) from [<80591f9c>] (usb_kill_urb+0x68/0xe4)
[  158.560084] [<80591f9c>] (usb_kill_urb) from [<7f1d05c0>] (uvc_uninit_video+0x60/0x90 [uvcvideo])
[  158.560113] [<7f1d05c0>] (uvc_uninit_video [uvcvideo]) from [<7f1d2aa8>] (uvc_video_enable+0x28/0x148 [uvcvideo])
[  158.560144] [<7f1d2aa8>] (uvc_video_enable [uvcvideo]) from [<7f1cddfc>] (uvc_stop_streaming+0x28/0x50 [uvcvideo])
[  158.560170] [<7f1cddfc>] (uvc_stop_streaming [uvcvideo]) from [<7f163130>] (__vb2_queue_cancel+0x38/0x18c [videobuf2_core])
[  158.560192] [<7f163130>] (__vb2_queue_cancel [videobuf2_core]) from [<7f16381c>] (vb2_core_streamoff+0x44/0xac [videobuf2_core])
[  158.560212] [<7f16381c>] (vb2_core_streamoff [videobuf2_core]) from [<7f17a2a8>] (vb2_streamoff+0x40/0x60 [videobuf2_v4l2])
[  158.560235] [<7f17a2a8>] (vb2_streamoff [videobuf2_v4l2]) from [<7f1ce2d8>] (uvc_queue_streamoff+0x34/0x48 [uvcvideo])
[  158.560265] [<7f1ce2d8>] (uvc_queue_streamoff [uvcvideo]) from [<7f1cf3f4>] (uvc_ioctl_streamoff+0x40/0x58 [uvcvideo])
[  158.560320] [<7f1cf3f4>] (uvc_ioctl_streamoff [uvcvideo]) from [<7f0b5d98>] (v4l_streamoff+0x2c/0x30 [videodev])
[  158.560401] [<7f0b5d98>] (v4l_streamoff [videodev]) from [<7f0ba3e0>] (__video_do_ioctl+0x2bc/0x318 [videodev])
[  158.560482] [<7f0ba3e0>] (__video_do_ioctl [videodev]) from [<7f0b9cdc>] (video_usercopy+0x1b8/0x5dc [videodev])
[  158.560564] [<7f0b9cdc>] (video_usercopy [videodev]) from [<7f0ba120>] (video_ioctl2+0x20/0x24 [videodev])
[  158.560645] [<7f0ba120>] (video_ioctl2 [videodev]) from [<7f0b4720>] (v4l2_ioctl+0xd0/0xe8 [videodev])
[  158.560691] [<7f0b4720>] (v4l2_ioctl [videodev]) from [<8029e1ac>] (do_vfs_ioctl+0xb0/0x7c8)
[  158.560699] [<8029e1ac>] (do_vfs_ioctl) from [<8029e908>] (SyS_ioctl+0x44/0x6c)
[  158.560706] [<8029e908>] (SyS_ioctl) from [<80107fc0>] (ret_fast_syscall+0x0/0x28)

uvc_uninit_video() performs a loop over kill_urb() and free_urb() which is a blocking call. This bug was probably introduced as a result of hardening the dequeue mechanisms against NULL pointer crashes as a result of root port disconnects.

The annoying thing is that synchronising the state of the hardware isn't going to be easy - periodic channels transmit their requests one microframe after you enable them and force-disabling the channel rarely works.

[P33M]

With the linked commit applied, I can spam click framerate changes (that induce endpoint altsetting changes) and guvcview still works - albeit at 3fps due to trying to software-decode and preview a 720p30/25 MJPEG stream. I'll update the issue when an rpi-update firmware is available for testing.

[P33M]

@antonblanchard can you run rpi-update and test?

[antonblanchard]

@P33M I ran rpi-update, and I can confirm the issue has gone away. Thanks for fixing this!