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

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

[Eric Blau]

On Wed, Feb 20, 2019 at 12:27 PM Mathias Nyman
<mathias.nyman@linux.intel.com> wrote:
>
> 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.

Hi Mathias,

I tried the patch and it works for me. I do see the card reader still
in polling, but, as you say, it does not prevent suspend. Personally,
I never use the card reader so I'm ok with it not working.

On resume I see the following messages printed but it doesn't appear
to affect further suspend/resume sequences:

Feb 21 19:59:13 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:13 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: hub 2-0:1.0: port_wait_reset: err = -16
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not enabled,
trying warm reset again...
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:14 eric-macbookpro kernel: hub 2-0:1.0: port_wait_reset: err = -16
Feb 21 19:59:14 eric-macbookpro kernel: usb usb2-port3: not enabled,
trying warm reset again...
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:15 eric-macbookpro kernel: hub 2-0:1.0: port_wait_reset: err = -16
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not enabled,
trying warm reset again...
Feb 21 19:59:15 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not warm reset
yet, waiting 200ms
Feb 21 19:59:16 eric-macbookpro kernel: xhci_hcd 0000:00:14.0: CTRL:
TypeReq=0x2303 val=0x5 idx=0x303 len=0 ==> -19
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: status 0341,
change 0000, 5.0 Gb/s
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not reset yet,
waiting 60ms
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not reset yet,
waiting 200ms
Feb 21 19:59:16 eric-macbookpro kernel: usb usb2-port3: not reset yet,
waiting 200ms
Feb 21 19:59:17 eric-macbookpro kernel: usb usb2-port3: not reset yet,
waiting 200ms
Feb 21 19:59:17 eric-macbookpro kernel: usb usb2-port3: not reset yet,
waiting 200ms
Feb 21 19:59:17 eric-macbookpro kernel: xhci_hcd 0000:00:14.0: CTRL:
TypeReq=0x2303 val=0x5 idx=0x303 len=0 ==> -19
Feb 21 19:59:17 eric-macbookpro kernel: xhci_hcd 0000:00:14.0: CTRL:
TypeReq=0x2303 val=0x5 idx=0x303 len=0 ==> -19
Feb 21 19:59:17 eric-macbookpro kernel: hub 2-0:1.0: state 7 ports 4
chg 0000 evt 0008
Feb 21 19:59:17 eric-macbookpro kernel: hub 2-0:1.0: hub_suspend
Feb 21 19:59:17 eric-macbookpro kernel: usb usb2: bus auto-suspend, wakeup 1


Thanks,
Eric

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

[Eric Blau]

On Thu, Mar 21, 2019 at 10:51 AM Mathias Nyman
<mathias.nyman@linux.intel.com> wrote:
>
> On 21.3.2019 15.32, Eric Blau wrote:
> >
> > Where do we stand with this fix? Were you able to try out this port
> > debug patch, Ivan?
> >
> > I normally run with ACPI wakeup disabled on XHC1 but if more debugging
> > is needed, I can enable wakeup again and try to reproduce what Ivan is
> > seeing. Just let me know. For now, I've been applying Mathias previous
> > patch to the latest kernels and have been suspending, hibernating and
> > resuming successfully with the card reader disabled.
> >
>
> Just added the patch to my for-usb-linus branch, will send it forward tomorrow

Great, thanks Mathias!

-Eric

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

[Mathias Nyman]

On 21.3.2019 15.32, Eric Blau wrote:
> On Mon, Mar 4, 2019 at 10:13 AM Mathias Nyman
> <mathias.nyman@linux.intel.com> wrote:
>>
>> On 26.2.2019 0.11, Ivan Mironov wrote:
>>> 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
> 
> Where do we stand with this fix? Were you able to try out this port
> debug patch, Ivan?
> 
> I normally run with ACPI wakeup disabled on XHC1 but if more debugging
> is needed, I can enable wakeup again and try to reproduce what Ivan is
> seeing. Just let me know. For now, I've been applying Mathias previous
> patch to the latest kernels and have been suspending, hibernating and
> resuming successfully with the card reader disabled.
> 

Just added the patch to my for-usb-linus branch, will send it forward tomorrow

-Mathias

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

[Eric Blau]

On Mon, Mar 4, 2019 at 10:13 AM Mathias Nyman
<mathias.nyman@linux.intel.com> wrote:
>
> On 26.2.2019 0.11, Ivan Mironov wrote:
> > 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

