[regression] USB power management failure to suspend / high CPU usage

[Mathias Nyman <mathias.nyman@linux.intel.com>]

On 26.2.2019 0.11, Ivan Mironov wrote:
> On Wed, 2019-02-20 at 19:28 +0200, Mathias Nyman wrote:
>> On 14.2.2019 20.04, Eric Blau wrote:
>>> On Thu, Feb 14, 2019 at 9:56 AM Mathias Nyman
>>> <mathias.nyman@linux.intel.com> wrote:
>>>>> Thanks for looking into this, Mathias. Now that you point this out, on
>>>>> older kernels where suspend and resume works, I noticed the following
>>>>> log messages emitted when resuming from suspend:
>>>>>
>>>>> Feb 06 18:58:05 eric-macbookpro kernel: usb usb2-port3: Cannot enable.
>>>>> Maybe the USB cable is bad?
>>>>
>>>> Attached a testpatch that should react to ports stuck in polling state,
>>>> and warm reset them.
>>>>
>>>> It doesn't limit the numbers of reset tries, or allow system suspend with ports
>>>> stuck in polling state, but I'd like to know how the MacBook reacts to it
>>>>
>>>> Can you test it with debugging enabled?
>>>
>>> Hi Mathias,
>>>
>>> Thanks for the patch. I tested it against 4.20.8 and got a couple
>>> successful suspends but on the third attempt I got the same failure
>>> again. I noticed after the first suspend/resume, the card reader
>>> showed as "Link:Compliance" but on later attempts it showed stuck in
>>> Polling again.
>>>
>>> I've attached the logs with debugging enabled.
>>>
>>
>> Thanks, logs show that several resets won't recover the card reader.
>>
>> I'm taking a different approach, USB3 ports in polling state should
>> automatically move to connected/enabled. So instead of preventing
>> suspend if a port is found in polling I'll let it try to finish link
>> training for some time, and then just continue with suspend if it fails.
>>
>> Patch attached.
>>
>> This won't fix the broken card reader, but should allow your MacBook to suspend.
>> After this we can start looking at fixing the card reader, Ivan Miranov sent some
>> proposal for this.
>>
>> -Mathias
> 
> Hi Mathias,
> 
> I applied your patch on top of v5.0-rc8 and tested it on my laptop.
> 
> It fixes the suspend problem from the kernel side, but there is another
> one: starting with the second suspend, XHCI controller wakes up the
> system just after few seconds after suspending. Laptop keeps looping
> through suspend/resume while lid is closed.
> 
> Such behaviour is quite stable: I was able to reproduce this three
> times with reboots in between. Corresponding dmesg and traces are here
> (from one run only):
> https://github.com/im-0/investigate-card-reader-suspend-problem-on-mbp11.4/tree/master/test-22
> 
> After disabling ACPI wake up on XHC1 (echo XHC1 >/proc/acpi/wakeup),
> everything works as expected: suspend/resume works fine multiple times,
> card reader remains missing after the first suspend/resume.
> 

Thanks, logs show it's no longer in a similar loop attempting so suspend
the bus, but device instead goes between polling, rxDetect and compliance,
modes, sometimes with cold attach status flag seen.

Most of the time is now spent resetting the device.

I have yet another patch, this one will just log the portstatus.
I'd like to know if we are doing something odd when resuming the port
that causes it to get stuck.

Patch attached, can you try it out?

Also available from my port-debug branch:
git://git.kernel.org/pub/scm/linux/kernel/git/mnyman/xhci.git port-debug

-Mathias

From c32bd41c2d44f14cbfaf26de1c40387e770ccc53 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@linux.intel.com>
Date: Fri, 1 Mar 2019 08:38:50 +0200
Subject: [PATCH] xhci: add more port debugging

Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
---
 drivers/usb/host/xhci-hub.c  | 53 +++++++++++++++++++++++++++++++-------------
 drivers/usb/host/xhci-ring.c | 12 ++++++----
 drivers/usb/host/xhci.c      | 15 +++++++++----
 3 files changed, 56 insertions(+), 24 deletions(-)

diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
index e2eece6..6ba1a78 100644
--- a/drivers/usb/host/xhci-hub.c
+++ b/drivers/usb/host/xhci-hub.c
@@ -487,8 +487,8 @@ static void xhci_disable_port(struct usb_hcd *hcd, struct xhci_hcd *xhci,
 	/* Write 1 to disable the port */
 	writel(port_status | PORT_PE, addr);
 	port_status = readl(addr);
-	xhci_dbg(xhci, "disable port, actual port %d status  = 0x%x\n",
-			wIndex, port_status);
+	xhci_dbg(xhci, "disable port %d-%d, portsc: 0x%x\n",
+		 hcd->self.busnum, wIndex + 1, port_status);
 }
 
 static void xhci_clear_port_change_bit(struct xhci_hcd *xhci, u16 wValue,
@@ -537,8 +537,9 @@ static void xhci_clear_port_change_bit(struct xhci_hcd *xhci, u16 wValue,
 	/* Change bits are all write 1 to clear */
 	writel(port_status | status, addr);
 	port_status = readl(addr);
-	xhci_dbg(xhci, "clear port %s change, actual port %d status  = 0x%x\n",
-			port_change_bit, wIndex, port_status);
+
+	xhci_dbg(xhci, "clear port%d %s change, portsc: 0x%x\n",
+		 wIndex + 1, port_change_bit, port_status);
 }
 
 struct xhci_hub *xhci_get_rhub(struct usb_hcd *hcd)
@@ -565,13 +566,16 @@ static void xhci_set_port_power(struct xhci_hcd *xhci, struct usb_hcd *hcd,
 	rhub = xhci_get_rhub(hcd);
 	port = rhub->ports[index];
 	temp = readl(port->addr);
+
+	xhci_dbg(xhci, "set port power %d-%d %s, portsc: 0x%x\n",
+		 hcd->self.busnum, index + 1, on ? "ON" : "OFF", temp);
+
 	temp = xhci_port_state_to_neutral(temp);
+
 	if (on) {
 		/* Power on */
 		writel(temp | PORT_POWER, port->addr);
 		temp = readl(port->addr);
-		xhci_dbg(xhci, "set port power, actual port %d status  = 0x%x\n",
-						index, temp);
 	} else {
 		/* Power off */
 		writel(temp & ~PORT_POWER, port->addr);
@@ -666,12 +670,17 @@ void xhci_set_link_state(struct xhci_hcd *xhci, struct xhci_port *port,
 			 u32 link_state)
 {
 	u32 temp;
+	u32 portsc;
 
-	temp = readl(port->addr);
-	temp = xhci_port_state_to_neutral(temp);
+	portsc = readl(port->addr);
+	temp = xhci_port_state_to_neutral(portsc);
 	temp &= ~PORT_PLS_MASK;
 	temp |= PORT_LINK_STROBE | link_state;
 	writel(temp, port->addr);
+
+	xhci_dbg(xhci, "Set port %d-%d link state, portsc: 0x%x, write 0x%x",
+		 port->rhub->hcd->self.busnum, port->hcd_portnum + 1,
+		 portsc, temp);
 }
 
 static void xhci_set_remote_wake_mask(struct xhci_hcd *xhci,
@@ -840,7 +849,9 @@ static int xhci_handle_usb2_port_link_resume(struct xhci_port *port,
 	} else if (time_after_eq(jiffies, bus_state->resume_done[wIndex])) {
 		int time_left;
 
-		xhci_dbg(xhci, "Resume USB2 port %d\n", wIndex + 1);
+		xhci_dbg(xhci, "resume USB2 port %d-%d\n",
+			 hcd->self.busnum, wIndex + 1);
+
 		bus_state->resume_done[wIndex] = 0;
 		clear_bit(wIndex, &bus_state->resuming_ports);
 
@@ -867,9 +878,8 @@ static int xhci_handle_usb2_port_link_resume(struct xhci_port *port,
 		} else {
 			int port_status = readl(port->addr);
 
-			xhci_warn(xhci, "Port resume %i msec timed out, portsc = 0x%x\n",
-				  XHCI_MAX_REXIT_TIMEOUT_MS,
-				  port_status);
+			xhci_warn(xhci, "Port resume timed out, port %d-%d: 0x%x\n",
+				  hcd->self.busnum, wIndex + 1, port_status);
 			*status |= USB_PORT_STAT_SUSPEND;
 			clear_bit(wIndex, &bus_state->rexit_ports);
 		}
@@ -1124,9 +1134,8 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 		if (status == 0xffffffff)
 			goto error;
 
-		xhci_dbg(xhci, "get port status, actual port %d status  = 0x%x\n",
-				wIndex, temp);
-		xhci_dbg(xhci, "Get port status returned 0x%x\n", status);
+		xhci_dbg(xhci, "Get port status %d-%d read: 0x%x, return 0x%x",
+			 hcd->self.busnum, wIndex + 1, temp, status);
 
 		put_unaligned(cpu_to_le32(status), (__le32 *) buf);
 		/* if USB 3.1 extended port status return additional 4 bytes */
@@ -1182,7 +1191,8 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 			temp = readl(ports[wIndex]->addr);
 			if ((temp & PORT_PE) == 0 || (temp & PORT_RESET)
 				|| (temp & PORT_PLS_MASK) >= XDEV_U3) {
-				xhci_warn(xhci, "USB core suspending device not in U0/U1/U2.\n");
+				xhci_warn(xhci, "USB core suspending port %d-%d not in U0/U1/U2\n",
+					  hcd->self.busnum, wIndex + 1);
 				goto error;
 			}
 
@@ -1550,6 +1560,9 @@ int xhci_bus_suspend(struct usb_hcd *hcd)
 		t2 = xhci_port_state_to_neutral(t1);
 		portsc_buf[port_index] = 0;
 
+		xhci_dbg(xhci, "bus_suspend port %d-%d, portsc: 0x%x\n",
+			 hcd->self.busnum, port_index + 1, t1);
+
 		/* Bail out if a USB3 port has a new device in link training */
 		if ((hcd->speed >= HCD_USB3) &&
 		    (t1 & PORT_PLS_MASK) == XDEV_POLLING) {
@@ -1616,6 +1629,9 @@ int xhci_bus_suspend(struct usb_hcd *hcd)
 			}
 		}
 		writel(portsc_buf[port_index], ports[port_index]->addr);
+
+		xhci_dbg(xhci, "bus_suspend port %d-%d, write: 0x%x\n",
+			 hcd->self.busnum, port_index + 1, portsc_buf[port_index]);
 	}
 	hcd->state = HC_STATE_SUSPENDED;
 	bus_state->next_statechange = jiffies + msecs_to_jiffies(10);
@@ -1693,6 +1709,9 @@ int xhci_bus_resume(struct usb_hcd *hcd)
 	while (port_index--) {
 		portsc = readl(ports[port_index]->addr);
 
+		xhci_dbg(xhci, "bus_resume port %d-%d, portsc: 0x%x\n",
+			 hcd->self.busnum, port_index + 1, portsc);
+
 		/* warm reset CAS limited ports stuck in polling/compliance */
 		if ((xhci->quirks & XHCI_MISSING_CAS) &&
 		    (hcd->speed >= HCD_USB3) &&
@@ -1721,6 +1740,8 @@ int xhci_bus_resume(struct usb_hcd *hcd)
 		/* disable wake for all ports, write new link state if needed */
 		portsc &= ~(PORT_RWC_BITS | PORT_CEC | PORT_WAKE_BITS);
 		writel(portsc, ports[port_index]->addr);
+		xhci_dbg(xhci, "bus_resume port %d-%d, write: 0x%x\n",
+			 hcd->self.busnum, port_index + 1, portsc);
 	}
 
 	/* USB2 specific resume signaling delay and U0 link state transition */
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 40fa25c..cbe66a1 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -1569,18 +1569,19 @@ static void handle_port_status(struct xhci_hcd *xhci,
 			  "WARN: xHC returned failed port status event\n");
 
 	port_id = GET_PORT_ID(le32_to_cpu(event->generic.field[0]));
-	xhci_dbg(xhci, "Port Status Change Event for port %d\n", port_id);
-
 	max_ports = HCS_MAX_PORTS(xhci->hcs_params1);
+
 	if ((port_id <= 0) || (port_id > max_ports)) {
-		xhci_warn(xhci, "Invalid port id %d\n", port_id);
+		xhci_warn(xhci, "Port change event with invalid port ID %d\n",
+			  port_id);
 		inc_deq(xhci, xhci->event_ring);
 		return;
 	}
 
 	port = &xhci->hw_ports[port_id - 1];
 	if (!port || !port->rhub || port->hcd_portnum == DUPLICATE_ENTRY) {
-		xhci_warn(xhci, "Event for invalid port %u\n", port_id);
+		xhci_warn(xhci, "Port change event, no port for port ID %u\n",
+			  port_id);
 		bogus_port_status = true;
 		goto cleanup;
 	}
@@ -1597,6 +1598,9 @@ static void handle_port_status(struct xhci_hcd *xhci,
 	hcd_portnum = port->hcd_portnum;
 	portsc = readl(port->addr);
 
+	xhci_dbg(xhci, "Port change event, %d-%d, id %d: 0x%x\n",
+		 hcd->self.busnum, hcd_portnum + 1, port_id, portsc);
+
 	trace_xhci_handle_port_status(hcd_portnum, portsc);
 
 	if (hcd->state == HC_STATE_SUSPENDED) {
diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
index 005e659..8cd8edf 100644
--- a/drivers/usb/host/xhci.c
+++ b/drivers/usb/host/xhci.c
@@ -893,7 +893,7 @@ static void xhci_disable_port_wake_on_bits(struct xhci_hcd *xhci)
 	struct xhci_port **ports;
 	int port_index;
 	unsigned long flags;
-	u32 t1, t2;
+	u32 t1, t2, portsc;
 
 	spin_lock_irqsave(&xhci->lock, flags);
 
@@ -902,10 +902,14 @@ static void xhci_disable_port_wake_on_bits(struct xhci_hcd *xhci)
 	ports = xhci->usb3_rhub.ports;
 	while (port_index--) {
 		t1 = readl(ports[port_index]->addr);
+		portsc = t1;
 		t1 = xhci_port_state_to_neutral(t1);
 		t2 = t1 & ~PORT_WAKE_BITS;
-		if (t1 != t2)
+		if (t1 != t2) {
 			writel(t2, ports[port_index]->addr);
+			xhci_dbg(xhci, "disable wake bits port %d-%d, portsc: 0x%x, write: 0x%x\n",
+				 xhci->usb3_rhub.hcd->self.busnum, port_index + 1, portsc, t2);
+		}
 	}
 
 	/* disable usb2 ports Wake bits */
@@ -913,12 +917,15 @@ static void xhci_disable_port_wake_on_bits(struct xhci_hcd *xhci)
 	ports = xhci->usb2_rhub.ports;
 	while (port_index--) {
 		t1 = readl(ports[port_index]->addr);
+		portsc = t1;
 		t1 = xhci_port_state_to_neutral(t1);
 		t2 = t1 & ~PORT_WAKE_BITS;
-		if (t1 != t2)
+		if (t1 != t2) {
 			writel(t2, ports[port_index]->addr);
+			xhci_dbg(xhci, "disable wake bits port %d-%d, portsc: 0x%x, write: 0x%x\n",
+				 xhci->usb2_rhub.hcd->self.busnum, port_index + 1, portsc, t2);
+		}
 	}
-
 	spin_unlock_irqrestore(&xhci->lock, flags);
 }
 
-- 
2.7.4