Hi, Just to give you an update. All is working great, the cause was an FPGA configuration issue. Thank you for your support. Joao On 5/19/2016 4:42 PM, Joao Pinto wrote: > > 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
