Hi,
Patrice CHOTARD <patrice.chotard@xxxxxx> writes:
>>>>>>>>> I am working on ARM STi platform, since v4.10-rc1, when booting
>>>>>>>>> B2260 or B2120 STi boards platform
>>>>>>>>> with nothing plugged on USB3 connector, i observed the following
>>>>>>>>> kernel logs :
>>>>>>>>>
>>>>>>>>> ....
>>>>>>>>> [ 801.953836] usb usb6-port1: Cannot enable. Maybe the USB
>>>>>>>>> cable is bad?
>>>>>>>>
>>>>>>>> That's odd, why does it try to reset the port if there's nothing
>>>>>>>> there?
>>>>>>>>
>>>>>>>>> [ 801.960455] xhci-hcd xhci-hcd.0.auto: Cannot set link state.
>>>>>>>>
>>>>>>>> This makes sense, nothing is connected, and we try to set link to
>>>>>>>> U3 (PORT_PE == 0)
>>>>>>>>
>>>>>>>>> [ 801.966611] usb usb6-port1: cannot disable (err = -32)
>>>>>>>> xhci reutns -EPIPE as we try to set link state to U3 while port
>>>>>>>> is not enabled (PORT_PE == 0)
>>>>>>>>
>>>>>>>>> [ 806.083772] usb usb6-port1: Cannot enable. Maybe the USB
>>>>>>>>> cable is bad?
>>>>>>>>
>>>>>>>> Again, about 5 seconds later the same port is reset, while
>>>>>>>> nothing is connected.
>>>>>>>> Odd
>>>>>>>>
>>>>>>>>> [ 806.090370] xhci-hcd xhci-hcd.0.auto: Cannot set link state.
>>>>>>>>> [ 806.096494] usb usb6-port1: cannot disable (err = -32)
>>>>>>>>> [ 810.208766] usb usb6-port1: Cannot enable. Maybe the USB
>>>>>>>>> cable is bad?
>>>>>>>>> [ 810.215374] xhci-hcd xhci-hcd.0.auto: Cannot set link state.
>>>>>>>>> [ 810.221478] usb usb6-port1: cannot disable (err = -32)
>>>>>>>>> [ 814.333767] usb usb6-port1: Cannot enable. Maybe the USB
>>>>>>>>> cable is bad?
>>>>>>>>> [ 814.340364] xhci-hcd xhci-hcd.0.auto: Cannot set link state.
>>>>>>>>> .....
>>>>>>>>>
>>>>>>>>> Another interesting thing is even if i plugged a device (a mass
>>>>>>>>> storage device in my case) on the USB3 connector,
>>>>>>>>> the above logs continue to appear.
>>>>>>>>>
>>>>>>>>> This is due to commit 37be66767e3ca "usb: hub: Fix auto-remount
>>>>>>>>> of safely removed or ejected USB-3 devices".
>>>>>>>>>
>>>>>>>>> I don't know if STi platforms are the only impacted by this issue.
>>>>>>>>>
>>>>>>>>> On v4.9 everything was ok.
>>>>>>>>>
>>>>>>>>
>>>>>>>> Was there not a single "Cannot enable. Maybe USB cable is bad"
>>>>>>>> message with 4.9?
>>>>>>>
>>>>>>> There is no "Cannot enable. Maybe USB cable is bad" message with 4.9
>>>>>>>
>>>>>>>>
>>>>>>>> Before commit 37be66767e3ca we forced the port to RxDetect state
>>>>>>>> via Disabled state,
>>>>>>>> and cleared port change flags when a usb3_port_disable() was called.
>>>>>>>>
>>>>>>>> after we just set the port to U3. Maybe those STi platforms
>>>>>>>> depend on that cycle somehow?
>>>>>>>
>>>>>>> I really don't know :-(
>>>>>>>
>>>>>>>>
>>>>>>>> Could you take logs (dmesg) of both 4.9 and 4.10-rc1 with both
>>>>>>>> usb core and xhci debugging enabled:
>>>>>>>>
>>>>>>>> echo -n 'module xhci_hcd =p' >
>>>>>>>> /sys/kernel/debug/dynamic_debug/control
>>>>>>>> echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
>>>>>>>
>>>>>>>
>>>>>>> You will find below the 2 requested logs, in both case , no USB
>>>>>>> cable are plugged.
>>>>>>>
>>>>>>> v4.9 dmesg logs :
>>>>>>>
>>>>>>> .....
>>>>>>> [ 31.368022] hub 6-0:1.0: hub_resume
>>>>>>> [ 31.368064] xhci-hcd xhci-hcd.0.auto: get port status, actual
>>>>>>> port 0 status = 0x400340
>>>>>>> [ 31.368071] xhci-hcd xhci-hcd.0.auto: Get port status returned
>>>>>>> 0x400340
>>>>>>> [ 31.368224] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0000
>>>>>>
>>>>>> Looks like port is stuck in Compliance mode, this should only
>>>>>> happen if a connect was detected,
>>>>>> moving the port from RxDetect to Polling, and then timeout on
>>>>>> polling to get to compliance.
>>>>>>
>>>>>> 4.9 is then stuck in a hub_suspend/resume loop with a port in
>>>>>> compliance mode.
>>>>>>>
>>>>>>>
>>>>>>> v4.10-rc1 dmesg logs :
>>>>>>>
>>>>>>> ....
>>>>>>> [ 269.436617] usb usb6-port1: cannot disable (err = -32)
>>>>>>> [ 269.464728] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002
>>>>>>> [ 269.464756] xhci-hcd xhci-hcd.0.auto: get port status, actual
>>>>>>> port 0 status = 0x340
>>>>>>
>>>>>> I 4.10-rc1 we are again stuck in Compliance mode, but this time
>>>>>> there was a event (00002) visible, maybe because
>>>>>> the flags were not cleared or some other reason. Now are stuck in a
>>>>>> port reset loop with the
>>>>>> port in compliance mode.
>>>>>> So the real question is why is the port in compliance mode when
>>>>>> there are no devices connected.?
>>>>>>
>>>>>> I'll continue looking at this more tomorrow
>>>>>
>>>>> So with both 4.9 and 4.10-rc the ports are in Compliance mode state,
>>>>> even if nothing is connected
>>>>> To me this looks like the real underlying issue. For some reason it
>>>>> didn't try to reset the port in 4.9,
>>>>> and never got to the loop of port reset.
>>>>>
>>>>> In 4.9 the hub->events_bits[0] are not set, so the hub thread won't
>>>>> even ask for port status
>>>>> on any ports.
>>>>>
>>>>> In 4.10-rc the hub->events_bits[0] is set for port 1, It will start
>>>>> handling port events, see the
>>>>> compliance state and try to warm reset the port, and fail as it
>>>>> never sees port
>>>>>
>>>>> Any chance you could add extra debugging to xhci to show why the
>>>>> change bit is set?
>>>>> Something like this:
>>>>>
>>>>> diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
>>>>> index 0ef1690..e425d82 100644
>>>>> --- a/drivers/usb/host/xhci-hub.c
>>>>> +++ b/drivers/usb/host/xhci-hub.c
>>>>> @@ -1271,6 +1271,10 @@ int xhci_hub_status_data(struct usb_hcd *hcd,
>>>>> char *buf)
>>>>> jiffies, bus_state->resume_done[i]))) {
>>>>> buf[(i + 1) / 8] |= 1 << (i + 1) % 8;
>>>>> status = 1;
>>>>> + xhci_err(xhci, "portsc 0x%x,
>>>>> port_c_suspend:%d, resume_done:%d\n",
>>>>> + temp,
>>>>> + bus_state->port_c_suspend,
>>>>> + bus_state->resume_done[i]);
>>>>> }
>>>>> if ((temp & PORT_RC))
>>>>> reset_change = true;
>>>>>
>>>>>
>>>>> and run with 4.9 and 4.10-rc
>>>>>
>>>>> -Mathias
>>>>
>>>>
>>>> Hi Mathias
>>>>
>>>> Thanks for your time
>>>>
>>>> For information i replaced xhci_err() by xhci_dbg() to avoid flooding
>>>> kernel log which
>>>> avoid to complete the kernel boot.
>>>>
>>>> Please find attached both kernel log files for v4.9 and v4.10-rc1.
>>>>
>>>> In v4.9_xhci-hub_additionnal_debug.txt, at the beginning of the trace
>>>> portsc value is 0xa400340, then at [ 18.366392] it becomes 0x400340
>>>> (link state change) and then 0x2802a0 and back again to 0xa400340
>>>>
>>>> In v4.10-rc1_xhci-hub_additionnal_debug.txt, at the beginning of the
>>>> trace
>>>> portsc value is 0xa400340, then at [ 5.557976] it becomes 0x400340
>>>> (link state change), and then 0x2802a0 or 0x680340 for ever ....
>>>>
>>>> Patrice
>>>>
>>>
>>> Hi Mathias
>>>
>>> Did new logs give you some clue about the XHCi problem ?
>>>
>>
>> Only that both cases, 4.9 and 4.10, start with port in compliance state
>> in a
>> auto suspend/resume. At some point the hub thread will see an event for
>> that
>> port and try to reset it. fail (as there is no device) and disable the
>> port.
>>
>>
>> log snippet of busylooping between autosuspend and resume, similar for
>> both 4.9 and
>> 4.10:
>>
>> [ 18.329121] hub 6-0:1.0: hub_suspend
>> [ 18.329175] usb usb6: bus auto-suspend, wakeup 1
>> [ 18.329193] xhci-hcd xhci-hcd.0.auto: portsc 0xa400340,
>> port_c_suspend:0, resume_done:0
>> [ 18.329202] usb usb6: suspend raced with wakeup event
>> [ 18.329209] usb usb6: usb auto-resume
>> [ 18.332758] xhci-hcd xhci-hcd.0.auto: portsc 0xa400340,
>> port_c_suspend:0, resume_done:0
>> [ 18.344140] hub 6-0:1.0: hub_resume
>> [ 18.344179] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x400340
>> [ 18.344191] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340
>> [ 18.344318] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0000
>> [ 18.344368] xhci-hcd xhci-hcd.0.auto: set port remote wake mask,
>> actual port 0 status = 0xe400340
>> [ 18.344451] hub 6-0:1.0: hub_suspend
>>
>>
>> In 4.9 we go back to the beginning, busylooping between auto suspend and
>> resume,
>> until after some random time when hub sees an event again, and continues
>> all over again.
>>
>> log snippet of event, and resetting the port for 4.9:
>>
>> [ 18.367378] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002
>> [ 18.367417] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x400340
>> [ 18.367426] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340
>> [ 18.367805] usb usb6-port1: link state change
>> [ 18.367846] xhci-hcd xhci-hcd.0.auto: clear port link state change,
>> actual port 0 status = 0x340
>> [ 18.367943] usb usb6-port1: do warm reset
>> [ 18.368043] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
>> [ 18.428313] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2b0
>> [ 18.428330] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2b0
>> [ 18.428475] usb usb6-port1: not warm reset yet, waiting 50ms
>> [ 18.468135] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for
>> port 2
>> [ 18.468155] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting
>> port polling.
>> [ 18.468167] xhci-hcd xhci-hcd.0.auto: portsc 0x2802a0,
>> port_c_suspend:0, resume_done:0
>> [ 18.487840] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2802e0
>> [ 18.487855] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0
>> [ 18.488636] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual
>> port 0 status = 0x802e0
>> [ 18.488736] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset
>> change, actual port 0 status = 0x2e0
>> [ 18.488803] xhci-hcd xhci-hcd.0.auto: clear port link state change,
>> actual port 0 status = 0x2e0
>> [ 18.488869] xhci-hcd xhci-hcd.0.auto: clear port connect change,
>> actual port 0 status = 0x2e0
>> [ 18.489012] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2e0
>> [ 18.489026] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2e0
>> [ 18.489112] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2e0
>> [ 18.489122] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2e0
>> [ 18.489182] xhci-hcd xhci-hcd.0.auto: Disable port 0
>> [ 18.489239] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x280
>> [ 18.489247] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x280
>> [ 18.489296] xhci-hcd xhci-hcd.0.auto: Enable port 0
>> [ 18.489357] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002
>> [ 18.489386] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2a0
>> [ 18.489395] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2a0
>> [ 18.489489] xhci-hcd xhci-hcd.0.auto: set port remote wake mask,
>> actual port 0 status = 0xe0002a0
>> [ 18.489547] hub 6-0:1.0: hub_suspend
>> [ 18.489606] usb usb6: bus auto-suspend, wakeup 1
>> [ 18.489624] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping
>> port polling.
>> [ 18.522772] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping
>> port polling.
>> [ 18.543748] Link is Up - 1000/Full
>> [ 18.863014] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for
>> port 2
>> [ 18.863033] xhci-hcd xhci-hcd.0.auto: resume root hub
>> [ 18.863073] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting
>> port polling.
>> [ 18.863089] xhci-hcd xhci-hcd.0.auto: portsc 0xa400340,
>> port_c_suspend:0, resume_done:0
>> [ 18.863333] usb usb6: usb wakeup-resume
>> [ 18.863355] usb usb6: usb auto-resume
>> [ 18.863379] hub 6-0:1.0: hub_resume
>> [ 18.863410] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x400340
>> [ 18.863419] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340
>>
>> In 4.10 the port disable is a bit different, so after hub sees the first
>> event (evt 0002) and tries to
>> reset the port, it will notice the reset fails, and try to reset port
>> several timer, then disable device,
>> which will end up with another event (evt 0002) and we start the whole
>> reset loop again.
>>
>> [ 5.558058] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002
>> [ 5.558093] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x400340
>> [ 5.558103] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340
>> [ 5.558187] usb usb6-port1: link state change
>> [ 5.558221] xhci-hcd xhci-hcd.0.auto: clear port link state change,
>> actual port 0 status = 0x340
>> [ 5.558278] usb usb6-port1: do warm reset
>> [ 5.558437] systemd-journald[108]: /dev/kmsg buffer overrun, some
>> messages lost.
>> [ 5.623028] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2b0
>> [ 5.623046] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2b0
>> [ 5.623134] usb usb6-port1: not warm reset yet, waiting 50ms
>> [ 5.658454] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for
>> port 2
>> [ 5.658471] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting
>> port polling.
>> [ 5.658487] xhci-hcd xhci-hcd.0.auto: portsc 0x2802a0,
>> port_c_suspend:0, resume_done:0
>> [ 5.683071] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2802e0
>> [ 5.683088] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0
>> [ 5.683187] usb usb6-port1: not warm reset yet, waiting 200ms
>> [ 5.777987] xhci-hcd xhci-hcd.0.auto: portsc 0x2802e0,
>> port_c_suspend:0, resume_done:0
>> [ 5.894043] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2802e0
>> [ 5.894061] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0
>> [ 5.894158] usb usb6-port1: not warm reset yet, waiting 200ms
>> [ 6.027992] xhci-hcd xhci-hcd.0.auto: portsc 0x2802e0,
>> port_c_suspend:0, resume_done:0
>> [ 6.103092] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x680340
>> [ 6.103110] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340
>> [ 6.103238] usb usb6-port1: not warm reset yet, waiting 200ms
>> [ 6.277993] xhci-hcd xhci-hcd.0.auto: portsc 0x680340,
>> port_c_suspend:0, resume_done:0
>> [ 6.313066] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x680340
>> [ 6.313085] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340
>> [ 6.313349] usb usb6-port1: not warm reset yet, waiting 200ms
>> [ 6.313385] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual
>> port 0 status = 0x480340
>> [ 6.313464] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset
>> change, actual port 0 status = 0x400340
>> [ 6.313523] xhci-hcd xhci-hcd.0.auto: clear port link state change,
>> actual port 0 status = 0x340
>> [ 6.313587] xhci-hcd xhci-hcd.0.auto: clear port connect change,
>> actual port 0 status = 0x340
>> [ 6.313651] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x340
>> [ 6.313665] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340
>> ..loop a few times, until
>> [ 9.673761] usb usb6-port1: not enabled, trying warm reset again...
>> [ 9.673771] usb usb6-port1: Cannot enable. Maybe the USB cable is bad?
>> [ 9.680418] xhci-hcd xhci-hcd.0.auto: Cannot set link state.
>> [ 9.722276] usb usb6-port1: cannot disable (err = -32)
>> [ 9.754240] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002
>> [ 9.754291] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x340
>> [ 9.754304] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340
>> [ 9.754419] usb usb6-port1: do warm reset
>> [ 9.782987] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping
>> port polling.
>> [ 9.813087] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0
>> status = 0x2b0
>>
>>
>> We could try things like clearing all port change flags in ports
>> disable, and/or only move ports
>> in xhci enabled state to U3 at port disable, from other states we would
>> do like in 4.9, and
>> move to RxDetect via disable.
>>
>> But this would not really solve the STi case, it would at best go back
>> to 4.9 where the issue is
>> better hidden and silently stay in the autosuspend/resume busyloop with
>> port in Compliance mode.
>>
>> You really should focus on why the port link state is in compliance in
>> the first place.
>>
>> -Mathias
>
> Hi Mathias
>
> +Felipe Balbi
>
> I did further test on previous kernel release.
> On v4.7, everything was ok , first issue appeared with v4.8-rc1 kernel.
>
> After bisection, the issue was introduced by
> c499ff71ff usb: dwc3: core: re-factor init and exit paths
>
> If dwc3_phy_setup() call is moved back in dwc3_probe() instead of
> dwc3_core_init(), everything is ok on STMicroelectronics platforms.
>
> I don't know if this issue has been seen on another platform.
>
> I can send a fix for this, but i wanted to get Felipe opinion on this.
That really shouldn't cause any issues for xHCI. We're initializing the
PHYs a little later, but still way before xHCI has a chance of
probing. Are you sure your bisection is sound? Which PHY driver are you
using? Maybe you have some quirk flag missing?
--
balbi
Attachment:
signature.asc
Description: PGP signature
