Lid switch triggered suspend takes much longer than UI triggered suspend

[Chris Gregan]

IBM T460
5.0.0-13-generic #14-Ubuntu SMP Mon Apr 15 14:59:14 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

When triggering a suspend even from the lid switch of my Lenovo T460 it takes 30 seconds to reach suspend state. Several others with different models of Lenovo laptops have also reproduced this issue.

It seems this is isolated to the lid switch as UI triggered suspend (alt+power icon) is far faster.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1829399

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Andrea Righi (arighi)]

Hi Chris, just to make sure I understand (from a kernel perspective), can you confirm that `echo mem > /sys/power/state` is also fast at reaching the suspend state?

In that case it would be interesting to check if there's a delay at detecting the state of the lid switch. For this, could you run the following command in a bash session:

$ while :; do echo `date` - `cat /proc/acpi/button/lid/LID0/state`; sleep 1; done

Close the lid, re-open it and you should notice something like this:

Thu May 16 17:50:42 CEST 2019 - state: open
Thu May 16 17:50:43 CEST 2019 - state: open
Thu May 16 17:50:44 CEST 2019 - state: open
Thu May 16 17:50:45 CEST 2019 - state: closed
Thu May 16 17:50:46 CEST 2019 - state: closed
Thu May 16 17:50:47 CEST 2019 - state: closed
Thu May 16 17:50:48 CEST 2019 - state: open
Thu May 16 17:50:49 CEST 2019 - state: open
Thu May 16 17:50:50 CEST 2019 - state: open
^C

Note that I have set the "lid close action" to do nothing, in this way we can better isolate the problem. Thanks.

[Chris Gregan (cgregan)]

This is interesting.

`echo mem > /sys/power/state`
This command was instant S3. The screen went black and the power light
immediately began to blink.

However...for lid switch the power light takes around 10 seconds to begin
to pulse, but the state immediately switches.

Fri 17 May 2019 09:48:22 AM CEST - state: open
Fri 17 May 2019 09:48:23 AM CEST - state: open
Fri 17 May 2019 09:48:24 AM CEST - state: open
Fri 17 May 2019 09:48:25 AM CEST - state: closed
Fri 17 May 2019 09:48:26 AM CEST - state: closed
Fri 17 May 2019 09:48:27 AM CEST - state: closed

It seems although detection if immediate, it takes 10 seconds to process?

On Thu, May 16, 2019 at 6:05 PM Andrea Righi <email address hidden>
wrote:

> Hi Chris, just to make sure I understand (from a kernel perspective),
> can you confirm that `echo mem > /sys/power/state` is also fast at
> reaching the suspend state?
>
> In that case it would be interesting to check if there's a delay at
> detecting the state of the lid switch. For this, could you run the
> following command in a bash session:
>
> $ while :; do echo `date` - `cat /proc/acpi/button/lid/LID0/state`;
> sleep 1; done
>
> Close the lid, re-open it and you should notice something like this:
>
> Thu May 16 17:50:42 CEST 2019 - state: open
> Thu May 16 17:50:43 CEST 2019 - state: open
> Thu May 16 17:50:44 CEST 2019 - state: open
> Thu May 16 17:50:45 CEST 2019 - state: closed
> Thu May 16 17:50:46 CEST 2019 - state: closed
> Thu May 16 17:50:47 CEST 2019 - state: closed
> Thu May 16 17:50:48 CEST 2019 - state: open
> Thu May 16 17:50:49 CEST 2019 - state: open
> Thu May 16 17:50:50 CEST 2019 - state: open
> ^C
>
> Note that I have set the "lid close action" to do nothing, in this way
> we can better isolate the problem. Thanks.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1829399
>
> Title:
> Lid switch triggered suspend takes much longer than UI triggered
> suspend
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1829399/+subscriptions
>

--

Chris Gregan
Engineering Manager
Solutions QA/Techops
<email address hidden>

[Chris Gregan (cgregan)]

Looks like it was actually longer than 10 seconds as I opened the lid 1 sec
after the power light began to pulse.

