Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Content-Type: text/plain;
        charset=us-ascii
Mime-Version: 1.0 (Mac OS X Mail 13.4 \(3608.80.23.2.2\))
Subject: Re: [PATCH 2/2] xhci: Poll for U0 after disabling USB2 LPM
From:   Kai-Heng Feng <kai.heng.feng@canonical.com>
In-Reply-To: <6c3ac2e5-73e9-6e4f-2940-63403821631f@linux.intel.com>
Date:   Tue, 9 Jun 2020 18:15:28 +0800
Cc:     Mathias Nyman <mathias.nyman@intel.com>,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        "open list:USB XHCI DRIVER" <linux-usb@vger.kernel.org>,
        open list <linux-kernel@vger.kernel.org>
Content-Transfer-Encoding: 8BIT
Message-Id: <8327233C-5DE8-43F8-9208-5FF888629047@canonical.com>
References: <20200520101811.2623-1-kai.heng.feng@canonical.com>
 <20200520101811.2623-2-kai.heng.feng@canonical.com>
 <6c3ac2e5-73e9-6e4f-2940-63403821631f@linux.intel.com>
To:     Mathias Nyman <mathias.nyman@linux.intel.com>
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk


> On Jun 8, 2020, at 19:21, Mathias Nyman <mathias.nyman@linux.intel.com> wrote:
> 
> On 20.5.2020 13.18, Kai-Heng Feng wrote:
>> USB2 devices with LPM enabled may interrupt the system suspend:
>> [  932.510475] usb 1-7: usb suspend, wakeup 0
>> [  932.510549] hub 1-0:1.0: hub_suspend
>> [  932.510581] usb usb1: bus suspend, wakeup 0
>> [  932.510590] xhci_hcd 0000:00:14.0: port 9 not suspended
>> [  932.510593] xhci_hcd 0000:00:14.0: port 8 not suspended
>> ..
>> [  932.520323] xhci_hcd 0000:00:14.0: Port change event, 1-7, id 7, portsc: 0x400e03
> 
> 400e03 = Connected, Enabled, U0 with port ink state change flag (PLC) set.
> 
>> ..
>> [  932.591405] PM: pci_pm_suspend(): hcd_pci_suspend+0x0/0x30 returns -16
>> [  932.591414] PM: dpm_run_callback(): pci_pm_suspend+0x0/0x160 returns -16
>> [  932.591418] PM: Device 0000:00:14.0 failed to suspend async: error -16
>> 
>> During system suspend, USB core will let HC suspends the device if it
>> doesn't have remote wakeup enabled and doesn't have any children.
>> However, from the log above we can see that the usb 1-7 doesn't get bus
>> suspended due to not in U0. After a while the port finished U2 -> U0
>> transition, interrupts the suspend process.
> 
> In USB2 HW link PM the PLC flag should not be set in U2Exit -> U0 transitions.
> Only case we should see a port change event is U2Entry -> U0 due to STALL or
> error/timeout. (see xhci 4.23.5.1.1.1)
> 
>> 
>> The observation is that after disabling LPM, port doesn't transit to U0
>> immediately and can linger in U2. xHCI spec 4.23.5.2 states that the
>> maximum exit latency for USB2 LPM should be BESL + 10us. The BESL for
>> the affected device is advertised as 400us, which is still not enough
>> based on my testing result.
>> 
>> So let's use the maximum permitted latency, 10000, to poll for U0
>> status to solve the issue.
> 
> I don't recall all details, but it could be that disabling LPM before suspend
> is unnecessary. 
> At least xhci should be able to set a port to U3 from U1 and U2 (see xhci 4.15.1)
> so that is one change that could be done to xhci_bus_suspend()

Yes, put the device to U3 directly does the trick.

> 
> Also just noticed that we are not really checking L1S field in PORTPMSC register, 
> this should tell if there was an issue with USB2 lpm state transitions, and
> perhaps we should disable lpm for that device. 
> 
> Does the L1S field show anything unuaual in your case?
> That could explain the port event with the PLC bit set.

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 2c255d0620b0..a2099d42e490 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -1592,7 +1592,7 @@ static void handle_port_status(struct xhci_hcd *xhci,
 {
        struct usb_hcd *hcd;
        u32 port_id;
-       u32 portsc, cmd_reg;
+       u32 portsc, portpmsc, cmd_reg;
        int max_ports;
        int slot_id;
        unsigned int hcd_portnum;
@@ -1634,9 +1634,10 @@ static void handle_port_status(struct xhci_hcd *xhci,
        bus_state = &port->rhub->bus_state;
        hcd_portnum = port->hcd_portnum;
        portsc = readl(port->addr);
+       portpmsc = readl(port->addr + PORTPMSC);
 
-       xhci_dbg(xhci, "Port change event, %d-%d, id %d, portsc: 0x%x\n",
-                hcd->self.busnum, hcd_portnum + 1, port_id, portsc);
+       xhci_dbg(xhci, "Port change event, %d-%d, id %d, portsc: 0x%x, portpmsc 0x%0x\n",
+                hcd->self.busnum, hcd_portnum + 1, port_id, portsc, portpmsc);
 
        trace_xhci_handle_port_status(hcd_portnum, portsc);

[  685.460054] xhci_hcd 0000:00:14.0: Port change event, 1-7, id 7, portsc: 0x400e03, portpmsc 0x1
[  685.460062] xhci_hcd 0000:00:14.0: resume root hub
[  685.460079] xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[  685.460094] xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping port polling.
[  685.521685] PM: pci_pm_suspend(): hcd_pci_suspend+0x0/0x30 returns -16
[  685.521695] PM: dpm_run_callback(): pci_pm_suspend+0x0/0x160 returns -16
[  685.521699] PM: Device 0000:00:14.0 failed to suspend async: error -16

So after disabling LPM, it takes a long time to complete L1 transition, before transitioning to L0.

Kai-Heng

> 
> I think we can avoid a readl_poll_timeout() solution in this case.
> 
> -Mathias