Re: [PATCH] USB: core: hub_port_reset: Remove extra 40 ms reset recovery time

[Mathias Nyman]

On 4.8.2024 16.19, Alan Stern wrote:
> On Sun, Aug 04, 2024 at 09:15:34AM +0200, Paul Menzel wrote:
> > [To: +Heikki]
> >
> >
> > Dear Alan, dear Heikki,
> >
> >
> > Am 26.07.24 um 19:48 schrieb Alan Stern:
>
> ...
>
> > > It's probably an xHCI thing -- the hardware may stop providing power to
> > > the ports during S3 suspend, or something like that.  The xHCI people
> > > may have a better idea of what's going on.
> >
> > Heikki, can you confirm this. I am attaching the logs with
>
> You should be asking Mathias, the xHCI maintainer.
>
> >      echo 'file drivers/usb/* +p' | sudo tee
> > /sys/kernel/debug/dynamic_debug/control
>
> ...
>
> > [  149.185600] usb 1-3: usb suspend, wakeup 0
> > [  149.185642] xhci_hcd 0000:00:14.0: Cancel URB 000000003e45896a, dev 4, ep 0x81, starting at offset 0x102ef1010
> > [  149.185661] usb usb2: usb auto-resume
> > [  149.185664] xhci_hcd 0000:00:14.0: // Ding dong!
> > [  149.185736] xhci_hcd 0000:00:14.0: Stopped on Transfer TRB for slot 2 ep 2
> > [  149.185745] xhci_hcd 0000:00:14.0: Removing canceled TD starting at 0x102ef1010 (dma) in stream 0 URB 000000003e45896a
> > [  149.185753] xhci_hcd 0000:00:14.0: Set TR Deq ptr 0x102ef1020, cycle 1
> >
> > [  149.185757] xhci_hcd 0000:00:14.0: // Ding dong!
> > [  149.185763] xhci_hcd 0000:00:14.0: xhci_giveback_invalidated_tds: Keep cancelled URB 000000003e45896a TD as cancel_status is 2
> > [  149.185770] xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @102ef1020
> > [  149.185775] xhci_hcd 0000:00:14.0: xhci_handle_cmd_set_deq: Giveback cancelled URB 000000003e45896a TD
> > [  149.185780] xhci_hcd 0000:00:14.0: Giveback URB 000000003e45896a, len = 0, expected = 116, status = -115
> > [  149.185788] xhci_hcd 0000:00:14.0: xhci_handle_cmd_set_deq: All TDs cleared, ring doorbell
> > [  149.185810] hub 2-0:1.0: hub_resume
> > [  149.185816] usb 1-4: usb suspend, wakeup 0
> > [  149.185840] hub 1-0:1.0: hub_suspend
> > [  149.185865] usb usb1: bus suspend, wakeup 0
> > [  149.185894] xhci_hcd 0000:00:14.0: port 1-4 not suspended
> > [  149.185899] xhci_hcd 0000:00:14.0: port 1-3 not suspended
>
> I have to wonder why xhci-hcd says ports 1-3 and 1-4 are not suspended,
> when only a few lines earlier the log says that devices 1-3 and 1-4
> have gone into USB suspend.

In bus suspend xhci notices that those ports are not properly suspended.
They are both in link state U0 state when they should be in U3 at this point
where devices and hubs should have successfully suspended.
Bus suspend will now try to set those ports to u3

Looks like at least 1-4 and 1-5 report connect status change at resume.
They need to be reset to get to the enabled state

[  149.879684] xhci_hcd 0000:00:14.0: xhci_resume: starting usb1 port polling.
[  149.879687] xhci_hcd 0000:00:14.0: Port change event, 1-4, id 4, portsc: 0x206e1
[  149.879736] xhci_hcd 0000:00:14.0: Port change event, 1-5, id 5, portsc: 0x206e1
...
[  149.937564] xhci_hcd 0000:00:14.0: clear port4 connect change, portsc: 0x6e1
[  149.937591] xhci_hcd 0000:00:14.0: clear port5 connect change, portsc: 0x6e1

Port Status: 0x206e1
	Connected
	Disabled
	Link: Polling
	Powered
	Full Speed
	Connect Status Change

port 1-3 seems like it resumes fine from u3 -> u0, but ends up being reset anyway
during resume, didn't look into why (maybe reset_resume flag is set?)

-Mathias