Fri 17 May 2019 09:48:20 AM CEST - state: open
Fri 17 May 2019 09:48:21 AM CEST - state: open
Fri 17 May 2019 09:48:22 AM CEST - state: open
Fri 17 May 2019 09:48:23 AM CEST - state: open
Fri 17 May 2019 09:48:24 AM CEST - state: open
Fri 17 May 2019 09:48:25 AM CEST - state: closed
Fri 17 May 2019 09:48:26 AM CEST - state: closed
Fri 17 May 2019 09:48:27 AM CEST - state: closed
Fri 17 May 2019 09:48:28 AM CEST - state: closed
Fri 17 May 2019 09:48:29 AM CEST - state: closed
Fri 17 May 2019 09:48:30 AM CEST - state: closed
Fri 17 May 2019 09:48:31 AM CEST - state: closed
Fri 17 May 2019 09:48:33 AM CEST - state: closed
Fri 17 May 2019 09:48:34 AM CEST - state: closed
Fri 17 May 2019 09:48:35 AM CEST - state: closed
Fri 17 May 2019 09:48:36 AM CEST - state: closed
Fri 17 May 2019 09:48:37 AM CEST - state: closed
Fri 17 May 2019 09:48:38 AM CEST - state: closed
Fri 17 May 2019 09:48:39 AM CEST - state: closed
Fri 17 May 2019 09:48:40 AM CEST - state: closed
Fri 17 May 2019 09:48:41 AM CEST - state: closed
Fri 17 May 2019 09:48:42 AM CEST - state: closed
Fri 17 May 2019 09:48:43 AM CEST - state: closed
Fri 17 May 2019 09:48:44 AM CEST - state: closed
Fri 17 May 2019 09:48:45 AM CEST - state: closed
Fri 17 May 2019 09:48:46 AM CEST - state: closed
Fri 17 May 2019 09:48:47 AM CEST - state: closed
Fri 17 May 2019 09:48:48 AM CEST - state: closed
Fri 17 May 2019 09:48:49 AM CEST - state: closed
Fri 17 May 2019 09:48:50 AM CEST - state: closed
Fri 17 May 2019 09:48:51 AM CEST - state: closed
Fri 17 May 2019 09:48:52 AM CEST - state: closed
Fri 17 May 2019 09:48:53 AM CEST - state: closed
Fri 17 May 2019 09:48:54 AM CEST - state: closed
Fri 17 May 2019 09:48:55 AM CEST - state: closed
Fri 17 May 2019 09:49:00 AM CEST - state: open
Fri 17 May 2019 09:49:02 AM CEST - state: open
Fri 17 May 2019 09:49:03 AM CEST - state: open
^C

On Fri, May 17, 2019 at 9:52 AM Chris Gregan <email address hidden>
wrote:

