High CPU due to excessive device changed signals from upower

Bug #1337200 reported by Alan Pope 🍺🐧🐱 πŸ¦„
34
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Canonical System Image
Fix Released
High
Canonical Devices Products
ubuntu-system-settings (Ubuntu)
Invalid
High
Unassigned
ubuntu-system-settings (Ubuntu RTM)
Confirmed
High
Ken VanDine
upower (Ubuntu RTM)
Fix Released
High
Unassigned

Bug Description

I've noticed this a few times but reproduced it today explicitly to file a bug.

Open system settings.
Perhaps open other apps (not necessarily required) on my mako I ran BBC News webapp.
Put phone on charger, go to bed
8 hours later, wake phone up, switch to system settings

UI in u-s-s is unresponsive, other apps are fine.
Tapping icons in the main screen of u-s-s yields no result for a long time, sometimes swiping away from the app and coming back is required to make it respond.
It feels like the app has locked up.

Indeed, looking at top, I see it's eating a core while doing "nothing".

top - 08:47:30 up 9:55, 2 users, load average: 1.30, 1.41, 1.61
Tasks: 249 total, 2 running, 247 sleeping, 0 stopped, 0 zombie
%Cpu(s): 51.5 us, 2.9 sy, 0.0 ni, 45.4 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 1878632 total, 1818100 used, 60532 free, 121936 buffers
KiB Swap: 524284 total, 0 used, 524284 free. 810184 cached Mem

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 4220 phablet 20 0 350900 130908 29404 R 99.6 7.0 3:40.49 system-settings
11266 phablet 20 0 5956 1224 772 R 2.6 0.1 0:00.54 top
  754 message+ 20 0 212124 207364 748 S 1.6 11.0 8:59.75 dbus-daemon
 1124 root 20 0 186560 16976 12608 S 0.6 0.9 0:34.08 unity-system-co
 1162 9999 20 0 10904 828 488 S 0.6 0.0 0:02.55 sensors.qcom
 1164 root 0 -20 7572 548 396 S 0.6 0.0 4:48.69 mpdecision
 4413 phablet 20 0 582656 72904 52940 S 0.6 3.9 0:08.16 webapp-containe
 1171 root 20 0 8244 1624 1224 S 0.3 0.1 0:08.97 Binder_2
 1675 root 20 0 51532 6140 4736 S 0.3 0.3 0:54.45 NetworkManager
 2521 phablet 20 0 44908 2424 2016 S 0.3 0.1 0:02.08 indicator-messa
 2565 phablet 20 0 566332 127124 56824 S 0.3 6.8 3:55.87 unity8
 2602 phablet 20 0 104328 8900 7296 S 0.3 0.5 0:29.69 pay-service

Not much in the log.

2014-07-02 17:00:50,867 - WARNING - file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/ListItems/SingleControl.qml:59:14: Unable to assign [undefined] to bool
creating surface at (0, 58) with size (768, 1222) with title 'Window 1'2014-07-02 17:00:51,118 - CRITICAL - ../../../../lib/SignOn/connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/32011/signond/socket: No such file or directory") 1
2014-07-03 00:12:28,936 - CRITICAL - ../../../../lib/SignOn/connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/32011/signond/socket: No such file or directory") 1
2014-07-03 00:12:29,902 - WARNING - file:///usr/lib/arm-linux-gnueabihf/qt5/qml/Ubuntu/Components/ListItems/SingleControl.qml:59:14: Unable to assign [undefined] to bool
creating surface at (0, 58) with size (768, 1222) with title 'Window 1'2014-07-03 00:12:30,176 - CRITICAL - ../../../../lib/SignOn/connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/32011/signond/socket: No such file or directory") 1

Related branches

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

Had this again this morning. Left phone overnight and it's still got system settings running but is wedged at 100% cpu

top - 11:26:33 up 1 day, 19:36, 2 users, load average: 1.24, 1.08, 1.02
Tasks: 255 total, 2 running, 245 sleeping, 8 stopped, 0 zombie
%Cpu(s): 52.5 us, 3.4 sy, 0.0 ni, 43.6 id, 0.5 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 1878632 total, 1831252 used, 47380 free, 61916 buffers
KiB Swap: 524284 total, 3124 used, 521160 free. 297436 cached Mem

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 5319 phablet 20 0 334864 104620 28532 R 99.2 5.6 2:23.93 system-settings

