Link to the patch : https://chromium-review.googlesource.com/c/chromiumos/third_party/kernel/+/1014402

Shyam, can you please help route this? I think Anshuman has done some work in USB resume area, but may be there is a better person.

Hey guys. The chromium address added here as owner is not mine. Please give me a few hours to get the right owner.

Thanks Ravi.

Google, 

Can you please add the following folks? 

Chang, Wei Shun <wei.shun.chang@intel.com>; Chen, Kane <kane.chen@intel.com>; Pawnikar, Sumeet R <sumeet.r.pawnikar@intel.com>

Kane, Sumeet, WS,

Ravi is checking to see if this is Poppy specific or Kaby lake specific. In the meantime can you look into the bug and provide what logs you need.

Thanks,
Shyam

Hi Ravi,
Sorry, I'm not sure if I fully understand the problem.
Is hammer a keyboard of Soraka?
Is hammer able to wake the system from s0ix but the wakeup_count is not increased with BT disabled?
How about other usb keyboard?

Did you monitor this count?
/sys/devices/pci0000:00/0000:00:14.0/usb1/x-x/power/wakeup_count?



Thank you

Hi Kane,


Is hammer a keyboard of Soraka?
Yes. Hammer is a keyboard for soraka.

Is hammer able to wake the system from s0ix but the wakeup_count is not increased with BT disabled?
Yes.
How about other usb keyboard?
So is the case, if the usb keyboard is directly connected to the roothub. But the wakeup count increments when the USB keyboard is connected to the hub connected to the hub connected to the roothub

Did you monitor this count?
/sys/devices/pci0000:00/0000:00:14.0/usb1/x-x/power/wakeup_count?

We want to be able to identify the exact device that woke the system up.  /sys/devices/pci0000:00/0000:00:14.0/usb1/power/wakeup_count  would normally be the USB 2.0 root hub. We want the wakeup_count of USB keyboard to increment.

Let us say the USB keyboard is /sys/devices/pci0000:00/0000:00:14.0/usb1-1/. we want /sys/devices/pci0000:00/0000:00:14.0/usb1-1/power/wakeup_count to increment.  That is what we are trying to achieve.

Hi Ravi,
I can reproduce issue on my soraka with BT disabled.

Also, here is something I noticed.
With BT disabled.
Issue is gone if I connect a 2.0 USB disk or lan dongle on other port on root hub
Issue can be repro if I connect a USB keyboard.

I can also see the below event log no matter issue is repro or not.
2018-04-19 20:52:06 | Wake Source | PME - XHCI (USB 2.0 port) | 2 ==> this digit is port number

So, I think the issue might not be directly related BT.
It seems the counter depends on what type of USB device left on the bus.
Thank you

I do not see USB_PORT_STAT_C_SUSPEND bit in the kernel when it comes to the problem.

i.e.,

localhost ~ # tail -f /var/log/messages | grep -e 'usb1-port2'
... // do suspend-to-idle
2018-04-20T17:18:27.368750+08:00 DEBUG kernel: [ 1011.364989] usb usb1-port2: status 0103 change 0004
... // turn-off BT, do suspend again.
2018-04-20T17:18:50.342995+08:00 DEBUG kernel: [ 1034.317637] usb usb1-port2: status 0107 change 0000

Manually twiddle the autosuspend off on 1-3, it works fine for 1-2.

e.g.,
echo on > /sys/devices/pci0000\:00/0000\:00\:14.0/usb1/1-3/power/control	# don't get confused by the 'on' string.

tail -f /var/log/messages | grep -e 'usb1-port2'
// do suspend-to-idle w/ BT disabled
2018-04-20T17:37:52.363332+08:00 DEBUG kernel: [ 2176.147387] usb usb1-port2: status 0103 change 0004
2018-04-20T17:37:52.364868+08:00 DEBUG kernel: [ 2176.397876] usb usb1-port2: status 0103, change 0000, 12 Mb/s

Sorry, lost track of this bug. What is the conclusion here ? 

As per comment #15 disabling autosuspend on bluetooth controller prevents the problem. but do we know why ? Is it possible to fix this so that the flag is set all the time?

I don't have a conclusion by far: this odd (USB_PORT_STAT_C_SUSPEND not appears) only happens in system-suspend; namely, with the original test setup, it does not happen when it comes to runtime-suspend.

e.g, comparing the behavior by 'tail -f /var/log/messages | grep usb1-port2' between system-suspend and runtime-suspend. (need some setup to enable usbcore kernel debug messages)

Also, w/ some USB devices (not all devices as I evaluated) hook onto either one of USB-C ports of my soraka, it may get around the issue as well. i.e., USB_PORT_STAT_C_SUSPEND appears after system suspend-resume .

Hi Harry,
Thanks for the insight and thanks for the effort. This is the only blocker to enabling dark resume on poppy devices. It would be great if we can fix this. Please let me know if I can be of any help.

