Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Rafael J. Wysocki]

On Fri, Feb 9, 2018 at 2:43 PM, Markus Demleitner  wrote:
> On Thu, Feb 08, 2018 at 08:12:06PM +0100, Rafael J. Wysocki wrote:
>> On Wednesday, February 7, 2018 11:44:15 PM CET Rafael J. Wysocki wrote:
>> > On Mon, Feb 5, 2018 at 6:06 PM, Rafael J. Wysocki
>> >  wrote:
>> > > On 2/5/2018 3:14 PM, Bjørn Mork wrote:
>> > >>
>> > >> "Rafael J. Wysocki"  writes:
>> > >>>
>> > >>> On 2/4/2018 9:28 PM, Bjørn Mork wrote:
>> > >>>
>> >  But I do wonder if the attached (completely untested!!) patch makes
>> >  things any better?
>> > >>>
>> > >>> I don't think so, the macro is needed too.
>> > >>
>> > >> Doh! Obviously.  Don't know how I managed to miss that.
>> > >>
>> > >>> I'll queue up a full revert of 662591461c4b9a1e3b.
>> > >>
>> > >> Still with the additional exception for "ec == first_ec"?
>> > >>
>> > >
>> > > No, just a full revert for now.
>> >
>> > That doesn't work, because we made some changes on top of this commit.
>> >
>> > I'll send a patch to try tomorrow.
>>
>> Below is a patch for the mainline (should be applicable to 4.15.y) to test.
>> Please let me know if it improves things for you.
>
> It pretty certainly does (patch applied on top of 4.15.0 from
> tarball).  Five out of five wakeup cycles were fast, and the cell
> modem is still properly initialised -- the message went out via the
> resumed modem.

OK, let's do it, then.

Thanks for testing!
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Markus Demleitner]

On Thu, Feb 08, 2018 at 08:12:06PM +0100, Rafael J. Wysocki wrote:
> On Wednesday, February 7, 2018 11:44:15 PM CET Rafael J. Wysocki wrote:
> > On Mon, Feb 5, 2018 at 6:06 PM, Rafael J. Wysocki
> >  wrote:
> > > On 2/5/2018 3:14 PM, Bjørn Mork wrote:
> > >>
> > >> "Rafael J. Wysocki"  writes:
> > >>>
> > >>> On 2/4/2018 9:28 PM, Bjørn Mork wrote:
> > >>>
> >  But I do wonder if the attached (completely untested!!) patch makes
> >  things any better?
> > >>>
> > >>> I don't think so, the macro is needed too.
> > >>
> > >> Doh! Obviously.  Don't know how I managed to miss that.
> > >>
> > >>> I'll queue up a full revert of 662591461c4b9a1e3b.
> > >>
> > >> Still with the additional exception for "ec == first_ec"?
> > >>
> > >
> > > No, just a full revert for now.
> > 
> > That doesn't work, because we made some changes on top of this commit.
> > 
> > I'll send a patch to try tomorrow.
> 
> Below is a patch for the mainline (should be applicable to 4.15.y) to test.
> Please let me know if it improves things for you.

It pretty certainly does (patch applied on top of 4.15.0 from
tarball).  Five out of five wakeup cycles were fast, and the cell
modem is still properly initialised -- the message went out via the
resumed modem.

Thanks!

 -- Markus

[patch retained for reference:]

