High CPU due to excessive device changed signals from upower

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

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

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.

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.

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

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.

@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

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.

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.

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.

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

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.

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.

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

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.

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

@martin would you mind looking at this and giving feedback

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!

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

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.

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

dmesg from the same time as the udevadm output attached previously

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).

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

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?

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.

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.

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.

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%.

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.

> 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?

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

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

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

<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

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

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

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