I had some traces, a setup as that there are hammer (port2, aka. 1-2) and BT (port3) on usb bus1 only.

When BT is off and system is entering suspend, both 1-2 and 1-3 are already been pushed into USB_STATE_SUSPENDED thus the power managment will not call usb_port_suspend(), while if the BT is on, 1-3 will be USB_STATE_CONFIGURED during suspending and invoke usb_port_suspend (through generic_suspend call).

@Ravi please find my inline answers
My Questions:
How is disabling bluetooth controller affecting other devices on the root hub.  Is this a bug ? If so can this be fixed ? 

This is something race with USB_RESUME_TIMEOUT, having a delay before checking 
USB_PORT_STAT_C_SUSPEND may fix this.

Expected behavior : when there is a wake from a port on roothub, We expect the status of the port to say it resumed and indicated change in the port status (C_PORT_STATE_SUSPEND).

When usb 2.0 device issue a remote wake up , xhci raise a interrupt and interrupter handler  detect a port resume event and schedules a timer of 40 ms to resume a port, so any change is port status or in  port change will only reflect after 40 ms.

https://elixir.bootlin.com/linux/latest/source/drivers/usb/host/xhci-hub.c#L951

https://elixir.bootlin.com/linux/latest/source/drivers/usb/host/xhci-hub.c#L1014

So if hub_port_status will only reflect any change port status and port change bit.

But What happens if any device 2.0 device is connected: Explanation is, if for any USB 2.0 device or any of it's descendant have remote wakeup disabled or wakeup disabled , this particular device does not enable suspend feature on that port , 
https://elixir.bootlin.com/linux/latest/source/drivers/usb/core/hub.c#L3190

Subsequently it automatically enters to low power mode when system enters to suspend, afterwards root hub resumes it on its own, which make xhci_bus_resume to wait for 40ms, 

https://elixir.bootlin.com/linux/latest/source/drivers/usb/host/xhci-hub.c#L1647

which really turns up change in the port status and port change bit (C_PORT_STATE_SUSPEND) of the port which actually cause the remote wakeup.

You can also observed this issue of wakeup count not incremented, when BT is enabled and its wakeup attributes also enabled or when a usb 3.0 Ethernet adapter is connected. 

I am able to see delayed 40+ ms USB_PORT_STAT_C_SUSPEND:

e.g.
2018-05-20T22:34:45.962781+08:00 DEBUG kernel: [ 1532.882658] hub 1-0:1.0: hub_resume
2018-05-20T22:34:45.962786+08:00 DEBUG kernel: [ 1532.882686] xhci_hcd 0000:00:14.0: get port status, actual port 0 status  = 0x2a0
2018-05-20T22:34:45.962791+08:00 DEBUG kernel: [ 1532.882690] xhci_hcd 0000:00:14.0: Get port status returned 0x100
2018-05-20T22:34:45.962795+08:00 DEBUG kernel: [ 1532.882737] xhci_hcd 0000:00:14.0: get port status, actual port 1 status  = 0x663
2018-05-20T22:34:45.962800+08:00 DEBUG kernel: [ 1532.882742] xhci_hcd 0000:00:14.0: Get port status returned 0x107
2018-05-20T22:34:45.962804+08:00 DEBUG kernel: [ 1532.882761] usb usb1-port2: status 0107 change 0000
...
2018-05-20T22:34:45.964789+08:00 DEBUG kernel: [ 1532.883661] xhci_hcd 0000:00:14.0: clear USB_PORT_FEAT_SUSPEND
2018-05-20T22:34:45.964793+08:00 DEBUG kernel: [ 1532.883670] xhci_hcd 0000:00:14.0: PORTSC 0663
2018-05-20T22:34:45.964797+08:00 DEBUG kernel: [ 1532.883704] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
2018-05-20T22:34:45.964801+08:00 DEBUG kernel: [ 1532.883708] xhci_hcd 0000:00:14.0: Port Status Change Event for port 2
2018-05-20T22:34:45.964805+08:00 DEBUG kernel: [ 1532.883721] xhci_hcd 0000:00:14.0: port resume event for port 2
2018-05-20T22:34:45.964809+08:00 DEBUG kernel: [ 1532.883742] xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
2018-05-20T22:34:45.971628+08:00 DEBUG kernel: [ 1532.891690] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
2018-05-20T22:34:46.003677+08:00 DEBUG kernel: [ 1532.923900] xhci_hcd 0000:00:14.0: Port Status Change Event for port 2
2018-05-20T22:34:46.003703+08:00 DEBUG kernel: [ 1532.923912] xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
2018-05-20T22:34:46.003706+08:00 DEBUG kernel: [ 1532.923917] usb 1-2: usb auto-resume
2018-05-20T22:34:46.003718+08:00 DEBUG kernel: [ 1532.923962] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0004
2018-05-20T22:34:46.045674+08:00 DEBUG kernel: [ 1532.964954] xhci_hcd 0000:00:14.0: get port status, actual port 1 status  = 0x603
2018-05-20T22:34:46.045719+08:00 DEBUG kernel: [ 1532.964966] xhci_hcd 0000:00:14.0: Get port status returned 0x40103
2018-05-20T22:34:46.056695+08:00 DEBUG kernel: [ 1532.975955] xhci_hcd 0000:00:14.0: clear port suspend/resume change, actual port 1 status  = 0x603
2018-05-20T22:34:46.056738+08:00 DEBUG kernel: [ 1532.975988] usb 1-2: finish resume