> 
> The corresponding fix for -stable would still be a full revert of
> 662591461c4b9a1e3b, but it needs to be fixed in the mainline first.
> 
> ---
>  drivers/acpi/ec.c |6 ++
>  1 file changed, 6 insertions(+)
> 
> Index: linux-pm/drivers/acpi/ec.c
> ===
> --- linux-pm.orig/drivers/acpi/ec.c
> +++ linux-pm/drivers/acpi/ec.c
> @@ -1927,6 +1927,9 @@ static int acpi_ec_suspend_noirq(struct
>   ec->reference_count >= 1)
>   acpi_set_gpe(NULL, ec->gpe, ACPI_GPE_DISABLE);
>  
> + if (acpi_sleep_no_ec_events())
> + acpi_ec_enter_noirq(ec);
> +
>   return 0;
>  }
>  
> @@ -1934,6 +1937,9 @@ static int acpi_ec_resume_noirq(struct d
>  {
>   struct acpi_ec *ec = acpi_driver_data(to_acpi_device(dev));
>  
> + if (acpi_sleep_no_ec_events())
> + acpi_ec_leave_noirq(ec);
> +
>   if (ec_no_wakeup && test_bit(EC_FLAGS_STARTED, >flags) &&
>   ec->reference_count >= 1)
>   acpi_set_gpe(NULL, ec->gpe, ACPI_GPE_ENABLE);
> 

-- 
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
A: Top-posting.
Q: What is the most annoying thing in e-mail?

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Rafael J. Wysocki]

On Mon, Feb 5, 2018 at 6:06 PM, Rafael J. Wysocki
 wrote:
> On 2/5/2018 3:14 PM, Bjørn Mork wrote:
>>
>> "Rafael J. Wysocki"  writes:
>>>
>>> On 2/4/2018 9:28 PM, Bjørn Mork wrote:
>>>
 But I do wonder if the attached (completely untested!!) patch makes
 things any better?
>>>
>>> I don't think so, the macro is needed too.
>>
>> Doh! Obviously.  Don't know how I managed to miss that.
>>
>>> I'll queue up a full revert of 662591461c4b9a1e3b.
>>
>> Still with the additional exception for "ec == first_ec"?
>>
>
> No, just a full revert for now.

That doesn't work, because we made some changes on top of this commit.

I'll send a patch to try tomorrow.

Thanks,
Rafael
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Rafael J. Wysocki]

On 2/5/2018 3:14 PM, Bjørn Mork wrote:

"Rafael J. Wysocki"  writes:

On 2/4/2018 9:28 PM, Bjørn Mork wrote:


But I do wonder if the attached (completely untested!!) patch makes
things any better?

I don't think so, the macro is needed too.

Doh! Obviously.  Don't know how I managed to miss that.


I'll queue up a full revert of 662591461c4b9a1e3b.

Still with the additional exception for "ec == first_ec"?



No, just a full revert for now.

The above can be fixed on top of that.

Thanks,
Rafael

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Bjørn Mork]

"Rafael J. Wysocki"  writes:
> On 2/4/2018 9:28 PM, Bjørn Mork wrote:
>
>> But I do wonder if the attached (completely untested!!) patch makes
>> things any better?
>
> I don't think so, the macro is needed too.

Doh! Obviously.  Don't know how I managed to miss that.

> I'll queue up a full revert of 662591461c4b9a1e3b.

Still with the additional exception for "ec == first_ec"?



Bjørn
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Rafael J. Wysocki]

On 2/4/2018 9:28 PM, Bjørn Mork wrote:

Greg KH  writes:

On Sat, Feb 03, 2018 at 07:25:54PM +0100, Markus Demleitner wrote:


It's 662591461c4b9a1e3b9b159dbf37648a585ebaae.  To my eyes, it even
looks plausible that it's causing the problematic behaviour, but
since I can't say I understand what I'd be doing if I dabbled with
the change, I've refrained from guessing how to fix it.

I'm happy to try patches, though.

Ok, thanks.  I've added the authors of this patch to the email here,
perhaps they have an idea of what is going on?

This thing made me curious enough to dive into code I don't understand,
as I have experienced the annoying crazy fan behaviour in resume a few
times on my X1 Carbon 4th gen.

Maybe I missed something, but it looks like commit

  c3a696b6e8f8 ("ACPI / EC: Use busy polling mode when GPE is not enabled")

introduced suspend/resume busy polling for the "boot EC" unintentionally?

The patch moved acpi_ec_leave_noirq() and acpi_ec_leave_noirq()
functions outside the #ifdef CONFIG_PM_SLEEP, so they could be reused
while installing handlers.  But when doing that the

if (ec == first_ec)

conditions on suspend/resume were silently dropped.  I assume the
intention might have been to move those intto acpi_ec_suspend_noirq()
and acpi_ec_resume_noirq() instead? But that didn't happen AFAICS.

Or did I misunderstand this completely?  Not unlikely given that I have
zero clue about what this code is doing...

But I do wonder if the attached (completely untested!!) patch makes
things any better?


I don't think so, the macro is needed too.

