Bug 180330 – [GTK] WK2/JSC idle wakeups and CPU utilisation

• Component: WebKitGTK
• Status: RESOLVED INVALID

[Michael Gratton]

Created attachment 328288 [details]
Sysprof file showing call traces when idle (first 1/2 of the trace)

Since porting Geary to WebKit2, I have noticed it seems to have been running hotter than previously when idle. This has also been reported by others in Bug 783025[0]. One person noticed using strace that when Geary is on the visible desktop, it is calling and returning from poll() at about 60 times per second, which is a substantial number of wakeups for an idle application. This seems to also occur for Epiphany, but not in other GTK+ apps such as Gitg, or Polari. Hence it looks like a WebKit2 issue.

I'm noticing it under Wayland, and have a query out in that bug as to whether others are seeing it under X11. The poll() rate decreases when it is not on the visible desktop, and I've managed to get the rate down a bit as well by ensuring Geary is not showing a WebView, but these aren't terribly useful workarounds. Geary is setting WEBKIT_DISABLE_COMPOSITING_MODE=1 in main() right after launching, but commenting that out doesn't seem to make any difference. I also tried commenting out the ~6 JS message handlers that Geary uses for displaying conversations, but that didn't help either.

Sysprof shows that most of the work being done when idle is in g_main_context_prepare() — 21% of the total, g_source_iter() — 17% of total, and magazine_cache_push_magazine (used by g_slice) — 12%. Most of the work being done by calls to g_source_iter are being made from libjavascriptcoregtk-4.0.so — accounting for 13% of the total work when idle.

Example strace showing polling is attached to Bug 783025, example sysprof of idle period is attached.

[0] - <https://bugzilla.gnome.org/show_bug.cgi?id=783025>

[Michael Gratton]

FWIW, a stack from one of the threads in libjavascriptcoregtk-4.0.so calling g_source_iter looks like this:

> #0  0x00007fffefd64901 in __GI___poll (fds=0x7fff84002e90, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
> #1  0x00007ffff751d169 in g_main_context_poll (priority=<optimised out>, n_fds=1, fds=0x7fff84002e90, timeout=<optimised out>, context=0x7fff84000b10)
    at ../../../../glib/gmain.c:4187
> #2  0x00007ffff751d169 in g_main_context_iterate (context=0x7fff84000b10, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimised out>) at ../../../../glib/gmain.c:3881
> #3  0x00007ffff751d502 in g_main_loop_run (loop=0x7fff84001d10) at ../../../../glib/gmain.c:4082
> #4  0x00007ffff1b5e6b0 in WTF::RunLoop::run() () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
> #5  0x00007ffff1b5d6c2 in  () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
> #6  0x00007ffff1b3645b in WTF::Thread::entryPoint(WTF::Thread::NewThreadContext*) () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
> #7  0x00007ffff1b5c779 in  () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
> #8  0x00007fffeeb157fc in start_thread (arg=0x7fffd6fff700) at pthread_create.c:465
> #9  0x00007fffefd70b0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

There's six threads that are at the moment that are showing this same trace, after some time of normal application use. All six seem to be running different GMainLoop instances however, based on the loop=xxx param of frame #3 being different in each case.

[Michael Catanzaro]

That just means there are sources attached to the main loop. The problem is that one (or more) of them is being dispatched too frequently (when poll returns). You're not likely to catch that with a random backtrace in gdb. I know of only two ways to debug an issue like this. First is to add some printfs in gmain.c to print the names of the sources that are being dispatched, and hope against hope that the problematic source has a name. A better way would be to try to configure systemtap and use dunfell [1], but that might be hard. At least we know the problem is in the UI process, not the web process. ;)

Carlos suggested on the mailing list that the problem might be the paint timer, so it would make sense to try and figure out if that's right first.

[1] https://github.com/pwithnall/dunfell

[Michael Catanzaro]

FWIW I've never noticed this issue. I do see excessive memory consumption when running in Wayland relative to X11, but that's a completely different problem.

[Michael Gratton]

As recently noted on the Geary bug, it also happens under X11, and seems to be related to animations - setting /org/gnome/desktop/interface/enable-animations to false makes the issue go away.

I'll dig into that angle a bit more from Geary's perspective when I have a moment.

[Carlos Garcia Campos]

(In reply to Michael Gratton from comment #4)
> As recently noted on the Geary bug, it also happens under X11, and seems to
> be related to animations - setting
> /org/gnome/desktop/interface/enable-animations to false makes the issue go
> away.
> 
> I'll dig into that angle a bit more from Geary's perspective when I have a
> moment.

This is unlikely to be a WebKit bug then, we don't do anything different depending on enable-animations setting.

[Michael Gratton]

Sigh, looks like a GtkSpiner wasn't being stopped when hidden. Doing so fixes the issue for Geary. Apologies for the noise.

Reported the wakeups to GTK+ here: https://gitlab.gnome.org/GNOME/gtk/issues/166