Slow wake up time on physical power button pressed

@mterry, do we have a bug left over from all the power dialog ones that deal with this?

Szymon, yeah, we've seen that, could not pinpoint the offender yet, other than knowing that it's a load-related thing.

It looks like this problem is something escalating to unacceptable stage, here short video:

https://bugs.launchpad.net/ubuntu/+source/unity8/+bug/1421455

@Szymon, that video link is incorrect?

@Saviq, no, I didn't leave a bug open for it, so this one is fine. It's not clear whether this is unity8's fault or USC's or powerd's. We'd need to add debugging to each one, then reproduce. But it's also not clear how to reliably reproduce.

Sorry I pasted wrong link, here is correct one: http://youtu.be/DypDSYhJV6g

@Szymon, thanks for the video! Looks painful. So both the greeter coming on slowly and being slow to log in might both be PAM problems then...

I'll assign back to myself, but again, I don't really know how to reproduce this. :(

It's unfortunately still unclear what's happening here. The working assumption is that dbus traffic is high in those instances, causing messages to get queued and block some parts of the system. Unfortunately steps to reproduce still unknown :/

This is close in behavior to bug 1429887.

I was monitoring my syslog while pressing the button.

Apr 29 14:37:35 ubuntu-phablet powerd[949]: handle_requestSysState from :1.13 - ACTIVE (1)
Apr 29 14:37:35 ubuntu-phablet powerd[949]: name_watch_add: looking for :1.13
Apr 29 14:37:35 ubuntu-phablet powerd[949]: watching :1.13 to see when it disappears on dbus
Apr 29 14:37:35 ubuntu-phablet powerd[949]: libsuspend: acquire_wake_lock: powerd_power_request
Apr 29 14:37:35 ubuntu-phablet powerd[949]: handle_requestSysState - SUCCESS
Apr 29 14:37:35 ubuntu-phablet powerd[949]: Enqueue state change to ACTIVE
Apr 29 14:37:35 ubuntu-phablet powerd[949]: exiting suspend
Apr 29 14:37:35 ubuntu-phablet powerd[949]: libsuspend: exit_suspend.
Apr 29 14:37:35 ubuntu-phablet kernel: [21759.723201][Ker_PM][request_suspend_state]wakeup (3->0) at 21760134073325 (2015-04-29 12:37:35.882532317 UTC)

< exactly here there is a short delay>

Apr 29 14:37:36 ubuntu-phablet powerd[949]: Emitting signal for transition to state ACTIVE (1)
Apr 29 14:37:36 ubuntu-phablet powerd[949]: Transition to ACTIVE complete
Apr 29 14:37:36 ubuntu-phablet powerd[949]: libsuspend: release_wake_lock: powerd_power_request
Apr 29 14:37:36 ubuntu-phablet kernel: [21760.273491]mtk-tpd: TPD wake up
Apr 29 14:37:36 ubuntu-phablet powerd[949]: light_dev: setting brightness to 120
Apr 29 14:37:36 ubuntu-phablet kernel: [21760.310044]mtk-tpd: TPD wake up done
Apr 29 14:37:36 ubuntu-phablet kernel: [21760.310066]<MAGNETIC> mag_context_obj ok------->hwm_obj->early_suspend=0
Apr 29 14:37:36 ubuntu-phablet powerd[949]: we get signal from :1.13: DisplayPowerStateChange
Apr 29 14:37:36 ubuntu-phablet powerd[949]: Received DisplayPowerStateChange: state=1 flags=2

Since some of those messages are from the kernel ringbuffer, I looked at the corresponding dmesg output:

[21606.412808] [Ker_PM][request_suspend_state]wakeup (3->0) at 21606823677239 (2015-04-29 12:35:02.572136231 UTC)
[21606.953480] mtk-tpd: TPD wake up
[21606.980027] mtk-tpd: TPD wake up done

So there seems to be at least half a second of delay between the kernel registering the button press and the display actually being requested to power on. Since display power-on is not instant, the total time from button press to visible display content is close to a second on my device in best case, sometimes up to three seconds and in rare cases the display does not turn on at all.

So looking at the powerd code, the only thing that does anything *real* between "exiting suspend" and "Emitting signal for transition to state ACTIVE" is a call to libsuspend_exit_suspend().

Which -- depending on the backend -- either makes one syscall and returns, or makes one syscall and waits for the fb state to be awake. Since the latter is the default backend and we're seeing delays, I'm guessing that's the code path we're hitting.

Why do we need to block on fb state there? (honest question, I don't understand the libsuspend code very well)

Just a quick follow-up: we are using the backend that blocks on fb state -- all a device needs is /sys/power/{state,wake_lock,wait_for_fb_sleep,wait_for_fb_wake}

So I'm feeling confident that's a part of the puzzle here.

Looking at the strace output one can see that powerd gets the power button press notification, processes it, and then nothing happens for half a second:

[pid 949] 1430318963.039809 send(3, "<31>Apr 29 16:49:23 powerd[949]: exiting suspend", 48, MSG_NOSIGNAL) = 48
[pid 949] 1430318963.040868 gettimeofday({1430318963, 40921}, NULL) = 0
[pid 949] 1430318963.041289 send(3, "<31>Apr 29 16:49:23 powerd[949]: libsuspend: exit_suspend.", 58, MSG_NOSIGNAL) = 58
[pid 949] 1430318963.042623 open("/sys/power/state", O_WRONLY) = 14
[pid 949] 1430318963.043483 write(14</sys/power/state>, "on", 2 <unfinished ...>

<Note: 508 milliseconds delay>

[pid 8256] 1430318963.515663 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 8256] 1430318963.515862 clock_gettime(CLOCK_MONOTONIC, {27280, 493365943}) = 0
[pid 8256] 1430318963.517005 clock_gettime(CLOCK_MONOTONIC, {27280, 493965482}) = 0
[pid 8256] 1430318963.518207 futex(0xaa430c, FUTEX_WAIT, 30, {14, 999399518} <unfinished ...>
[pid 971] 1430318963.587966 <... read resumed> "a", 1) = 1
[pid 971] 1430318963.588263 close(7</sys/power/wait_for_fb_wake>) = 0
[pid 971] 1430318963.589699 open("/sys/power/wait_for_fb_sleep", O_RDONLY) = 7
[pid 971] 1430318963.590953 read(7</sys/power/wait_for_fb_sleep>, <unfinished ...>
[pid 949] 1430318963.592034 <... write resumed> ) = 2

If you look close enough you can see that pid 949 does a blocking write of the string "on" to /sys/power/state, and this syscall comes back half a second later. Half a second. Exactly the missing time we are looking for.

So I pressed the power button to turn off the screen, waited a couple of seconds to allow the system go to sleep, and did the following:

root@ubuntu-phablet:~# time echo "on" > /sys/power/state

real 0m0.545s
user 0m0.000s
sys 0m0.000s

Something in the kernel seems to take roughly half a second to wake up.

I looked at the Documentation/power/states.txt file of the Linux kernel and was am a bit confused: There should be only four valid values one can write to /sys/power/state, namely "mem", "standby", "freeze" and "disk". On the bq phone the file contains "mem disk", so only those two states are available. I found out that "on" seems to be an accepted value on Android kernels only.

So the root of the problem my lie in kernel land at the end.

Yeah it seems likely that some driver is probably being slow in its late_resume handler. There may be something in dmesg which shows how long individual late_resume calls are making, I can't remember (there may also be some debug option which has to be enabled).

Iirc the reason we have to wait for the fb state to change was because you can hit deadlocks with some of the phone kernels if you write state changes to /sys/power/state without waiting. Android also waits for the framebuffer state to change, so that's the only arrangement that's probably tested by the phone makers as well.

So this bug has to be "escalated" to the handset or even the chipset manufacturer, right?

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

The issue became *much* better on my krillin device with OTA-4. Can anybody comment on what was changed?