I'll queue up a full revert of 662591461c4b9a1e3b.

Thanks,
Rafael

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Bjørn Mork]

Greg KH  writes:
> On Sat, Feb 03, 2018 at 07:25:54PM +0100, Markus Demleitner wrote:
>
>> It's 662591461c4b9a1e3b9b159dbf37648a585ebaae.  To my eyes, it even
>> looks plausible that it's causing the problematic behaviour, but
>> since I can't say I understand what I'd be doing if I dabbled with
>> the change, I've refrained from guessing how to fix it.
>> 
>> I'm happy to try patches, though.
>
> Ok, thanks.  I've added the authors of this patch to the email here,
> perhaps they have an idea of what is going on?

This thing made me curious enough to dive into code I don't understand,
as I have experienced the annoying crazy fan behaviour in resume a few
times on my X1 Carbon 4th gen.

Maybe I missed something, but it looks like commit

 c3a696b6e8f8 ("ACPI / EC: Use busy polling mode when GPE is not enabled")

introduced suspend/resume busy polling for the "boot EC" unintentionally?

The patch moved acpi_ec_leave_noirq() and acpi_ec_leave_noirq()
functions outside the #ifdef CONFIG_PM_SLEEP, so they could be reused
while installing handlers.  But when doing that the

   if (ec == first_ec)

conditions on suspend/resume were silently dropped.  I assume the
intention might have been to move those intto acpi_ec_suspend_noirq()
and acpi_ec_resume_noirq() instead? But that didn't happen AFAICS.

Or did I misunderstand this completely?  Not unlikely given that I have
zero clue about what this code is doing...

But I do wonder if the attached (completely untested!!) patch makes
things any better?


Bjørn

>From 82b8f437a243854a3f1d3c82f85520fd2b71 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bj=C3=B8rn=20Mork?= 
Date: Sun, 4 Feb 2018 21:15:36 +0100
Subject: [PATCH] Revert "ACPI / EC: Drop EC noirq hooks to fix a regression"
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

This reverts commit 662591461c4b9a1e3b9b159dbf37648a585ebaae
and re-introduce the conditions dropped by commit c3a696b6e8f8
("ACPI / EC: Use busy polling mode when GPE is not enabled")

Fixes: c3a696b6e8f8 ("ACPI / EC: Use busy polling mode when GPE is not enabled")
Signed-off-by: Bjørn Mork 
---
 drivers/acpi/ec.c | 20 
 1 file changed, 20 insertions(+)

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index d9f38c645e4a..24a772f66847 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -1905,6 +1905,26 @@ int __init acpi_ec_ecdt_probe(void)
 }
 
 #ifdef CONFIG_PM_SLEEP
+static int acpi_ec_suspend_noirq(struct device *dev)
+{
+	struct acpi_ec *ec =
+		acpi_driver_data(to_acpi_device(dev));
+
+	if (ec == first_ec)
+		acpi_ec_enter_noirq(ec);
+	return 0;
+}
+
+static int acpi_ec_resume_noirq(struct device *dev)
+{
+	struct acpi_ec *ec =
+		acpi_driver_data(to_acpi_device(dev));
+
+	if (ec == first_ec)
+		acpi_ec_leave_noirq(ec);
+	return 0;
+}
+
 static int acpi_ec_suspend(struct device *dev)
 {
 	struct acpi_ec *ec =
-- 
2.11.0

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Greg KH]

