Message-ID: <0745123b-8f7c-4eef-a0ec-dfaae0864c54@molgen.mpg.de>
Date: Mon, 5 Aug 2024 23:41:29 +0200
From: Paul Menzel <pmenzel@...gen.mpg.de>
To: Mathias Nyman <mathias.nyman@...ux.intel.com>,
 Alan Stern <stern@...land.harvard.edu>
Cc: Mathias Nyman <mathias.nyman@...el.com>,
 Heikki Krogerus <heikki.krogerus@...ux.intel.com>,
 Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
 Kai-Heng Feng <kai.heng.feng@...onical.com>,
 Hans de Goede <hdegoede@...hat.com>, linux-usb@...r.kernel.org,
 linux-kernel@...r.kernel.org
Subject: Re: [PATCH] USB: core: hub_port_reset: Remove extra 40 ms reset
 recovery time

Dear Mathias,


Thank you for the quick reply and analysis.


Am 05.08.24 um 11:17 schrieb Mathias Nyman:
> On 4.8.2024 16.19, Alan Stern wrote:
>> On Sun, Aug 04, 2024 at 09:15:34AM +0200, Paul Menzel wrote:


[…]

>>> 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?)

Is that a hardware, firmware, or something else issue?

Just as another data point the logs from a Kaby Lake-R(?) Dell XPS 13 
9370 (i7-8550U). First suspend with LMP USB-C mini Dock and Ethernet 
cable connected, the second suspend with the device unplugged.

     $ grep -e "Linux version" -e "DMI:" -e ': reset' 
20240805–dell-xps-13-9370–linux-6.9.12–dmesg.txt
     [    0.000000] Linux version 6.9.12-amd64 
(debian-kernel@...ts.debian.org) (x86_64-linux-gnu-gcc-13 (Debian 
13.3.0-3) 13.3.0, GNU ld (GNU Binutils for Debian) 2.42.90.20240720) #1 
SMP PREEMPT_DYNAMIC Debian 6.9.12-1 (2024-07-27)
     [    0.000000] DMI: Dell Inc. XPS 13 9370/0F6P3V, BIOS 1.21.0 
07/06/2022
     [   11.726362] r8152-cfgselector 4-1.1.3: reset SuperSpeed USB 
device number 5 using xhci_hcd
     [   52.215529] usb 1-5: reset high-speed USB device number 2 using 
xhci_hcd
     [   52.319498] usb 4-1: reset SuperSpeed USB device number 2 using 
xhci_hcd
     [   52.490726] usb 3-1: reset high-speed USB device number 2 using 
xhci_hcd
     [   53.061379] usb 4-1.4: reset SuperSpeed USB device number 4 
using xhci_hcd
     [   53.161160] usb 4-1.1: reset SuperSpeed USB device number 3 
using xhci_hcd
     [   53.348471] usb 3-1.5: reset high-speed USB device number 4 
using xhci_hcd
     [   53.579860] usb 3-1.1: reset high-speed USB device number 3 
using xhci_hcd
     [   53.915600] r8152-cfgselector 4-1.1.3: reset SuperSpeed USB 
device number 5 using xhci_hcd
     [   54.805472] usb 4-1.4: reset SuperSpeed USB device number 4 
using xhci_hcd
     [   68.034874] usb 1-5: reset high-speed USB device number 2 using 
xhci_hcd


Kind regards,

Paul
View attachment "20240805–dell-xps-13-9370–linux-6.9.12–dmesg.txt" of type "text/plain" (220881 bytes)

Powered by blists - more mailing lists