After a few moments the schedule problem happen again:
# INFO: task kworker/0:1:349 blocked for more than 120 seconds.
Not tainted 4.6.0-rc5 #9
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1 D ffffff8008086c60 0 349 2 0x00000000
Workqueue: usb_hub_wq hub_event
Call trace:
[<ffffff8008086c60>] __switch_to+0xc8/0xd4
[<ffffff8008638774>] __schedule+0x18c/0x5c8
[<ffffff8008638be8>] schedule+0x38/0x98
[<ffffff800863b71c>] schedule_timeout+0x160/0x1ac
[<ffffff8008639714>] wait_for_common+0xac/0x150
[<ffffff80086397cc>] wait_for_completion+0x14/0x1c
[<ffffff8008489998>] xhci_alloc_dev+0xf4/0x2a0
[<ffffff800844ffd0>] usb_alloc_dev+0x68/0x2cc
[<ffffff800845696c>] hub_event+0x784/0x11f4
[<ffffff80080ce444>] process_one_work+0x130/0x2f4
[<ffffff80080ce65c>] worker_thread+0x54/0x434
[<ffffff80080d40fc>] kthread+0xd4/0xe8
[<ffffff8008085e10>] ret_from_fork+0x10/0x40
INFO: task kworker/0:1:349 blocked for more than 120 seconds.
Not tainted 4.6.0-rc5 #9
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1 D ffffff8008086c60 0 349 2 0x00000000
Workqueue: usb_hub_wq hub_event
Call trace:
[<ffffff8008086c60>] __switch_to+0xc8/0xd4
[<ffffff8008638774>] __schedule+0x18c/0x5c8
[<ffffff8008638be8>] schedule+0x38/0x98
[<ffffff800863b71c>] schedule_timeout+0x160/0x1ac
[<ffffff8008639714>] wait_for_common+0xac/0x150
[<ffffff80086397cc>] wait_for_completion+0x14/0x1c
[<ffffff8008489998>] xhci_alloc_dev+0xf4/0x2a0
[<ffffff800844ffd0>] usb_alloc_dev+0x68/0x2cc
[<ffffff800845696c>] hub_event+0x784/0x11f4
[<ffffff80080ce444>] process_one_work+0x130/0x2f4
[<ffffff80080ce65c>] worker_thread+0x54/0x434
[<ffffff80080d40fc>] kthread+0xd4/0xe8
[<ffffff8008085e10>] ret_from_fork+0x10/0x40
So Chris' patch did not solve this problem either.
Thanks.
On 5/19/2016 4:39 PM, Joao Pinto wrote:
> Hi Felipe and Mathias,
>
> On 5/19/2016 1:22 PM, Mathias Nyman wrote:
>> On 19.05.2016 14:23, Joao Pinto wrote:
>>> Hi Felipe,
>>>
>>> On 5/19/2016 11:32 AM, Felipe Balbi wrote:
>>>>
>>>> Hi,
>>>>
>>>>
>>>> Note that we really did get a command timeout. Can you add a little
>>>> extra debugging to try and figure out why that command failed?
>>>>
>>>
>>> After instrumenting and capturing FPGA signals, the driver could go a bit
>>> further... Could this be a FPGA timming issue?
>>>
>> ..
>>
>>> xhci-hcd xhci-hcd.0.auto: Timeout while waiting for setup device command
>>> usb 3-1: hub failed to enable device, error -62
>>> xhci-hcd xhci-hcd.0.auto: Endpoint 0x0 ep reset callback called
>>> xhci-hcd xhci-hcd.0.auto: xHCI dying or halted, can't queue_command
>>> xhci-hcd xhci-hcd.0.auto: FIXME: allocate a command ring segment
>>> usb usb3-port1: couldn't allocate usb_device
>>>
>>> Joao
>>
>> Does the patch from Chris Bainbridge help?
>> It's currently only Gregs tree in the usb-next branch.
>>
>> It fixes a locking issue where hw can't handle several ports being in default
>> state at
>> the same time, and setup device command timeout issue when both usb2 and usb3
>> devices
>> try to enumerate at the same time.
>>
>> commit feb26ac31a2a5cb88d86680d9a94916a6343e9e6
>> usb: core: hub: hub_port_init lock controller instead of bus
>
> Applied Chris' patch and apparently solved the cyclic crash problem that
> happened every time the wait completion timeout and context had to change. But
> the log after insert pen drive remains the same:
>
> xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 1
> xhci-hcd xhci-hcd.0.auto: resume root hub
> xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling.
> xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x206e1
> xhci-hcd xhci-hcd.0.auto: Get port status returned 0x10101
> xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x6e1
> xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x6e1
> xhci-hcd xhci-hcd.0.auto: Get port status returned 0x101
> xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling.
> xhci-hcd xhci-hcd.0.auto: // Ding dong!
> xhci-hcd xhci-hcd.0.auto: Command timeout
> xhci-hcd xhci-hcd.0.auto: Abort command ring
>
>
> It worked a bit a few hours ago like I tiold you in a past e-mail:
> After instrumenting and capturing FPGA signals, the driver could go a bit
> further... Could this be a FPGA timming issue?
>
>
> xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 1
> xhci-hcd xhci-hcd.0.auto: resume root hub
> xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling.
> xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x206e1
> xhci-hcd xhci-hcd.0.auto: Get port status returned 0x10101
> xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x6e1
> xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling.
> xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x6e1
> xhci-hcd xhci-hcd.0.auto: Get port status returned 0x101
> xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling.
> xhci-hcd xhci-hcd.0.auto: // Ding dong!
> xhci-hcd xhci-hcd.0.auto: Slot 1 output ctx = 0x9f5d64000 (dma)
> xhci-hcd xhci-hcd.0.auto: Slot 1 input ctx = 0x9f5d68000 (dma)
> xhci-hcd xhci-hcd.0.auto: Set slot id 1 dcbaa entry ffffff800807c008 to 0x9f5d64000
> xhci-hcd xhci-hcd.0.auto: set port reset, actual port 0 status = 0x6f1
> xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x200e03
> xhci-hcd xhci-hcd.0.auto: Get port status returned 0x100503
> xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0xe03
> usb 3-1: new high-speed USB device number 2 using xhci-hcd
> xhci-hcd xhci-hcd.0.auto: Set root hub portnum to 1
> xhci-hcd xhci-hcd.0.auto: Set fake root hub portnum to 1
> xhci-hcd xhci-hcd.0.auto: udev->tt = (null)
> xhci-hcd xhci-hcd.0.auto: udev->ttport = 0x0
> xhci-hcd xhci-hcd.0.auto: Slot ID 1 Input Context:
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd000 (virt) @9f5d68000 (dma) 0x000000 -
> drop flags
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd004 (virt) @9f5d68004 (dma) 0x000003 -
> add flags
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd008 (virt) @9f5d68008 (dma) 0x000000 -
> rsvd2[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd00c (virt) @9f5d6800c (dma) 0x000000 -
> rsvd2[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd010 (virt) @9f5d68010 (dma) 0x000000 -
> rsvd2[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd014 (virt) @9f5d68014 (dma) 0x000000 -
> rsvd2[3]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd018 (virt) @9f5d68018 (dma) 0x000000 -
> rsvd2[4]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd01c (virt) @9f5d6801c (dma) 0x000000 -
> rsvd2[5]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd020 (virt) @9f5d68020 (dma) 0x000000 -
> rsvd64[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd028 (virt) @9f5d68028 (dma) 0x000000 -
> rsvd64[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd030 (virt) @9f5d68030 (dma) 0x000000 -
> rsvd64[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd038 (virt) @9f5d68038 (dma) 0x000000 -
> rsvd64[3]
> xhci-hcd xhci-hcd.0.auto: Slot Context:
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd040 (virt) @9f5d68040 (dma) 0x8300000 -
> dev_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd044 (virt) @9f5d68044 (dma) 0x010000 -
> dev_info2
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd048 (virt) @9f5d68048 (dma) 0x000000 -
> tt_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd04c (virt) @9f5d6804c (dma) 0x000000 -
> dev_state
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd050 (virt) @9f5d68050 (dma) 0x000000 -
> rsvd[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd054 (virt) @9f5d68054 (dma) 0x000000 -
> rsvd[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd058 (virt) @9f5d68058 (dma) 0x000000 -
> rsvd[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd05c (virt) @9f5d6805c (dma) 0x000000 -
> rsvd[3]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd060 (virt) @9f5d68060 (dma) 0x000000 -
> rsvd64[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd068 (virt) @9f5d68068 (dma) 0x000000 -
> rsvd64[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd070 (virt) @9f5d68070 (dma) 0x000000 -
> rsvd64[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd078 (virt) @9f5d68078 (dma) 0x000000 -
> rsvd64[3]
> xhci-hcd xhci-hcd.0.auto: IN Endpoint 00 Context (ep_index 00):
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd080 (virt) @9f5d68080 (dma) 0x000000 -
> ep_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd084 (virt) @9f5d68084 (dma) 0x400026 -
> ep_info2
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd088 (virt) @9f5d68088 (dma) 0x9f5d66001
> - deq
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd090 (virt) @9f5d68090 (dma) 0x000000 -
> tx_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd094 (virt) @9f5d68094 (dma) 0x000000 -
> rsvd[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd098 (virt) @9f5d68098 (dma) 0x000000 -
> rsvd[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd09c (virt) @9f5d6809c (dma) 0x000000 -
> rsvd[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0a0 (virt) @9f5d680a0 (dma) 0x000000 -
> rsvd64[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0a8 (virt) @9f5d680a8 (dma) 0x000000 -
> rsvd64[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0b0 (virt) @9f5d680b0 (dma) 0x000000 -
> rsvd64[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0b8 (virt) @9f5d680b8 (dma) 0x000000 -
> rsvd64[3]
> xhci-hcd xhci-hcd.0.auto: OUT Endpoint 01 Context (ep_index 01):
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0c0 (virt) @9f5d680c0 (dma) 0x000000 -
> ep_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0c4 (virt) @9f5d680c4 (dma) 0x000000 -
> ep_info2
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0c8 (virt) @9f5d680c8 (dma) 0x000000 - deq
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0d0 (virt) @9f5d680d0 (dma) 0x000000 -
> tx_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0d4 (virt) @9f5d680d4 (dma) 0x000000 -
> rsvd[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0d8 (virt) @9f5d680d8 (dma) 0x000000 -
> rsvd[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0dc (virt) @9f5d680dc (dma) 0x000000 -
> rsvd[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0e0 (virt) @9f5d680e0 (dma) 0x000000 -
> rsvd64[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0e8 (virt) @9f5d680e8 (dma) 0x000000 -
> rsvd64[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0f0 (virt) @9f5d680f0 (dma) 0x000000 -
> rsvd64[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd0f8 (virt) @9f5d680f8 (dma) 0x000000 -
> rsvd64[3]
> xhci-hcd xhci-hcd.0.auto: IN Endpoint 01 Context (ep_index 02):
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd100 (virt) @9f5d68100 (dma) 0x000000 -
> ep_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd104 (virt) @9f5d68104 (dma) 0x000000 -
> ep_info2
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd108 (virt) @9f5d68108 (dma) 0x000000 - deq
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd110 (virt) @9f5d68110 (dma) 0x000000 -
> tx_info
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd114 (virt) @9f5d68114 (dma) 0x000000 -
> rsvd[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd118 (virt) @9f5d68118 (dma) 0x000000 -
> rsvd[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd11c (virt) @9f5d6811c (dma) 0x000000 -
> rsvd[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd120 (virt) @9f5d68120 (dma) 0x000000 -
> rsvd64[0]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd128 (virt) @9f5d68128 (dma) 0x000000 -
> rsvd64[1]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd130 (virt) @9f5d68130 (dma) 0x000000 -
> rsvd64[2]
> xhci-hcd xhci-hcd.0.auto: @ffffff8008acd138 (virt) @9f5d68138 (dma) 0x000000 -
> rsvd64[3]
> xhci-hcd xhci-hcd.0.auto: // Ding dong!
> xhci-hcd xhci-hcd.0.auto: Command timeout
> xhci-hcd xhci-hcd.0.auto: Abort command ring
> xhci-hcd xhci-hcd.0.auto: Stopped the command ring failed, maybe the host is dead
> xhci-hcd xhci-hcd.0.auto: // Halt the HC
> xhci-hcd xhci-hcd.0.auto: Host not halted after 16000 microseconds.
> xhci-hcd xhci-hcd.0.auto: Abort command ring failed
> xhci-hcd xhci-hcd.0.auto: HC died; cleaning up
> xhci-hcd xhci-hcd.0.auto: xHCI host controller is dead.
> xhci-hcd xhci-hcd.0.auto: Timeout while waiting for setup device command
> usb 3-1: hub failed to enable device, error -62
> xhci-hcd xhci-hcd.0.auto: Endpoint 0x0 ep reset callback called
> xhci-hcd xhci-hcd.0.auto: xHCI dying or halted, can't queue_command
> xhci-hcd xhci-hcd.0.auto: FIXME: allocate a command ring segment
> usb usb3-port1: couldn't allocate usb_device
>
> Any thoughts?
>
>>
>> -Mathias
>>
>
> Thanks!
>
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