On Sat, Feb 03, 2018 at 07:25:54PM +0100, Markus Demleitner wrote:
> On Tue, Jan 30, 2018 at 07:32:04AM +0100, Greg KH wrote:
> > On Mon, Jan 29, 2018 at 07:21:09PM +0100, Markus Demleitner wrote:
> > > A while ago I opened bug #197863 in the kernel bugzilla:
> > > 
> > > https://bugzilla.kernel.org/show_bug.cgi?id=197863
> > > 
> > > Essentially, xhci_hcd on a resume from RAM takes several seconds on a
> > > Thinkpad X240 that is equipped with a Sierra LTE modem after an
> > > upgrade to 4.13:
> [...]
> > > Now, interestingly, there are quick resumes in 4.15.0, too, now and
> > > then.  In that case, things look pretty much like on 4.12.2.  Here's
> > > a 4.15.0 fast resume example:
> > > 
> > > [  873.127570] usb 1-4: device firmware changed
> > > [  873.277351] usb 1-8: reset high-speed USB device number 4 using 
> > > xhci_hcd
> > > [  873.515141] restoring control ----0101/0/2
> > > [  873.583238] OOM killer enabled.
> > > [  873.583240] Restarting tasks ... 
> > > [  873.583339] usb 1-4: USB disconnect, device number 10
> > > [  873.586356] done.
> > > [  873.604420] PM: suspend exit
> > > [  873.737283] usb 1-4: new high-speed USB device number 11 using xhci_hcd
> > > [  880.867398] usb 1-4: device descriptor read/64, error -110
> > > [  881.175558] usb 1-4: New USB device found, idVendor=1199, 
> > > idProduct=a001
> > > [  881.175563] usb 1-4: New USB device strings: Mfr=1, Product=2, 
> > > SerialNumber=3
> > > [  881.175566] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
> > > [  881.175568] usb 1-4: Manufacturer: Sierra Wireless Inc.
> > > [  881.175570] usb 1-4: SerialNumber: 013937002544516
> > > 
> > > Any guess what might be behind this?
> > 
> > Any chance you can run 'git bisect' to find the offending commit for
> > this issue?
> 
> It's 662591461c4b9a1e3b9b159dbf37648a585ebaae.  To my eyes, it even
> looks plausible that it's causing the problematic behaviour, but
> since I can't say I understand what I'd be doing if I dabbled with
> the change, I've refrained from guessing how to fix it.
> 
> I'm happy to try patches, though.

Ok, thanks.  I've added the authors of this patch to the email here,
perhaps they have an idea of what is going on?

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Markus Demleitner]

On Tue, Jan 30, 2018 at 07:32:04AM +0100, Greg KH wrote:
> On Mon, Jan 29, 2018 at 07:21:09PM +0100, Markus Demleitner wrote:
> > A while ago I opened bug #197863 in the kernel bugzilla:
> > 
> > https://bugzilla.kernel.org/show_bug.cgi?id=197863
> > 
> > Essentially, xhci_hcd on a resume from RAM takes several seconds on a
> > Thinkpad X240 that is equipped with a Sierra LTE modem after an
> > upgrade to 4.13:
[...]
> > Now, interestingly, there are quick resumes in 4.15.0, too, now and
> > then.  In that case, things look pretty much like on 4.12.2.  Here's
> > a 4.15.0 fast resume example:
> > 
> > [  873.127570] usb 1-4: device firmware changed
> > [  873.277351] usb 1-8: reset high-speed USB device number 4 using xhci_hcd
> > [  873.515141] restoring control ----0101/0/2
> > [  873.583238] OOM killer enabled.
> > [  873.583240] Restarting tasks ... 
> > [  873.583339] usb 1-4: USB disconnect, device number 10
> > [  873.586356] done.
> > [  873.604420] PM: suspend exit
> > [  873.737283] usb 1-4: new high-speed USB device number 11 using xhci_hcd
> > [  880.867398] usb 1-4: device descriptor read/64, error -110
> > [  881.175558] usb 1-4: New USB device found, idVendor=1199, idProduct=a001
> > [  881.175563] usb 1-4: New USB device strings: Mfr=1, Product=2, 
> > SerialNumber=3
> > [  881.175566] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
> > [  881.175568] usb 1-4: Manufacturer: Sierra Wireless Inc.
> > [  881.175570] usb 1-4: SerialNumber: 013937002544516
> > 
> > Any guess what might be behind this?
> 
> Any chance you can run 'git bisect' to find the offending commit for
> this issue?

It's 662591461c4b9a1e3b9b159dbf37648a585ebaae.  To my eyes, it even
looks plausible that it's causing the problematic behaviour, but
since I can't say I understand what I'd be doing if I dabbled with
the change, I've refrained from guessing how to fix it.

I'm happy to try patches, though.

Thanks,

  Markus

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Markus Demleitner]

Hi Oliver,

On Tue, Jan 30, 2018 at 08:45:17AM +0100, Oliver Neukum wrote:
> Am Montag, den 29.01.2018, 19:21 +0100 schrieb Markus Demleitner:
> > 
> > Any guess what might be behind this?
> > 
> have you checked the persist attribute between the versions working
> well and working badly?