Changed in ubuntu-system-settings (Ubuntu):
importance: Undecided → Low
importance: Low → High
Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

Be nice if you could attach with gdb and see what its doing

Changed in ubuntu-system-settings (Ubuntu):
assignee: nobody → Jonas G. Drange (jonas-drange)
status: New → Triaged
Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

This is what I see when I strace the running process

http://paste.ubuntu.com/7807924/

This was while it was sat in the updates screen, doing nothing, but eating 100% cpu.

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

Tried getting a gdb backtrace via https://wiki.ubuntu.com/Backtrace#Already_running_programs but it didn't work as the app didn't hang and when I did ctrl+c it killed gdb.

tags: added: lt-category-visible lt-prio-low
Revision history for this message
Sebastien Bacher (seb128) wrote :

thanks popey, you did the gdb one wrong it seems. you need to type "continue" to resume the code before doing ctrl-C

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

As I recall I had no opportunity to type anything after continue as it was running and had no prompt.

I am afk now until the weekend. Can someone else reproduce this with gdb debugging? It's really easy to reproduce.

Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

@popey are you always on the system update page?
From the paste it looks like something lower level is in a tight loop polling a socket or something

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

I think so, yes. Will try again tonight with two devices. One on updates, one not.

I usually check for updates before bed, then lock screen and stick it on charge.

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

I tried today while I was out.
Left #133 mako on updates screen.
Left #146 mako on settings main screen.

Locked both and left for 7 hours.

When I returned 133 was usable. 146 was unusable.

Will try again overnight once 146 phone is updated to latest.

Revision history for this message
Florian W. (florian-will) wrote :

Not sure if that's related or maybe expected behaviour, the strace contains "\35\0\0\0org.freedesktop.UPower.Devic"… strings which seem to indicate that something in system settings repeatedly calls the upower dbus API. If these dbus calls are not expected (for example to refresh battery info regularly), maybe increasing the strace -s param could give some more insight into what the CPU is doing. It seems like only the battery plugin of system settings uses upower calls through a glib upower library.

Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

Seb mind taking a quick look?
Battery and brightness plugins are the only code connecting to powerd
The unit should really be suspended so not sure why settings would consume cpu on wake, unless the unit does not suspend but the app is backgrounded by app lifecyle. Still dont see anything looking at continuous updates

And no one else has reported so popey is up to something

Changed in ubuntu-system-settings (Ubuntu):
assignee: Jonas G. Drange (jonas-drange) → Sebastien Bacher (seb128)
Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

I may well be doing something dumb.

As a test I have just rebooted two phones, one devel, one proposed. I have started system settings, gone to updates screen. Neither show any updates. I tapped the power button and have sat them down to charge, so they'll be on overnight. I'll check them again in ~8 hours.

Revision history for this message
Alan Pope 🍺🐧🐱 πŸ¦„ (popey) wrote :

