Push-client frequently blocking phone suspend
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Canonical System Image |
Fix Released
|
Critical
|
John Lenton | ||
Ubuntu Push Notifications |
Fix Released
|
Undecided
|
Samuele Pedroni | ||
ubuntu-push (Ubuntu) |
Fix Released
|
Undecided
|
Unassigned | ||
ubuntu-push (Ubuntu RTM) |
Fix Released
|
Undecided
|
Unassigned |
Bug Description
current build number: 256
device name: krillin
channel: ubuntu-
last update: 2015-03-22 22:01:56
version version: 256
version ubuntu: 20150312
version device: 20150310-3201c0a
version custom: 20150216-561-29-186
While debugging the suspend process with my krillin, I noticed that sometimes ubuntu-push-client holds a powerd sysstate for too long (minutes), blocking the suspend process entirely.
Follows the log I got from powerd:
Mar 22 23:09:21 ubuntu-phablet powerd[964]: handle_
Mar 22 23:09:21 ubuntu-phablet powerd[964]: name_watch_add: looking for :1.92
Mar 22 23:09:21 ubuntu-phablet powerd[964]: watching :1.92 to see when it disappears on dbus
Mar 22 23:09:21 ubuntu-phablet powerd[964]: libsuspend: acquire_wake_lock: powerd_
Mar 22 23:09:21 ubuntu-phablet powerd[964]: handle_
Mar 22 23:09:21 ubuntu-phablet powerd[964]: Enqueue state change to ACTIVE
Mar 22 23:09:21 ubuntu-phablet powerd[964]: exiting suspend
Mar 22 23:09:21 ubuntu-phablet powerd[964]: libsuspend: calling exit_suspend
Mar 22 23:09:21 ubuntu-phablet kernel: [ 1397.544062]PM: suspend exit 2015-03-23 02:09:21.573597769 UTC
Mar 22 23:09:21 ubuntu-phablet kernel: [ 1397.544113]active wakeup source: MT662x
Mar 22 23:09:21 ubuntu-phablet kernel: [ 1397.544129]active wakeup source: alarm
Mar 22 23:09:21 ubuntu-phablet kernel: [ 1397.554088]
Mar 22 23:09:21 ubuntu-phablet powerd[964]: calling wait_for_next_alarm
Mar 22 23:09:21 ubuntu-phablet kernel: [ 1397.563938]
Mar 22 23:09:22 ubuntu-phablet powerd[964]: libsuspend: exit_suspend succeeded
Mar 22 23:09:22 ubuntu-phablet powerd[964]: Emitting signal for transition to state ACTIVE (1)
Mar 22 23:09:22 ubuntu-phablet powerd[964]: Transition to ACTIVE complete
Mar 22 23:09:22 ubuntu-phablet powerd[964]: libsuspend: release_wake_lock: powerd_
Mar 22 23:09:22 ubuntu-phablet powerd[964]: handle_
Mar 22 23:09:22 ubuntu-phablet powerd[964]: void {anonymous}
Mar 22 23:09:22 ubuntu-phablet powerd[964]: setting hardware wakeup time to 2015-03-23 11:00:00 for indicator-datetime
Mar 22 23:12:10 ubuntu-phablet powerd[964]: handle_
Mar 22 23:12:10 ubuntu-phablet powerd[964]: void {anonymous}
Mar 22 23:12:10 ubuntu-phablet powerd[964]: setting hardware wakeup time to 2015-03-22 23:17:10 for ubuntu push client
Mar 22 23:12:10 ubuntu-phablet powerd[964]: handle_
Mar 22 23:12:10 ubuntu-phablet powerd[964]: clear_sys_request: ubuntu push client - :1.92
Mar 22 23:12:10 ubuntu-phablet powerd[964]: name_watch_remove: looking for :1.92
Mar 22 23:12:10 ubuntu-phablet powerd[964]: name_watch: ref_count for :1.92 is now 0
Mar 22 23:12:10 ubuntu-phablet powerd[964]: no longer watching :1.92, there are no more requests
Mar 22 23:12:10 ubuntu-phablet powerd[964]: libsuspend: acquire_wake_lock: powerd_
Mar 22 23:12:10 ubuntu-phablet powerd[964]: Enqueue state change to SUSPEND
Mar 22 23:12:10 ubuntu-phablet powerd[964]: libsuspend: prepare_suspend.
Mar 22 23:12:10 ubuntu-phablet powerd[964]: Emitting signal for transition to state SUSPEND (0)
Mar 22 23:12:10 ubuntu-phablet powerd[964]: entering suspend
Mar 22 23:12:10 ubuntu-phablet powerd[964]: libsuspend: calling enter_suspend
Mar 22 23:12:10 ubuntu-phablet powerd[964]: libsuspend: enter_suspend succeeded
Mar 22 23:12:10 ubuntu-phablet powerd[964]: Transition to SUSPEND complete
Mar 22 23:12:10 ubuntu-phablet powerd[964]: libsuspend: release_wake_lock: powerd_
It took ubuntu-push-client 169 seconds to release the sysstate from powerd, and that probably only happened after powerd triggered the alarm that was scheduled by ubuntu-push-client.
Related branches
- John Lenton (community): Approve
-
Diff: 46 lines (+10/-5)2 files modifiedclient/session/session.go (+9/-4)
client/session/session_test.go (+1/-1)
- Samuele Pedroni: Approve
-
Diff: 85 lines (+20/-3)4 files modifiedclient/client.go (+2/-0)
client/client_test.go (+1/-0)
debian/config.json (+2/-1)
poller/poller.go (+15/-2)
Changed in canonical-devices-system-image: | |
status: | New → Confirmed |
importance: | Undecided → Critical |
milestone: | none → ww13-ota |
Changed in canonical-devices-system-image: | |
assignee: | nobody → John Lenton (chipaca) |
Changed in ubuntu-push: | |
assignee: | nobody → Samuele Pedroni (pedronis) |
Changed in canonical-devices-system-image: | |
status: | Confirmed → In Progress |
Changed in canonical-devices-system-image: | |
status: | In Progress → Fix Released |
Changed in ubuntu-push: | |
status: | In Progress → Fix Committed |
Changed in ubuntu-push: | |
status: | Fix Committed → Fix Released |
Changed in ubuntu-push (Ubuntu): | |
status: | Confirmed → Fix Released |
From IRC: ::reset_ alarm_clock( ) found 3 remaining wakeup requests
<rsalveti> Mar 22 23:06:34 ubuntu-phablet powerd[964]: void {anonymous}
<rsalveti> Mar 22 23:06:34 ubuntu-phablet powerd[964]: setting hardware wakeup time to 2015-03-22 23:09:20 for ubuntu push client
<Chipaca> rsalveti: i'm afraid i don't understand what i'm supposed to be gleaning from the kernel logs :(
<Chipaca> rsalveti: i can tell you what the push client should be doing
<rsalveti> so ubuntu push client requested a hardware wakeup time to 2015-03-22 23:09:20, phone suspended fine, woke up at the exact time, then push client got a SysState lock and only released at 23:12:10
<Chipaca> rsalveti: and i _think_ it's doing what it should be doing :)
<Chipaca> rsalveti: push requests a wake up for 5m in the future
<Chipaca> rsalveti: when it wakes up, it asks for a wake lock
* loicm has quit (Ping timeout)
<Chipaca> rsalveti: it then waits up to 1 minute for the network to come up
<Chipaca> rsalveti: when the network comes up, it waits up to 3 minutes for polld to poll stuff
<Chipaca> rsalveti: once polld signals it's done, it asks for a wakeup in 5 minutes, and releases the wake lock
<rsalveti> right, then it is indeed the expected behavior
<Chipaca> phew :)
<rsalveti> but it's annoying that it blocks the suspend for so long
<Chipaca> rsalveti: all those timeouts are configurable
<rsalveti> can't we optimize this?
<Chipaca> rsalveti: you mean, changing those timeouts?
<Chipaca> rsalveti: sure
<rsalveti> Chipaca: when you wait for the network, do you wait the full 60 seconds or do you wait until you get the connection, if less than 60 seconds?
<Chipaca> rsalveti: the latter
<pedronis> the big chunk is polld I suppose
<Chipaca> pedronis: or maybe the network coming up
<rsalveti> network should return quite fast actually
<Chipaca> or all of the above
<rsalveti> 1 minute is a lot of time
<Chipaca> rsalveti: yes
<rsalveti> Chipaca: maybe polld is taking more time now because of the amount of users we have?
<Chipaca> rsalveti: so it's entirely possible there are bugs or unexpected interactions going on; debug logs for push, and the account-polld log, might shed more light.
<Chipaca> rsalveti: polld does not go via our servers
<Chipaca> it's straight to twitter/google
<rsalveti> enabled debug in push-client, how to enable debug for polld?
<Chipaca> rsalveti: do you have a google or twitter account enabled on the device you're checking?
<rsalveti> Chipaca: I got telegram, gmail and twitter
<rsalveti> and I joined the warthogs group in telegram
<Chipaca> rsalveti: gmail and twitter are polld; telegram uses push