Persist is 1 in both cases.  But persist was a good point anyway --
there's *probably* little point having an LTE card persist (I don't
think it could keep registered with the mobile network on 5..25 mW),
and so I tried 

echo 0 > /sys/bus/usb/devices/1-4/power/persist

before suspending.  Doing this three times before a suspend, the box
came back three out of three with 4.15.0.  Suspending without the
intervening write immediately brought back the 10 s timeout.  Then
again two fast resumes with an echo before it.  And another one.

So -- I think I have a good workaround for me[1].

I'll try to get myself to git-bisecting the problem, because I see
it'd be better if we could figure out why persist hasn't been a
problem before 4.13.0 and has been causing the long resume delay from
then on.  I'm not making actual promises, though (I'm a bit scared of
checkout sizes, build times, and lots of reboots; log(n) still rises
fairly steeply for low n...)

Thanks for providing the useful hint,

 Markus


[1] For anyone who ended up here looking for a solution:  I dumped

  #!/bin/sh
  case "$1" in
  suspend|hibernate)
  echo 0 > /sys/bus/usb/devices/1-4/power/persist
  ;;
  esac
  exit 0

into a file

/etc/pm/sleep.d/05sierra

(works with pm-utils, probably not with systemd)

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Oliver Neukum]

Am Montag, den 29.01.2018, 19:21 +0100 schrieb Markus Demleitner:
> 
> Any guess what might be behind this?
> 

Hi,

have you checked the persist attribute between the versions working
well and working badly?

Regards
Oliver

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Greg KH]