Good news. The phone running devel was hanging, but the one running proposed (#189) was fine. So it's possible this is now no longer an issue.

Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

Reproduced on a krilin running 185
I opened the battery and brightness panels before turning the the main settings panel, although Popey says he has not been doing that. strace attached showing dbus calls with powerd.

seeing this on dbus continuously

signal sender=:1.31 -> dest=(null destination) serial=108899 path=/org/freedesktop/UPower/devices/line_power_wireless; interface=org.freedesktop.UPower.Device; member=Changed
signal sender=:1.31 -> dest=(null destination) serial=108900 path=/org/freedesktop/UPower/devices/battery_battery; interface=org.freedesktop.UPower.Device; member=Changed
signal sender=:1.31 -> dest=(null destination) serial=108903 path=/org/freedesktop/UPower/devices/line_power_ac; interface=org.freedesktop.UPower.Device; member=Changed
signal sender=:1.31 -> dest=(null destination) serial=108904 path=/org/freedesktop/UPower/devices/battery_battery; interface=org.freedesktop.UPower.Device; member=Changed
signal sender=:1.31 -> dest=(null destination) serial=108908 path=/org/freedesktop/UPower/devices/line_power_usb; interface=org.freedesktop.UPower.Device; member=Changed

Revision history for this message
Ken VanDine (ken-vandine) wrote :

I did some further debugging and found that disabling the battery plugin in ubuntu-system-settings does keep system-settings from causing the load. However, when the device wakes after sleeping on 100% battery while charging, I see dbus-daemon spewing device changed signals from upower. Without settings running, I saw 57 device changed signals from upower in 5 seconds.

Revision history for this message
Sebastien Bacher (seb128) wrote :

Unassigning, I'm not working on that one. Looking a bit to it I can confirm what Ken wrote, in some cases there is a low level event spam, seems like rather a kernel/udev/... issue, it just happens that u-s-s reacts to those events and the callback uses some cpu, so calling it in loop leads to the cpu usage

Changed in ubuntu-system-settings (Ubuntu):
assignee: Sebastien Bacher (seb128) → nobody
Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

@martin would you mind looking at this and giving feedback

summary: - U-S-S sluggish after some hours, high CPU
+ High CPU due to excessive device changed signals from upower
Changed in ubuntu-system-settings (Ubuntu):
assignee: nobody → Martin Pitt (pitti)
Revision history for this message
Martin Pitt (pitti) wrote :

On a device/in a situation which reproduces this, can you please run

  udevadm monitor -e

I expect that there is a high frequency of uevents related to the battery from the kernel's battery driver. These get relayed through udev and upower to U-S-S. In particular we need to see if there are any properties which actually change, i. e. whether the battery goes crazy or the bat driver has a bug to fire a ginormous amount of uevents (which keeps significant parts of the system busy). It's of course possible that there are no uevents but upower manages to get stuck in some kind of loop. But that's less probable as it never happened on other systems.

The recent "dmesg" output would also be interesting, in case that the driver reports some error there.

Thanks!

Changed in ubuntu-system-settings (Ubuntu):
status: Triaged → Incomplete
Revision history for this message
Martin Pitt (pitti) wrote :

(I'm still subscribed, just unassigning while this is incomplete)

Changed in ubuntu-system-settings (Ubuntu):
assignee: Martin Pitt (pitti) → nobody
Revision history for this message
Selene ToyKeeper (toykeeper) wrote :

I think I've been seeing this bug too, but haven't looked into it in detail. Basically, if I leave the phone idle overnight, it's extremely slow when I try to use it in the morning... and dbus-daemon is constantly pegging the CPU. 'top' generally shows that dbus-daemon has a few hours worth of CPU cycles accumulated; this morning it listed 181 minutes of active time even though it had only been booted for ~10 hours.

Revision history for this message
Ken VanDine (ken-vandine) wrote :

This is the output from "udevadm monitor -e" over the course of a little over a minute

Revision history for this message
Ken VanDine (ken-vandine) wrote :

dmesg from the same time as the udevadm output attached previously

Changed in ubuntu-system-settings (Ubuntu):
assignee: nobody → Martin Pitt (pitti)
status: Incomplete → Triaged
tags: added: ota-1 rtm14
Revision history for this message
Martin Pitt (pitti) wrote :

That shows that the kernel sends us an update for all 4 power supplies every 10 seconds, which doesn't sound "excessive". So I'm glad that we at least ruled out this end.

So going one step up the stack, could you run "upower --monitor-detail" when this happens? In theory this should exactly mirror the kernel uevents for the power_supply updates; but earlier comments seem to suggest that it sends out a lot more.

 β†’ If it shows tons of updates, we have our culprit

 β†’ If it shows 4 updates every 10 s, it's fine. In that case, please run dbus-monitor --system | ts -s '%.S' to see what's going on on the bus, i. e. whether upower actually sends so many signals (or something else is). (dbus-monitor doesn't do time-stamping by itself, so piping it through ts is better for logging).

Revision history for this message
Martin Pitt (pitti) wrote :

(It's not triaged for me -- I can't reproduce this at all, and I don't have a Krillin)

Changed in ubuntu-system-settings (Ubuntu):
assignee: Martin Pitt (pitti) → nobody
status: Triaged → Incomplete
Revision history for this message
Martin Pitt (pitti) wrote :

Update: turns out that the udevadm log from above is irrelevant -- it was taken when system-settings was *not* spinning. So this is back to being the most likely cause. Can you please do a monitoring event while system-settings *is* spinning?

Revision history for this message
Pat McGowan (pat-mcgowan) wrote :
Revision history for this message
Martin Pitt (pitti) wrote :

OK, Pat's upower log also by and large just reflects the kernel events. We discussed that on IRC, and we think that there's two different issues here:

 * The main problem is that system-settings subscribes to D-BUS signals (from upower), and then goes to sleep. When it wakes back up, it receives all the queued signals from dbus-daemon, as the semantics of D-BUS is to not lose signals. These can't be "filtered out" on the D-BUS side. What system-settings could do is to unsubscribe from D-BUS before suspending, and re-subscribing after resuming.

 * This problem is mitigated by upower 0.99, as that suppresses change events if the values didn't actually change. As the udevadm monitor log shows, the Android kernel is really dumb here -- it sends out change signals for all devices every 10 s even if nothing changed (like the AC). Due to using a PropertyChanged signal (which does value comparison and is only sent on actual changes) instead of the raw "DeviceChanged" signals (which are an one-to-one reflection of the original uevents) we filter out about 3/4 of the original events. I. e. upower itself still wakes up just as often as 0.9 (as that happens through the kernel), but affects userspace much less.

Martin Pitt (pitti)
Changed in ubuntu-system-settings (Ubuntu):
status: Incomplete → In Progress
Revision history for this message
Ken VanDine (ken-vandine) wrote :

My branch that disconnects from the signals on suspend and connect again on resume doesn't really fix this. I did make the system-settings code more efficient, but actually it doesn't connect to device-changed signals. Only device-added and device-removed. There are some places where we call some synchronous functions on upower, and when dbus-daemon is busy caused blocking issues.

I did some more testing tonight and found that even without system-settings running when the device sleeps, dbus-daemon uses quite a bit of CPU on resume. I saw between 24% and 87% without system-settings even running and would last for anywhere from 10s to over a minute. Attempting to start system-settings while dbus-daemon was busy would cause dbus-daemon load go up quite a bit and last longer. When dbus-daemon was the top culprit for the high load, upowerd was a distant #2, at just over 1%. However, once dbus-daemon settled down, upowerd would drop back to 0%.

My new theory is dbus-daemon is spinning out of control because of upower, probably because indicator-power is still subscribed to it. When the device wakes, upowerd must be flooding dbus itself. When dbus-daemon is busy, it blocks or is just slow to respond.

Another observation, I think this situation is more noticeable when the device is plugged into a computer, not just a wall charger. I didn't check the load on resume while plugged into a wall charger, but system-settings UI was much more responsive on waking up.

Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

I checked wall charger yesterday and it seems the behavior is the same. IMO this is a separate bug in that the device should be able to suspend when on the wall charger as this is not an active usb data connection.

Revision history for this message
Ken VanDine (ken-vandine) wrote :
Revision history for this message
Ken VanDine (ken-vandine) wrote :
Revision history for this message
Ken VanDine (ken-vandine) wrote :
Revision history for this message
Ken VanDine (ken-vandine) wrote :

I attached udevadm.log, upower-monitor.log and dbus-monitor.log which was generated over a period with a number of suspend and resumes. This was all with system-settings' battery plugin removed, so nothing from settings listening for upower. I also never had system-settings completely hang, but several times it was very stuttering on resume and once it hung for about 2 seconds. I also watched top during this time and saw dbus-daemon's load hit 73% at one point while the screen was off, and it often jumped over 20%.

Revision history for this message
Ken VanDine (ken-vandine) wrote :

After attempting to work around this in ubuntu-system-settings, I don't think it's possible. The problem seems to be upower pushing dbus-daemon's load high enough that slows down or blocks dbus calls.

affects: upower (Ubuntu) → upower (Ubuntu RTM)
Revision history for this message
Martin Pitt (pitti) wrote :

> My new theory is dbus-daemon is spinning out of control because of upower, probably because indicator-power is still subscribed to it.

That, and powerd as well for the record.

Thanks for the logs!

 * udevadm.log doesn't look surprising: We get one event for each of the four power_supply devices every 10 s. While sending events for all those (AC, full battery, etc.) is a bit stupid, this is a frequency which we should be able to keep up with easily. There are no bursts of events at any time.

 * upower monitor is surprising: while its "changed" events for ac, line_power_usb, and line_power_wireless pretty much exactly reflect the uevents, the ones for battery_battery happen much more frequently, about once per second. I don't know why that happens (this would now require starting upowerd in the foreground and watching its debug output). This is the place where upower 0.99's "have properties actually changed" behaviour helps immensely, even though it doesn't explain alone why upower itself wakes up so often. If the "wakes up once per second" still happens with 0.99, we need the debug info. But still, there are no bursts here which seem to correlate to an app waking up.

 * dbus-monitor.log shows roughly the same number of events, but it doesn't contain timestamp information, so it's not possible to see bursts there. To do that, please run dbus-monitor --system | ts -s '%.S' (see comment 23).

At this point, is there a major reason to not update upowerd to 0.99 and pull in the corresponding powerd, system-settings, and indicator-power changes?

Revision history for this message
Ken VanDine (ken-vandine) wrote :

I've built powerd, upowerd, indicator-power and ubuntu-system-settings in rtm silo 16 for testing.

Revision history for this message
Ken VanDine (ken-vandine) wrote :

I've confirmed the transition to upower 0.99 fixes this issue, really nice improvement all around.

Changed in upower (Ubuntu RTM):
importance: Undecided → High
status: New → Confirmed
Changed in ubuntu-system-settings (Ubuntu RTM):
status: New → Invalid
Changed in ubuntu-system-settings (Ubuntu):
status: In Progress → Invalid
Olli Ries (ories)
Changed in canonical-devices-system-image:
assignee: nobody → Canonical Devices Products (canonical-devices-products-team)
importance: Undecided → High
milestone: none → r1
status: New → Confirmed
Revision history for this message
Martin Pitt (pitti) wrote :

Un-duplicating, as 1375152 is private. I rather made 1375152 a duplicate of this one.

Revision history for this message
Ricardo Salveti (rsalveti) wrote :

<rsalveti> pitti: because the problem is the kernel sending way too much uevents related with power
<rsalveti> which makes upower to be quite a bit verbose, and dbus as well (on krillin only)
<pitti> rsalveti: that's then not really a duplicate
<pitti> rsalveti: #1337200 is about queueing up d-bus signals while a process is sleeping, and then flushing them on wakeup
<pitti> rsalveti: if on that other platform the kernel is sending too many events, that's a separate cause

Changed in ubuntu-system-settings (Ubuntu RTM):
status: Invalid → In Progress
assignee: nobody → Ken VanDine (ken-vandine)
importance: Undecided → High
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package ubuntu-system-settings - 0.3+15.04.20141210~rtm-0ubuntu1

---------------
ubuntu-system-settings (0.3+15.04.20141210~rtm-0ubuntu1) 14.09; urgency=low

  [ Ken VanDine ]
  * Support UPower 0.99 (LP: #1337200, #1390629)

  [ Ubuntu daily release ]
  * New rebuild forced
 -- Ubuntu daily release <email address hidden> Wed, 10 Dec 2014 23:53:31 +0000

Changed in ubuntu-system-settings (Ubuntu RTM):
status: In Progress → Fix Released
Changed in upower (Ubuntu RTM):
status: Confirmed → Fix Released
Changed in canonical-devices-system-image:
status: Confirmed → Fix Released
Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

I am re-opening this because the same symptom is still ocurring, open settings app after the phone has charged and both settings and dbus-daemon eat the cpu

Changed in ubuntu-system-settings (Ubuntu RTM):
status: Fix Released → Confirmed
Changed in canonical-devices-system-image:
status: Fix Released → Confirmed
milestone: ww51-2014 → ww13-ota
Revision history for this message
Pat McGowan (pat-mcgowan) wrote :

The latest krillin kernel suppresses unnecessary messages so this is largely fixed.

Changed in canonical-devices-system-image:
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.