> This is interesting.
>
> `echo mem > /sys/power/state`
> This command was instant S3. The screen went black and the power light
> immediately began to blink.
>
> However...for lid switch the power light takes around 10 seconds to begin
> to pulse, but the state immediately switches.
>
> Fri 17 May 2019 09:48:22 AM CEST - state: open
> Fri 17 May 2019 09:48:23 AM CEST - state: open
> Fri 17 May 2019 09:48:24 AM CEST - state: open
> Fri 17 May 2019 09:48:25 AM CEST - state: closed
> Fri 17 May 2019 09:48:26 AM CEST - state: closed
> Fri 17 May 2019 09:48:27 AM CEST - state: closed
>
> It seems although detection if immediate, it takes 10 seconds to process?
>
> On Thu, May 16, 2019 at 6:05 PM Andrea Righi <email address hidden>
> wrote:
>
>> Hi Chris, just to make sure I understand (from a kernel perspective),
>> can you confirm that `echo mem > /sys/power/state` is also fast at
>> reaching the suspend state?
>>
>> In that case it would be interesting to check if there's a delay at
>> detecting the state of the lid switch. For this, could you run the
>> following command in a bash session:
>>
>> $ while :; do echo `date` - `cat ...

[Andrea Righi (arighi)]

Alright, the fact that `echo mem > /sys/power/state` is fast means that the delay issue is not in the "suspend" path and we also know that it's not even in the detection path (/proc/acpi/button/lid/LID0/state). So the delay must be somewhere between the detection of the event and the delivery of the proper suspend action, that should be driven by systemd, more exactly systemd-logind.

At this point I think it would interesting to take a look at journalctl, more exactly the timestamps and messages around a line like "systemd-logind[...]: Lid closed.". This should give us an idea how fast systemd detected the event and how fast it processed it.

[Terry Rudd (terrykrudd)]

Chris, any chance we can get the data that Andrea is asking for above?

[Chris Gregan (cgregan)]

May 25 08:50:46 Thermia microk8s.daemon-apiserver[7167]: I0525 08:50:46.182335 7167 wrap.go:47] PUT /api/v1/namespaces/kube-system/endpoints/kube-controller-manager?timeout=10s: (3.332254ms) 200 [kube-controller-manager/v1.14.1 (linux/amd64) kubernetes/b739410/leader-election 127.0.0.1:56726]
May 25 08:50:46 Thermia microk8s.daemon-apiserver[7167]: I0525 08:50:46.634891 7167 wrap.go:47] GET /api/v1/nodes?resourceVersion=5708807&timeoutSeconds=450&watch=true: (7m30.001685916s) 200 [heapster/v0.0.0 (linux/amd64) kubernetes/$Format 192.168.86.33:48032]
May 25 08:50:46 Thermia microk8s.daemon-apiserver[7167]: I0525 08:50:46.637456 7167 get.go:251] Starting watch for /api/v1/nodes, rv=5709318 labels= fields= timeout=5m16s
May 25 08:50:47 Thermia microk8s.daemon-apiserver[7167]: I0525 08:50:47.005793 7167 wrap.go:47] GET /api/v1/namespaces/kube-system/endpoints/kube-scheduler?timeout=10s: (2.286855ms) 200 [kube-scheduler/v1.14.1 (linux/amd64) kubernetes/b739410/leader-election 127.0.0.1:49932]
May 25 08:50:47 Thermia microk8s.daemon-apiserver[7167]: I0525 08:50:47.010412 7167 wrap.go:47] PUT /api/v1/namespaces/kube-system/endpoints/kube-scheduler?timeout=10s: (3.348305ms) 200 [kube-scheduler/v1.14.1 (linux/amd64) kubernetes/b739410/leader-election 127.0.0.1:49932]
May 25 08:50:47 Thermia systemd-logind[1166]: Lid closed.
May 25 08:50:47 Thermia systemd-logind[1166]: Suspending...
May 25 08:50:47 Thermia NetworkManager[1197]: <info> [1558788647.9902] manager: sleep: sleep requested (sleeping: no enabled: yes)
May 25 08:50:47 Thermia NetworkManager[1197]: <info> [1558788647.9905] device (p2p-dev-wlp4s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
May 25 08:50:47 Thermia NetworkManager[1197]: <info> [1558788647.9931] manager: NetworkManager state is now ASLEEP
May 25 08:50:48 Thermia systemd[1]: Reached target Sleep.
--
May 25 14:41:02 Thermia kernel: Bluetooth: hci0: API lock is enabled
May 25 14:41:02 Thermia kernel: Bluetooth: hci0: Debug lock is disabled
May 25 14:41:02 Thermia kernel: Bluetooth: hci0: Minimum firmware build 1 week 10 2014
May 25 14:41:02 Thermia kernel: Bluetooth: hci0: Found device firmware: intel/ibt-11-5.sfi
May 25 14:41:02 Thermia kernel: done.
May 25 14:41:01 Thermia systemd-logind[1166]: Lid opened.
May 25 14:41:02 Thermia microk8s.daemon-apiserver[7167]: I0525 14:41:01.990168 7167 wrap.go:47] GET /apis/extensions/v1beta1/daemonsets?resourceVersion=5585151&timeout=5m26s&timeoutSeconds=326&watch=true: (5m26.091210748s) 200 [kube-controller-manager/v1.14.1 (linux/amd64) kubernetes/b739410/shared-informers 127.0.0.1:49858]
May 25 14:41:02 Thermia microk8s.daemon-apiserver[7167]: I0525 14:41:01.993603 7167 wrap.go:47] GET /api/v1/namespaces/kube-system/endpoints/kube-scheduler?timeout=10s: (4.257777ms) 200 [kube-scheduler/v1.14.1 (linux/amd64) kubernetes/b739410/leader-election 127.0.0.1:49932]
May 25 14:41:02 Thermia microk8s.daemon-apiserver[7167]: I0525 14:41:01.993898 7167 wrap.go:47] GET /api/v1/namespaces/kube-system/endpoints/kube-controller-manager?timeout=10s: (4.104768ms) 200 [kube-controller-manager/v1.14.1 (linux/amd64) kubernetes/b739410/leade...

[Chris Gregan (cgregan)]

It does seem to have improved in the last update

[Andrea Righi (arighi)]

Thanks Chris, looking at journalct it seems that from the "Lid closed" event and "Reached target Sleep" there's just 1s. So, the time between these two events is also definitely fast, therefore the bottleneck is not in the part of systemd that processes the "lid closed" event.

At this point I'm wondering if the bottleneck is in the part of systemd that detects the "lid closed" event. For that we should run the same loop in a bash session (while :; do echo `date` - `cat /proc/acpi/button/lid/LID0/state`; sleep 1; done), close the lid and compare the timestamps of the transition between "open" and "closed" (in the bash session) with the timestamp of the "Lid closed" event in journalctl. If they don't match the bottleneck is in systemd not being able to detect the lid closed event fast enough.

Moreover, in the last comment (#10) you mentioned that things have been improved. Do you have some numbers (i.e., how many second it needs to actually go to sleep) or is it just a feeling? Thanks!

[Launchpad Janitor (janitor)]

[Expired for linux (Ubuntu) because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Darko Veberic (darko-veberic-kit)]

similar thing happens with my lenovo thinkpad x1 carbon gen5. the time it takes for suspend is excrutiationgly long. it used to be a couple of seconds, at most, now the wait for the red led on top of "i" in ThinkPad logo seems to be taking for ages to start blinking. the output of the loop (suggested by @arighi above)

while true ; do echo $(date) $(cat /proc/acpi/button/lid/LID/state) ; done

gives the following:

Thu 11 Jun 2020 09:36:44 AM CEST state: open
Thu 11 Jun 2020 09:36:45 AM CEST state: open
Thu 11 Jun 2020 09:36:46 AM CEST state: open <-- close lid
Thu 11 Jun 2020 09:36:47 AM CEST state: open
Thu 11 Jun 2020 09:36:48 AM CEST state: open
Thu 11 Jun 2020 09:36:49 AM CEST state: closed
Thu 11 Jun 2020 09:36:50 AM CEST state: closed
Thu 11 Jun 2020 09:36:51 AM CEST state: closed
Thu 11 Jun 2020 09:36:52 AM CEST state: closed
Thu 11 Jun 2020 09:36:53 AM CEST state: closed
Thu 11 Jun 2020 09:36:54 AM CEST state: closed
Thu 11 Jun 2020 09:36:55 AM CEST state: closed
Thu 11 Jun 2020 09:36:56 AM CEST state: closed
Thu 11 Jun 2020 09:36:57 AM CEST state: closed
Thu 11 Jun 2020 09:36:58 AM CEST state: closed
Thu 11 Jun 2020 09:36:59 AM CEST state: closed
Thu 11 Jun 2020 09:37:00 AM CEST state: closed
Thu 11 Jun 2020 09:37:01 AM CEST state: closed
Thu 11 Jun 2020 09:37:02 AM CEST state: closed
Thu 11 Jun 2020 09:37:03 AM CEST state: closed
Thu 11 Jun 2020 09:37:04 AM CEST state: closed
Thu 11 Jun 2020 09:37:05 AM CEST state: closed
Thu 11 Jun 2020 09:37:06 AM CEST state: closed
Thu 11 Jun 2020 09:37:07 AM CEST state: closed
Thu 11 Jun 2020 09:37:08 AM CEST state: closed
Thu 11 Jun 2020 09:37:09 AM CEST state: closed
Thu 11 Jun 2020 09:37:10 AM CEST state: closed
Thu 11 Jun 2020 09:37:11 AM CEST state: closed
Thu 11 Jun 2020 09:37:12 AM CEST state: closed
Thu 11 Jun 2020 09:37:13 AM CEST state: closed
Thu 11 Jun 2020 09:37:14 AM CEST state: closed
Thu 11 Jun 2020 09:37:15 AM CEST state: closed
Thu 11 Jun 2020 09:37:16 AM CEST state: closed
Thu 11 Jun 2020 09:37:17 AM CEST state: closed
Thu 11 Jun 2020 09:37:18 AM CEST state: closed
                      19 <-- power led starts blinking
                      20
                      21
                      22
                      23
                      24
                      25
                      26
                      27
                      28 <-- open lid
                      29
Thu 11 Jun 2020 09:37:30 AM CEST state: open
Thu 11 Jun 2020 09:37:31 AM CEST state: open
Thu 11 Jun 2020 09:37:35 AM CEST state: open <-- ctrl-c while-loop

[Darko Veberic (darko-veberic-kit)]

interesting observation: if i close the lid for, say, 1 sec, and then open it again, after similar time delay as observed in the previous comment, my thinkpad goes into suspend although i am working in my desktop (obviously with the lid open). the lid close seems to trigger the suspend which comes 30 seconds later, no matter what...

[HolgerT (holger6666)]

I can confirm behavior on my Xubuntu 20.04 x86_64 package. Suspend mode is "assigned" to power button. Not until round about 30 seconds after pressing the button, the PC goes into suspend mode.

[Darko Veberic (darko-veberic-kit)]

there has been no progress on this issue, it's the same in ubuntu 21.04. the behavior described in #15 is especially annoying since closing the lid by mistake (while eg carrying it around) and opening it immediately does not cancel the suspend, it comes 30s later no matter what one is currently doing.

[Kai-Heng Feng (kaihengfeng)]

Does "echo mem | sudo tee /sys/power/state" suspend the system immediately?

[Nick Rosbrook (enr0n)]

The original report for this is stale. If anyone is experiencing similar issues on different hardware with newer releases, please open a separate bug report.