On Mon, Jan 29, 2018 at 07:21:09PM +0100, Markus Demleitner wrote:
> Hi,
> 
> A while ago I opened bug #197863 in the kernel bugzilla:
> 
> https://bugzilla.kernel.org/show_bug.cgi?id=197863
> 
> Essentially, xhci_hcd on a resume from RAM takes several seconds on a
> Thinkpad X240 that is equipped with a Sierra LTE modem after an
> upgrade to 4.13:
> 
> On Mon, Nov 20, 2017 at 11:24:09AM +, bugzilla-dae...@bugzilla.kernel.org 
> wrote:
> > https://bugzilla.kernel.org/show_bug.cgi?id=197863
> > 
> > --- Comment #2 from Greg Kroah-Hartman (g...@kroah.com) ---
> > On Mon, Nov 20, 2017 at 09:02:46AM +, 
> > bugzilla-dae...@bugzilla.kernel.org
> > wrote:
> > > I think your speculation is right, the xhci has taken too much time for a
> > > reset:
> > > [   39.292052] usb 1-4: reset high-speed USB device number 2 using 
> > > xhci_hcd
> > > [   45.812046] usb 1-4: device descriptor read/64, error -110
> > > [   46.262082] usb 1-7: reset full-speed USB device number 3 using 
> > > xhci_hcd
> > > I don't know if it should be reset in this case, let me switch to usb
> > > component for suggestion.
> > 
> > All USB bugs should be sent to the linux-usb@vger.kernel.org mailing
> > list, and not entered into bugzilla.  Please bring this issue up there,
> > if it is still a problem in the latest kernel release.
> 
> The trouble persists in 4.15.0, and wakeup keeps being fast in 4.12.X.
> 
> I have just looked at things a bit more closely, and it would seem
> the changes are due to the USB subsystem blocking until the (slow)
> LTE modem sends an all clear.
> 
> Here's a dmesg excerpt from 4.15.0 slow resume:
> 
> 
> [  417.234716] ACPI: Low-level resume complete
> ...about 30 lines of non-USB jabber elided here...
> [  419.184328] usb usb1: root hub lost power or was reset
> [  419.184332] usb usb2: root hub lost power or was reset
> [  419.463469] usb 3-1: reset high-speed USB device number 2 using ehci-pci
> [  419.583449] usb 1-8: reset high-speed USB device number 4 using xhci_hcd
> [  419.588769] psmouse serio1: synaptics: queried min coordinates: x 
> [1232..], y [1216..]
> [  419.821258] restoring control ----0101/0/2
> [  419.913513] usb 1-4: reset high-speed USB device number 9 using xhci_hcd
> ...this is when the system hangs; the screen is on, but now wakeup
> actions are executed until...
> [  427.343486] usb 1-4: device descriptor read/64, error -110
> [  427.662438] OOM killer enabled.
> [  427.662440] Restarting tasks ... done.
> [  427.683062] PM: suspend exit
> 
> If you look at the corresponding sequence in 4.12.2:
> 
> [   31.678001] usb 1-4: reset high-speed USB device number 2 using xhci_hcd
> [   31.848202] usb 1-4: device firmware changed
> [   31.988048] usb 1-7: reset full-speed USB device number 3 using xhci_hcd
> [   32.159069] PM: resume of devices complete after 1170.527 msecs
> [   32.159546] OOM killer enabled.
> [   32.159548] Restarting tasks ... 
> [   32.159650] usb 1-4: USB disconnect, device number 2
> [   32.162274] done.
> [   32.297920] usb 1-4: new high-speed USB device number 5 using xhci_hcd
> [   32.469119] usb 1-4: New USB device found, idVendor=8087, idProduct=0716
> [   32.469124] usb 1-4: New USB device strings: Mfr=0, Product=0, 
> SerialNumber=0
> [   35.639922] usb 1-4: USB disconnect, device number 5
> [   38.438173] usb 1-4: new high-speed USB device number 6 using xhci_hcd
> [   38.616527] usb 1-4: New USB device found, idVendor=1199, idProduct=a001
> [   38.616535] usb 1-4: New USB device strings: Mfr=1, Product=2, 
> SerialNumber=3
> [   38.616539] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
> [   38.616543] usb 1-4: Manufacturer: Sierra Wireless Inc.
> [   38.616545] usb 1-4: SerialNumber: 013937002544516
> 
> ...it seems that the resume of the Sierra card happens
> "aynchronously", if you will.  In the "slow" cases, I just notice, no
> messages about the Sierra Wireless card appear in dmesg, but the
> modem still works.
> 
> Now, interestingly, there are quick resumes in 4.15.0, too, now and
> then.  In that case, things look pretty much like on 4.12.2.  Here's
> a 4.15.0 fast resume example:
> 
> [  873.127570] usb 1-4: device firmware changed
> [  873.277351] usb 1-8: reset high-speed USB device number 4 using xhci_hcd
> [  873.515141] restoring control ----0101/0/2
> [  873.583238] OOM killer enabled.
> [  873.583240] Restarting tasks ... 
> [  873.583339] usb 1-4: USB disconnect, device number 10
> [  873.586356] done.
> [  873.604420] PM: suspend exit
> [  873.737283] usb 1-4: new high-speed USB device number 11 using xhci_hcd
> [  880.867398] usb 1-4: device descriptor read/64, error -110
> [  881.175558] usb 1-4: New USB device found, idVendor=1199, idProduct=a001
> [  881.175563] usb 1-4: New USB device strings: Mfr=1, Product=2, 
> SerialNumber=3
> [  881.175566] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
> [  881.175568] usb 1-4: Manufacturer: Sierra Wireless Inc.
> [  881.175570] 

Re: [Bug 197863] Thinkpad X240 resume dramatically slower on kernels 4.13+

[Markus Demleitner]

Hi,

A while ago I opened bug #197863 in the kernel bugzilla:

https://bugzilla.kernel.org/show_bug.cgi?id=197863

Essentially, xhci_hcd on a resume from RAM takes several seconds on a
Thinkpad X240 that is equipped with a Sierra LTE modem after an
upgrade to 4.13:

On Mon, Nov 20, 2017 at 11:24:09AM +, bugzilla-dae...@bugzilla.kernel.org 
wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=197863
> 
> --- Comment #2 from Greg Kroah-Hartman (g...@kroah.com) ---
> On Mon, Nov 20, 2017 at 09:02:46AM +, bugzilla-dae...@bugzilla.kernel.org
> wrote:
> > I think your speculation is right, the xhci has taken too much time for a
> > reset:
> > [   39.292052] usb 1-4: reset high-speed USB device number 2 using xhci_hcd
> > [   45.812046] usb 1-4: device descriptor read/64, error -110
> > [   46.262082] usb 1-7: reset full-speed USB device number 3 using xhci_hcd
> > I don't know if it should be reset in this case, let me switch to usb
> > component for suggestion.
> 
> All USB bugs should be sent to the linux-usb@vger.kernel.org mailing
> list, and not entered into bugzilla.  Please bring this issue up there,
> if it is still a problem in the latest kernel release.