Where do we stand with this fix? Were you able to try out this port
debug patch, Ivan?

I normally run with ACPI wakeup disabled on XHC1 but if more debugging
is needed, I can enable wakeup again and try to reproduce what Ivan is
seeing. Just let me know. For now, I've been applying Mathias previous
patch to the latest kernels and have been suspending, hibernating and
resuming successfully with the card reader disabled.

Thanks,
Eric

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

[Eric Blau]

On Mon, Feb 25, 2019 at 5:11 PM Ivan Mironov <mironov.ivan@gmail.com> wrote:
>
> 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.

Hmm, I didn't see the same behavior on my MacBook, but maybe it is
because I disable lid power events in /etc/systemd/logind.conf.
Suspend/resume worked reliably for a week doing probably about a dozen
suspend/resume cycles with Mathias' patch.

-Eric

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

[Mathias Nyman]

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

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

[Ivan Mironov]

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.

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

[Mathias Nyman]

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

From 444cab4f41c79c5a04d1fc8939b450c89dc64768 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@linux.intel.com>
Date: Wed, 20 Feb 2019 16:10:54 +0200
Subject: [PATCH 1/2] xhci: Don't let USB3 ports stuck in polling state prevent
 suspend

Commit 2f31a67f01a8 ("usb: xhci: Prevent bus suspend if a port connect
change or polling state is detected") was intended to prevent ports that
were still link training from being forced to U3 suspend state mid
enumeration.
This solved enumeration issues for devices with slow link training.

Turns out some devices are stuck in the link training/polling state,
and thus that patch will prevent suspend completely for these devices.
This is seen with USB3 card readers in some MacBooks.

Instead of preventing suspend, give some time to complete the link
training. On successful training the port will end up as connected
and enabled.
If port instead is stuck in link training the bus suspend will continue
suspending after 360ms (10 * 36ms) timeout (tPollingLFPSTimeout).

Original patch was sent to stable, this one should go there as well

Fixes: 2f31a67f01a8 ("usb: xhci: Prevent bus suspend if a port connect change or polling state is detected")
Cc: stable@vger.kernel.org
Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
---
 drivers/usb/host/xhci-hub.c | 19 ++++++++++++-------
 drivers/usb/host/xhci.h     |  8 ++++++++
 2 files changed, 20 insertions(+), 7 deletions(-)

diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
index e2eece6..96a7405 100644
--- a/drivers/usb/host/xhci-hub.c
+++ b/drivers/usb/host/xhci-hub.c
@@ -1545,20 +1545,25 @@ int xhci_bus_suspend(struct usb_hcd *hcd)
 	port_index = max_ports;
 	while (port_index--) {
 		u32 t1, t2;
-
+		int retries = 10;
+retry:
 		t1 = readl(ports[port_index]->addr);
 		t2 = xhci_port_state_to_neutral(t1);
 		portsc_buf[port_index] = 0;
 
-		/* Bail out if a USB3 port has a new device in link training */
-		if ((hcd->speed >= HCD_USB3) &&
+		/*
+		 * Give a USB3 port in link training time to finish, but don't
+		 * prevent suspend as port might be stuck
+		 */
+		if ((hcd->speed >= HCD_USB3) && retries-- &&
 		    (t1 & PORT_PLS_MASK) == XDEV_POLLING) {
-			bus_state->bus_suspended = 0;
 			spin_unlock_irqrestore(&xhci->lock, flags);
-			xhci_dbg(xhci, "Bus suspend bailout, port in polling\n");
-			return -EBUSY;
+			msleep(XHCI_PORT_POLLING_LFPS_TIME);
+			spin_lock_irqsave(&xhci->lock, flags);
+			xhci_dbg(xhci, "port %d polling in bus suspend, waiting\n",
+				 port_index);
+			goto retry;
 		}
-
 		/* suspend ports in U0, or bail out for new connect changes */
 		if ((t1 & PORT_PE) && (t1 & PORT_PLS_MASK) == XDEV_U0) {
 			if ((t1 & PORT_CSC) && wake_enabled) {
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index 652dc36..9334cde 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -452,6 +452,14 @@ struct xhci_op_regs {
  */
 #define XHCI_DEFAULT_BESL	4
 
+/*
+ * USB3 specification define a 360ms tPollingLFPSTiemout for USB3 ports
+ * to complete link training. usually link trainig completes much faster
+ * so check status 10 times with 36ms sleep in places we need to wait for
+ * polling to complete.
+ */
+#define XHCI_PORT_POLLING_LFPS_TIME  36
+
 /**
  * struct xhci_intr_reg - Interrupt Register Set
  * @irq_pending:	IMAN - Interrupt Management Register.  Used to enable
-- 
2.7.4

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

[Mathias Nyman]

On 12.2.2019 20.55, Eric Blau wrote:
> On Tue, Feb 12, 2019 at 1:06 PM Alan Stern <stern@rowland.harvard.edu> wrote:
>>
>> On Tue, 12 Feb 2019, Mathias Nyman wrote:
>>
>>>
>>> This logs shows a USB3 Apple card reader successfully suspending to U3 state
>>> once, but fails to resume back to U0. It is logically disconnected as a result of
>>> failing to resume, and is left stuck in a polling link state.
>>>
>>> This is the only USB3 device connected. The polling link state does not yet show the device
>>> as connected or enabled, so hub attempts to autosuspend.
>>> There is however a final check before autosuspending the hub which prevents suspend
>>> due to the port in polling state. This autosuspend attempt continues in a loop.
>>
>> I don't know what the right answer is here.  But we shouldn't allow
>> faulty peripherals to prevent the system from going into suspend.
>>
>> Should we give up after some fixed number of warm resets, say 5?
> 

I don't think the current code gets as far as warm resetting the port.
It seems to be stuck in the suspend attempt loop.

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

Thanks
Mathias

From 6b3b9f3d41b8ac9cf993bf4b88a20e30c99e3b7f Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@linux.intel.com>
Date: Thu, 14 Feb 2019 15:40:12 +0200
Subject: [PATCH] usb: warm reset USB3 ports stuck in polling

warm reset USB3 ports stuck in polling after 360ms.

In the polling state USB3 ports are link training, which should
not take longer than 360ms according to USB3 specification
tPollingLFPSTimeout value.

The card reader connected to xhci in MacBookPro is found stuck
in this state after resuming from suspend.

Signed-off-by: Mathias Nyman <mathias.nyman@linux.intel.com>
---
 drivers/usb/core/hub.c | 36 +++++++++++++++++++++++++++++++++---
 1 file changed, 33 insertions(+), 3 deletions(-)

diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index 8d4631c..448884d 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -1151,9 +1151,10 @@ static void hub_activate(struct usb_hub *hub, enum hub_activation_type type)
 		 */
 		if (hub_is_superspeed(hdev) &&
 		    ((portstatus & USB_PORT_STAT_LINK_STATE) ==
-						USB_SS_PORT_LS_POLLING))
+						USB_SS_PORT_LS_POLLING)) {
 			need_debounce_delay = true;
-
+			set_bit(port1, hub->event_bits);
+		}
 		/* Clear status-change flags; we'll debounce later */
 		if (portchange & USB_PORT_STAT_C_CONNECTION) {
 			need_debounce_delay = true;
@@ -2697,6 +2698,9 @@ static unsigned hub_is_wusb(struct usb_hub *hub)
 #define HUB_LONG_RESET_TIME	200
 #define HUB_RESET_TIMEOUT	800
 
+#define HUB_LFPS_TIME		24
+#define HUB_LFPS_TIMEOUT	360
+
 /*
  * "New scheme" enumeration causes an extra state transition to be
  * exposed to an xhci host and causes USB3 devices to receive control
@@ -2737,6 +2741,31 @@ static bool hub_port_warm_reset_required(struct usb_hub *hub, int port1,
 		|| link_state == USB_SS_PORT_LS_COMP_MOD;
 }
 
+static bool hub_port_stuck_in_polling(struct usb_hub *hub, int port1,
+				      u16 portstatus)
+{
+	u16 link_state;
+	u16 portchange;
+	int lfps_delay = 0;
+
+	if (!hub_is_superspeed(hub->hdev))
+		return false;
+
+	link_state = portstatus & USB_PORT_STAT_LINK_STATE;
+
+	while (link_state == USB_SS_PORT_LS_POLLING) {
+		msleep(HUB_LFPS_TIME);
+
+		hub_port_status(hub, port1, &portstatus, &portchange);
+		link_state = portstatus & USB_PORT_STAT_LINK_STATE;
+
+		lfps_delay += HUB_LFPS_TIME;
+		if (lfps_delay > HUB_LFPS_TIMEOUT)
+			return true;
+	}
+	return false;
+}
+
 static int hub_port_wait_reset(struct usb_hub *hub, int port1,
 			struct usb_device *udev, unsigned int delay, bool warm)
 {
@@ -5329,7 +5358,8 @@ static void port_event(struct usb_hub *hub, int port1)
 	 * Warm reset a USB3 protocol port if it's in
 	 * SS.Inactive state.
 	 */
-	if (hub_port_warm_reset_required(hub, port1, portstatus)) {
+	if (hub_port_warm_reset_required(hub, port1, portstatus) ||
+	    hub_port_stuck_in_polling(hub, port1, portstatus)) {
 		dev_dbg(&port_dev->dev, "do warm reset\n");
 		if (!udev || !(portstatus & USB_PORT_STAT_CONNECTION)
 				|| udev->state == USB_STATE_NOTATTACHED) {
-- 
2.7.4

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

[Greg KH]

On Wed, Jan 02, 2019 at 10:42:55AM -0500, Eric Blau wrote:
> On Sun, Dec 23, 2018 at 11:28 AM Greg KH <greg@kroah.com> wrote:
> >
> > On Sun, Dec 23, 2018 at 08:49:42AM -0500, Eric Blau wrote:
> > >
> > > The behavior exists in 4.19.8 and 4.19.11, the kernel versions I have
> > > upgraded to with Arch Linux, so the regression was introduced sometime
> > > between 4.19.4 and 4.19.8. Hibernate still works but when I resume
> > > from hibernate, there is a ksoftirqd and kworker thread/process
> > > together taking up 100% of one core. If I turn off auto power control
> > > for usb1 and usb2, the threads stop spinning. i.e.,
> > >
> > > echo 'on' > '/sys/bus/usb/devices/usb1/power/control
> > >
> > > Any suggestions as to where this regression was introduced and what
> > > can be done to fix it?
> >
> > Sorry, this is a known issue, will be fixed in the next 4.19 release
> > that should be out next week.
> >
> > If you are curious, it is fixed by commit 45f750c16cae ("xhci: Don't
> > prevent USB2 bus suspend in state check intended for USB3 only") in
> > Linus's tree.
> 
> Hi Greg,
> 
> I've upgraded to 4.20 and the same regression still exists. I know
> this is not a stable release currently, but 4.20 has 45f750c16cae
> merged as commit 93a86395b429:
> 
> commit 93a86395b429c3a68a0d029f584f39890c0801b2
> Merge: 45f750c16cae 28a86092b175
> Author:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> AuthorDate: Fri Dec 14 17:06:09 2018 +0100
> Commit:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> CommitDate: Fri Dec 14 17:06:09 2018 +0100
> 
>     Merge tag 'usb-serial-4.20-rc7' of
> https://git.kernel.org/pub/scm/linux/kernel/git/johan/usb-serial into
> usb-linus
> 
> 
> The same workaround is still effective, but I thought I'd let you know
> that I'm still experiencing the same issue. If there's anything else I
> can do to help track this down, please let me know.

Can you post the information that you are still having this issue on the
linux-usb@vger.kernel.org mailing list, along with any kernel logs that
you might have that shows this?  The developers there can help you out.

thanks,

greg k-h

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

[Eric Blau]

On Sun, Dec 23, 2018 at 11:28 AM Greg KH <greg@kroah.com> wrote:
>
> On Sun, Dec 23, 2018 at 08:49:42AM -0500, Eric Blau wrote:
> >
> > The behavior exists in 4.19.8 and 4.19.11, the kernel versions I have
> > upgraded to with Arch Linux, so the regression was introduced sometime
> > between 4.19.4 and 4.19.8. Hibernate still works but when I resume
> > from hibernate, there is a ksoftirqd and kworker thread/process
> > together taking up 100% of one core. If I turn off auto power control
> > for usb1 and usb2, the threads stop spinning. i.e.,
> >
> > echo 'on' > '/sys/bus/usb/devices/usb1/power/control
> >
> > Any suggestions as to where this regression was introduced and what
> > can be done to fix it?
>
> Sorry, this is a known issue, will be fixed in the next 4.19 release
> that should be out next week.
>
> If you are curious, it is fixed by commit 45f750c16cae ("xhci: Don't
> prevent USB2 bus suspend in state check intended for USB3 only") in
> Linus's tree.

Hi Greg,

I've upgraded to 4.20 and the same regression still exists. I know
this is not a stable release currently, but 4.20 has 45f750c16cae
merged as commit 93a86395b429:

commit 93a86395b429c3a68a0d029f584f39890c0801b2
Merge: 45f750c16cae 28a86092b175
Author:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>
AuthorDate: Fri Dec 14 17:06:09 2018 +0100
Commit:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>
CommitDate: Fri Dec 14 17:06:09 2018 +0100

    Merge tag 'usb-serial-4.20-rc7' of
https://git.kernel.org/pub/scm/linux/kernel/git/johan/usb-serial into
usb-linus


The same workaround is still effective, but I thought I'd let you know
that I'm still experiencing the same issue. If there's anything else I
can do to help track this down, please let me know.

Thanks,
Eric

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

[Eric Blau]

On Sun, Dec 23, 2018 at 11:28 AM Greg KH <greg@kroah.com> wrote:
>
> On Sun, Dec 23, 2018 at 08:49:42AM -0500, Eric Blau wrote:
> >
> > Any suggestions as to where this regression was introduced and what
> > can be done to fix it?
>
> Sorry, this is a known issue, will be fixed in the next 4.19 release
> that should be out next week.

Great, thanks for letting me know. I'll look out for the next 4.19 release.

Regards,
Eric

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

[Greg KH]

On Sun, Dec 23, 2018 at 08:49:42AM -0500, Eric Blau wrote:
> Hi folks,
> 
> I noticed a regression introduced sometime after 4.19.4 in USB power
> management. I have a 2015 MacBook Pro. When I try to do a suspend or a
> suspend+hibernate, I get the following error messages trying to
> suspend usb2 and the suspend fails. This works fine in 4.19.4:
> 
> Dec 22 13:50:36 eric-macbookpro kernel: Freezing remaining freezable
> tasks ... (elapsed 0.001 seconds) done.
> Dec 22 13:50:36 eric-macbookpro kernel: Suspending console(s) (use
> no_console_suspend to debug)
> Dec 22 13:50:36 eric-macbookpro kernel: dpm_run_callback():
> usb_dev_freeze+0x0/0x10 returns -16
> Dec 22 13:50:36 eric-macbookpro kernel: PM: Device usb2 failed to
> freeze async: error -16
> Dec 22 13:50:38 eric-macbookpro systemd[1]:
> systemd-hybrid-sleep.service: Main process exited, code=exited,
> status=1/FAILURE
> Dec 22 13:50:38 eric-macbookpro systemd[1]:
> systemd-hybrid-sleep.service: Failed with result 'exit-code'.
> Dec 22 13:50:38 eric-macbookpro systemd[1]: Failed to start Hybrid
> Suspend+Hibernate.
> Dec 22 13:50:38 eric-macbookpro systemd[1]: Dependency failed for
> Hybrid Suspend+Hibernate.
> Dec 22 13:50:38 eric-macbookpro systemd[1]: hybrid-sleep.target: Job
> hybrid-sleep.target/start failed with result 'dependency'.
> Dec 22 13:50:38 eric-macbookpro systemd-logind[1573]: Operation
> 'sleep' finished.
> Dec 22 13:50:38 eric-macbookpro systemd[1]: Stopped target Sleep.
> 
> The behavior exists in 4.19.8 and 4.19.11, the kernel versions I have
> upgraded to with Arch Linux, so the regression was introduced sometime
> between 4.19.4 and 4.19.8. Hibernate still works but when I resume
> from hibernate, there is a ksoftirqd and kworker thread/process
> together taking up 100% of one core. If I turn off auto power control
> for usb1 and usb2, the threads stop spinning. i.e.,
> 
> echo 'on' > '/sys/bus/usb/devices/usb1/power/control
> 
> Any suggestions as to where this regression was introduced and what
> can be done to fix it?

Sorry, this is a known issue, will be fixed in the next 4.19 release
that should be out next week.

If you are curious, it is fixed by commit 45f750c16cae ("xhci: Don't
prevent USB2 bus suspend in state check intended for USB3 only") in
Linus's tree.

thanks,

greg k-h