Reading the thread again I suppose we may further tinker the original patch like this, exclude autosuspend case:

diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index fd9285d..ec136a2 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -3474,6 +3474,10 @@ int usb_port_resume(struct usb_device *udev, pm_message_t msg)
                 */
                status = hub_port_status(hub, port1, &portstatus, &portchange);
 
+               if (status == 0 && !PMSG_IS_AUTO(msg) &&
+                       (portchange & USB_PORT_STAT_C_SUSPEND))
+                       pm_wakeup_event(&udev->dev, 0);
+
                /* TRSMRCY = 10 msec */
                msleep(10);
        }

This does not change the log behavior while makes the counter increase one when it comes to system suspend/resume.

Same as #22, unwind more lines of context.

diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index fd9285d..ec136a2 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -3465,24 +3465,28 @@ int usb_port_resume(struct usb_device *udev, pm_message_t msg)
        } else {
                /* drive resume for USB_RESUME_TIMEOUT msec */
                dev_dbg(&udev->dev, "usb %sresume\n",
                                (PMSG_IS_AUTO(msg) ? "auto-" : ""));
                msleep(USB_RESUME_TIMEOUT);
 
                /* Virtual root hubs can trigger on GET_PORT_STATUS to
                 * stop resume signaling.  Then finish the resume
                 * sequence.
                 */
                status = hub_port_status(hub, port1, &portstatus, &portchange);
 
+               if (status == 0 && !PMSG_IS_AUTO(msg) &&
+                       (portchange & USB_PORT_STAT_C_SUSPEND))
+                       pm_wakeup_event(&udev->dev, 0);
+
                /* TRSMRCY = 10 msec */
                msleep(10);
        }

i think when usb_port_reusme clears USB_PORT_FEAT_SUSPEND for any ports, 

https://elixir.bootlin.com/linux/latest/source/drivers/usb/core/hub.c#L3448

xhci enables the port_c_suspend for that port also.

https://elixir.bootlin.com/linux/latest/source/drivers/usb/host/xhci-hub.c#L1356

So i think it may end up to increment the wakeup count for wrong port also.

Alternately, we may consider move USB_PORT_STAT_C_SUSPEND evaluation to label SuspendCleared; such that, simplify and unify two check points into one. (else it would double count in case BT on)


diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index fd9285d..e2910b5 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -3449,8 +3449,6 @@ int usb_port_resume(struct usb_device *udev, pm_message_t msg)
        /* Skip the initial Clear-Suspend step for a remote wakeup */
        status = hub_port_status(hub, port1, &portstatus, &portchange);
        if (status == 0 && !port_is_suspended(hub, portstatus)) {
-               if (portchange & USB_PORT_STAT_C_SUSPEND)
-                       pm_wakeup_event(&udev->dev, 0);
                goto SuspendCleared;
        }
 
@@ -3486,9 +3484,12 @@ int usb_port_resume(struct usb_device *udev, pm_message_t msg)
                                usb_clear_port_feature(hub->hdev, port1,
                                        USB_PORT_FEAT_C_PORT_LINK_STATE);
                } else {
-                       if (portchange & USB_PORT_STAT_C_SUSPEND)
+                       if (portchange & USB_PORT_STAT_C_SUSPEND) {
                                usb_clear_port_feature(hub->hdev, port1,
                                                USB_PORT_FEAT_C_SUSPEND);
+                               if (!PMSG_IS_AUTO(msg))
+                                       pm_wakeup_event(&udev->dev, 0);
+                       }
                }
        }

I have started a thread for this issue with linux-usb mailing list.

https://www.spinics.net/lists/linux-usb/msg169432.html

Alan Stern (USB subsystem maintainer) acknowledged the problem and told, for external hubs it may not be possible to fix this problem. 

Quoting his latest response on this thread,

>"It sounds like you want the code in usb_port_resume() to check and see
> whether the port has already received a wakeup signal and hasn't
> finished processing it yet.
> 
> There's no way to do this for ports on external hubs, but in principle 
> it can be done for ports on root hubs.  If we see that a wakeup signal 
> was received, we can call pm_wakeup_event().  Will that be good enough?"  

"Something is better than nothing" :-) 

Also, I think we will have significant percentage of use cases where the user might be connecting his USB devices directly without a hub. So if we can tell which "rootport" was a wakeup source, that will still be better than today (where we have nothing).