The trouble persists in 4.15.0, and wakeup keeps being fast in 4.12.X.

I have just looked at things a bit more closely, and it would seem
the changes are due to the USB subsystem blocking until the (slow)
LTE modem sends an all clear.

Here's a dmesg excerpt from 4.15.0 slow resume:


[  417.234716] ACPI: Low-level resume complete
...about 30 lines of non-USB jabber elided here...
[  419.184328] usb usb1: root hub lost power or was reset
[  419.184332] usb usb2: root hub lost power or was reset
[  419.463469] usb 3-1: reset high-speed USB device number 2 using ehci-pci
[  419.583449] usb 1-8: reset high-speed USB device number 4 using xhci_hcd
[  419.588769] psmouse serio1: synaptics: queried min coordinates: x [1232..], 
y [1216..]
[  419.821258] restoring control ----0101/0/2
[  419.913513] usb 1-4: reset high-speed USB device number 9 using xhci_hcd
...this is when the system hangs; the screen is on, but now wakeup
actions are executed until...
[  427.343486] usb 1-4: device descriptor read/64, error -110
[  427.662438] OOM killer enabled.
[  427.662440] Restarting tasks ... done.
[  427.683062] PM: suspend exit

If you look at the corresponding sequence in 4.12.2:

[   31.678001] usb 1-4: reset high-speed USB device number 2 using xhci_hcd
[   31.848202] usb 1-4: device firmware changed
[   31.988048] usb 1-7: reset full-speed USB device number 3 using xhci_hcd
[   32.159069] PM: resume of devices complete after 1170.527 msecs
[   32.159546] OOM killer enabled.
[   32.159548] Restarting tasks ... 
[   32.159650] usb 1-4: USB disconnect, device number 2
[   32.162274] done.
[   32.297920] usb 1-4: new high-speed USB device number 5 using xhci_hcd
[   32.469119] usb 1-4: New USB device found, idVendor=8087, idProduct=0716
[   32.469124] usb 1-4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[   35.639922] usb 1-4: USB disconnect, device number 5
[   38.438173] usb 1-4: new high-speed USB device number 6 using xhci_hcd
[   38.616527] usb 1-4: New USB device found, idVendor=1199, idProduct=a001
[   38.616535] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[   38.616539] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
[   38.616543] usb 1-4: Manufacturer: Sierra Wireless Inc.
[   38.616545] usb 1-4: SerialNumber: 013937002544516

...it seems that the resume of the Sierra card happens
"aynchronously", if you will.  In the "slow" cases, I just notice, no
messages about the Sierra Wireless card appear in dmesg, but the
modem still works.

Now, interestingly, there are quick resumes in 4.15.0, too, now and
then.  In that case, things look pretty much like on 4.12.2.  Here's
a 4.15.0 fast resume example:

[  873.127570] usb 1-4: device firmware changed
[  873.277351] usb 1-8: reset high-speed USB device number 4 using xhci_hcd
[  873.515141] restoring control ----0101/0/2
[  873.583238] OOM killer enabled.
[  873.583240] Restarting tasks ... 
[  873.583339] usb 1-4: USB disconnect, device number 10
[  873.586356] done.
[  873.604420] PM: suspend exit
[  873.737283] usb 1-4: new high-speed USB device number 11 using xhci_hcd
[  880.867398] usb 1-4: device descriptor read/64, error -110
[  881.175558] usb 1-4: New USB device found, idVendor=1199, idProduct=a001
[  881.175563] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  881.175566] usb 1-4: Product: Sierra Wireless EM7345 4G LTE
[  881.175568] usb 1-4: Manufacturer: Sierra Wireless Inc.
[  881.175570] usb 1-4: SerialNumber: 013937002544516

Any guess what might be behind this?

Thanks,

  Markus

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majord...@vger.kernel.org
More majordomo info at