Tuesday, 22 October 2013

Reducing wake-ups, the 2013 edition

While doing work on UPower, trying to reduce its wake-ups when idle, I realised that a couple of applications on my desktop were waking up far more than should be necessary.

Detecting wake-ups

First, we need to detect wake-ups. This is a fairly well-known, and old, process, using the venerable PowerTop.

# powertop --html=/tmp/foo.html --time=60

You can increase the number of seconds to get a more realistic view of your machine's idleness, but this is enough to show the main culprits.

In my case, evolution, gnote and devhelp were all waking up about 30 times a second whilst mostly idle. Evolution might be an outlier, as it also talks to the network, and is a bigger application to debug, so I started with devhelp.

$ strace -vvv -p `pidof devhelp`
Process 19069 attached
restart_syscall(<... resuming interrupted call ...>) = 0
recvfrom(6, 0x23fece4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=3, events=POLLIN}], 3, 17) = 0 (Timeout)
recvfrom(6, 0x23fece4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=3, events=POLLIN}], 3, 17) = 0 (Timeout)

And the screen fills up with EAGAIN errors. This looks a lot like a a timeout being called too often.

Debugging wake-ups

I started sprinkling debug in g_main_context_prepare(), the function that prepares the various timeout and idle sources for dispatch, and calculates the timeouts for each poll() operation.

Something like:
if (source_timeout > 0 && source_timeout <= 20)
  g_message ("Source '%s' has very low timeout %d", g_source_get_name (source), source_timeout);

The problem is we end up getting a null source name for almost all of the sources. This is where g_source_set_name() and its sibling g_source_set_name_by_id() come in handy.

timeout_id = g_timeout_add (timeout, myfunction, mydata);
g_source_set_name_by_id (timeout_id, "[module-name] myfunction");

And we start doing that all over GTK+. As you can see from the patches in the bug, there's not just timeouts added by g_timeout_add() that we need to name.

In custody

The huge amount of debug shown when running our application with the gmain.c debug above tells us:
GLib-Message: Source 0x2d4f380 '[gtk+] gdk_frame_clock_paint_idle' has very low timeout 17
even when the window doesn't change, is in the background, and not updating. About 30 times a second.

Who are you gonna call?

Or by whom have you been called, rather. This is a small section of my ~/.gdbinit which will break on a particular function, print a backtrace, and continue. It makes it easier to interact with the logs after the fact, especially if they are calls that happen often and you're not interested in all the calls.

set breakpoint pending on
break gdk_frame_clock_begin_updating

We did the same for gdk_frame_clock_begin_updating and found a backtrace similar to the one in Bugzilla. We only needed to start reading some code after that, and figuring out what was going on. The result was a bug in GTK+, likely a regression from GTK+ 3.8.

Your laptop should last a bit longer when the updates hit.


Name your timeouts with g_source_set_name_by_id(), run powertop, and file bugs against broken applications.

Update: Fixed powertop command-line.


David said...

Thanks for the tip about g_source_set_name_by_id()!

Cristian Ciupitu said...

I believe the correct command is:

powertop --html=/tmp/foo.html --time=60

at least with powertop-2.4-5.fc19.x86_64.

Tobi said...

OS X Mavericks has a nice new power menu with the power wasting apps listed:


I thing this is something nice to have for Gnome.

Bastien Nocera said...

Cristian: You're right, I should have copy pasted instead of trying to remember it. Fixed.

Tobi: that strikes me as a pretty awful UI but some of that functionality is available through UPower's wake-ups D-Bus interface.

Stijn Hoop said...

Thank you for making my laptop last longer!

Federico Mena Quintero said...

FWIW, it's not too hard to find the timeout callbacks without having to name timers: https://people.gnome.org/~federico/news-2006-09.html#14

(Although having named timers is super nice!)