Bug 210561 – [GTK] excessive wakeups/polling due to gdk_frame_clock_begin_updating

• Component: WebKitGTK
• Status: RESOLVED FIXED

[Tomáš Janoušek]

Since upgrading to 2.28, /usr/lib/x86_64-linux-gnu/webkit2gtk-4.0/WebKitWebProcess drains my laptop battery like crazy:

$ ps axfu
[...]
tomi      243322 15.0  0.2 102683612 96224 ?     Sl   17:53   0:00 liferea
tomi      243332  4.7  0.2 102722076 90816 ?     SLl  17:53   0:00  \_ /usr/lib/x86_64-linux-gnu/webkit2gtk-4.0/WebKitWebProcess 7 19
tomi      243333  1.5  0.1 103007620 53204 ?     SLl  17:53   0:00  \_ /usr/lib/x86_64-linux-gnu/webkit2gtk-4.0/WebKitNetworkProcess 8 1

$ LANG=C strace -f -p 243332
strace: Process 243332 attached with 11 threads
[pid 243360] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243359] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243357] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243356] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243355] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243344] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243343] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243342] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243341] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 243340] futex(0x7f14fb18c7cc, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 243332] restart_syscall(<... resuming interrupted read ...>) = 0
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 17) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 16) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 16) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 16) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 15) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 16) = 0 (Timeout)
[pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 16) = 0 (Timeout)

It's not necessary to run liferea, it's reproducible just by "surf about:blank", so I tried to gdb the process to see what's going on. By breaking at ../../../glib/gmain.c:3677 and looking for small enough source_timeout, I found this:

(gdb) print *source
$8 = {callback_data = 0x562da2385070, callback_funcs = 0x7f4824f32280 <g_source_callback_funcs>, source_funcs =
    0x7f4824f32340 <g_timeout_funcs>, ref_count = 2, context = 0x562da20fa910, priority = 120, flags = 1, source_id = 29853,
  poll_fds = 0x0, prev = 0x0, next = 0x0, name = 0x562da243f320 "[gtk+] gdk_frame_clock_paint_idle", priv = 0x562da239ead0}

So it seems something is calling gdk_frame_clock_begin_updating without a matching gdk_frame_clock_end_updating... Well, there's just one call to gdk_frame_clock_begin_updating in the entire webkit source and no call to gdk_frame_clock_end_updating so we just need to find why that's getting called:

Thread 2.1 "WebKitWebProces" hit Breakpoint 2, gdk_frame_clock_begin_updating (frame_clock=0x555abd120590 [GdkFrameClockIdle])
    at ../../../../gdk/gdkframeclock.c:319
(gdb) bt
#0  gdk_frame_clock_begin_updating (frame_clock=0x555abd120590 [GdkFrameClockIdle]) at ../../../../gdk/gdkframeclock.c:319
#1  0x00007f34a3b15e49 in WebCore::DisplayRefreshMonitorGtk::requestRefreshCallback() ()
    at ../Source/WebCore/platform/graphics/gtk/DisplayRefreshMonitorGtk.cpp:67
#2  0x00007f34a39afa4a in WebCore::RenderingUpdateScheduler::scheduleTimedRenderingUpdate() ()
    at ../Source/WebCore/page/RenderingUpdateScheduler.cpp:59
#3  WebCore::RenderingUpdateScheduler::scheduleTimedRenderingUpdate() () at ../Source/WebCore/page/RenderingUpdateScheduler.cpp:45
#4  0x00007f34a3982129 in WTF::Function<void (WebCore::Document&)>::operator()(WebCore::Document&) const ()
    at DerivedSources/ForwardingHeaders/wtf/Function.h:84
#5  WebCore::Page::forEachDocument(WTF::Function<void (WebCore::Document&)> const&) const () at ../Source/WebCore/page/Page.cpp:2843
#6  0x00007f34a398225b in WebCore::Page::updateStyleAfterChangeInEnvironment() () at ../Source/WebCore/page/Page.cpp:574
#7  0x00007f34a39822e5 in WebCore::Page::updateStyleForAllPagesAfterGlobalChangeInEnvironment() ()
    at ../Source/WebCore/page/Page.cpp:586
#8  0x00007f34a2992656 in WebKit::WebPage::themeDidChange(WTF::String&&) ()
    at ../Source/WebKit/WebProcess/WebPage/gtk/WebPageGtk.cpp:167
#9  0x00007f34a2974f79 in WebKit::WebPage::WebPage(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&) () at ../Source/WebKit/WebProcess/WebPage/WebPage.cpp:604
#10 0x00007f34a29757fe in WebKit::WebPage::create(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&) () at ../Source/WebKit/WebProcess/WebPage/WebPage.cpp:379
#11 0x00007f34a27e36fc in WebKit::WebProcess::createWebPage(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&) () at ../Source/WebKit/WebProcess/WebProcess.cpp:685
#12 0x00007f34a24307d7 in IPC::callMemberFunctionImpl<WebKit::WebProcess, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&), std::tuple<WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters>, 0ul, 1ul>(WebKit::WebProcess*, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&), std::tuple<WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters>&&, std::integer_sequence<unsigned long, 0ul, 1ul>) () at ../Source/WebKit/Platform/IPC/HandleMessage.h:41
#13 IPC::callMemberFunction<WebKit::WebProcess, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&), std::tuple<WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters>, std::integer_sequence<unsigned long, 0ul, 1ul> >(std::tuple<WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters>&&, WebKit::WebProcess*, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&)) () at ../Source/WebKit/Platform/IPC/HandleMessage.h:47
#14 IPC::handleMessage<Messages::WebProcess::CreateWebPage, WebKit::WebProcess, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&)>(IPC::Decoder&, WebKit::WebProcess*, void (WebKit::WebProcess::*)(WTF::ObjectIdentifier<WebCore::PageIdentifierType>, WebKit::WebPageCreationParameters&&)) ()
    at ../Source/WebKit/Platform/IPC/HandleMessage.h:120
#15 0x00007f34a2429c5b in WebKit::WebProcess::didReceiveWebProcessMessage(IPC::Connection&, IPC::Decoder&) ()
    at DerivedSources/WebKit/WebProcessMessageReceiver.cpp:291
#16 0x00007f34a2580460 in IPC::Connection::dispatchMessage(IPC::Decoder&) () at ../Source/WebKit/Platform/IPC/Connection.cpp:1008
#17 0x00007f34a25817d5 in IPC::Connection::dispatchMessage(std::unique_ptr<IPC::Decoder, std::default_delete<IPC::Decoder> >) ()
    at ../Source/WebKit/Platform/IPC/Connection.cpp:1077
#18 0x00007f34a2581e9b in IPC::Connection::dispatchOneIncomingMessage() () at ../Source/WebKit/Platform/IPC/Connection.cpp:1146
#19 0x00007f34a03c4cac in WTF::RunLoop::performWork() () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
#20 0x00007f34a0412ae9 in  () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
#21 0x00007f34a0b9f4de in g_main_dispatch (context=0x555abd114690) at ../../../glib/gmain.c:3309
#22 g_main_context_dispatch (context=context@entry=0x555abd114690) at ../../../glib/gmain.c:3974
#23 0x00007f34a0b9f890 in g_main_context_iterate
    (context=0x555abd114690, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../glib/gmain.c:4047
#24 0x00007f34a0b9fb63 in g_main_loop_run (loop=0x555abd159c50) at ../../../glib/gmain.c:4241
#25 0x00007f34a0413548 in WTF::RunLoop::run() () at /usr/lib/x86_64-linux-gnu/libjavascriptcoregtk-4.0.so.18
#26 0x00007f34a299af8f in WebKit::AuxiliaryProcessMain<WebKit::WebProcess, WebKit::WebProcessMainGtk>(int, char**) ()
    at ../Source/WebKit/Shared/AuxiliaryProcessMain.h:68
#27 0x00007f34a1a2de0b in __libc_start_main (main=
    0x555abb1ef760 <main()>, argc=3, argv=0x7ffcb4760f68, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcb4760f58) at ../csu/libc-start.c:308
#28 0x0000555abb1ef7ea in _start ()

The document.scheduleTimedRenderingUpdate invocation in Page::updateStyleAfterChangeInEnvironment is definitely new in 2.28, but it does seem weird that any scheduleTimedRenderingUpdate invocation across webkit would lead to 60 wakeups per second forever and ever... Indeed, it seems that opening https://en.wikipedia.org/wiki/GIF#/media/File:Rotating_earth_(large).gif invokes scheduleTimedRenderingUpdate and even after switching to about:blank, this process continues waking up more than 60 times per second. So this is not really a 2.28 regression, it just got worse and is triggered by any web page, not just those that actually move.

Perhaps DisplayRefreshMonitorGtk::~DisplayRefreshMonitorGtk should call gdk_frame_clock_end_updating? But then, when I browse for a while and then attach gdb, break on gdk_frame_clock_paint_idle and print *priv, I get:

$2 = {frame_time = 51614508992, min_next_frame_time = 51614525659, sleep_serial = 7357, freeze_time = 0, flush_idle_id = 0, 
  paint_idle_id = 11239, freeze_count = 0, updating_count = 1, requested = GDK_FRAME_CLOCK_PHASE_NONE, 
  phase = GDK_FRAME_CLOCK_PHASE_NONE, in_paint_idle = 0}

updating_count is 1, so it doesn't seem like gdk_frame_clock_begin_updating is getting called multiple times, and thus calling gdk_frame_clock_end_updating is unlikely to help.
But it seems WebCore::RenderingUpdateScheduler::scheduleTimedRenderingUpdate (and thus also WebCore::DisplayRefreshMonitorGtk::requestRefreshCallback) _is_ getting called fairly often, so maybe this whole gdk_frame_clock_begin_updating is actually a mistake and we should be calling gdk_frame_clock_request_phase instead? More info about that here:

https://developer.gnome.org/gdk3/stable/GdkFrameClock.html

[Carlos Garcia Campos]

Thanks for the so detailed bug report. We have noticed this, but it wasn't always reproducible for me. I assumed we were leaking a DisplayRefreshMonitor at some point, but it seems we don't, and maybe the problem is the way we use the GdkFrameClock.

[Carlos Garcia Campos]

The reason why we don't call end_updating is because we assume the frame clock is destroyed when the offscreen window is destroyed.

[Carlos Garcia Campos]

I've tried to reproduce this again with MiniBrowser, evolution and liferea and I still can't reproduce it :-(

[Tomáš Janoušek]

> I've tried to reproduce this again with MiniBrowser, evolution and liferea and I still can't reproduce it :-(

Weird. :-/

I can reproduce it with 2.28.1 just by launching liferea, or by launching surf about:blank and then stracing the WebKitWebProcess. With 2.26.4 surf about:blank is okay, but surf https://en.wikipedia.org/wiki/GIF#/media/File:Rotating_earth_(large).gif triggers it.

[Tomáš Janoušek]

I should also say that my system is amd64 Debian testing.

[Carlos Garcia Campos]

Just to be clear, I see the GdkFrameClock being used, but it's correctly destroyed as expected.

[Tomáš Janoušek]

Perhaps you have a different version of gtk that fixed/worked around this? Or maybe it's a difference between X11 and Wayland backends? I'm using X11 and gtk 3.24.18.

[Tomáš Janoušek]

Anyway, if you want the offscreen window destruction to clean things up, perhaps https://developer.gnome.org/gtk3/unstable/GtkWidget.html#gtk-widget-add-tick-callback is better than gdk_frame_clock_begin_updating?

(BTW, if you want a more interactive communication channel, I'm Liskni_si on freenode and @Liskni_si on Twitter.)

[Carlos Garcia Campos]

(In reply to Tomáš Janoušek from comment #7)
> Perhaps you have a different version of gtk that fixed/worked around this?
> Or maybe it's a difference between X11 and Wayland backends? I'm using X11
> and gtk 3.24.18.

Maybe, I don't think it's X11 or wayland specific, because other people reported the problem with evolution under wayland.

[Carlos Garcia Campos]

(In reply to Tomáš Janoušek from comment #8)
> Anyway, if you want the offscreen window destruction to clean things up,
> perhaps
> https://developer.gnome.org/gtk3/unstable/GtkWidget.html#gtk-widget-add-tick-
> callback is better than gdk_frame_clock_begin_updating?

I've checked the GdkFrameClock is properly destroyed.

> (BTW, if you want a more interactive communication channel, I'm Liskni_si on
> freenode and @Liskni_si on Twitter.)

I'll ping you tomorrow on IRC then. Thanks!

[Christoph Anton Mitterer]

Hey.

Probably the following has nothing to do with this bug (which I'm also experiencing in at least Evolution):


Could it be that this issue is somehow caused by a kernel change (specifically something that happened in kernels >5.2)?


I see this pattern of fast:
pid 243332] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 243332] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 17) = 0 (Timeout)

in quite a number of applications (e.g. diodon is one: https://bugs.launchpad.net/diodon/+bug/1871008 ... and I've also noticed it in cinnamon https://github.com/linuxmint/cinnamon/issues/9085#issuecomment-615543487 )

These in turn are all programs which might play a part in a bigger issue I suffer since kernels >5.2, namely some massive increase of CPU temperature respectively power consumption for GPU but also non-GPU intensive workloads:
see:
https://bugzilla.kernel.org/show_bug.cgi?id=207245
(with links to other related bug reports)
for more details.



Cheers,
Chris.

[Michael Catanzaro]

If I were you, I would try bisecting the kernel.

[Tomáš Janoušek]

Christoph Anton Mitterer, yeah, if you're running several apps that each use WebKitGtk and suffer from this issue, that would indeed make your CPU considerably hotter. I'm lucky to just be running one and I still had to downgrade. :-)

Anyway, I added a reply here as well: https://gitlab.freedesktop.org/drm/intel/-/issues/953#note_470483 because I think the kernel issue may not be fully fixed either, and might be making it worse.

[Christoph Anton Mitterer]

@Michael: Well that's probably the next thing on the road.

@Tomáš: Thanks for your comments, though I kinda doubt that the WebKit issue is the only reason for my problems (see e.g. my extensive tests, which show that even without Evolution or any GUI activity, there's a huge difference between 5.2 and 5.5 (worse)... and within each between intel_pstate being enabled (worse) and not.

Having e.g. Evolution run with some WebKit process being in the state of high CPU utilisation (which is likely this bug), just makes it worse.


Could anyone else check whether he sees *this* issue here, with much older kernels (i.e. 5.2 and below)?

Also, any fix for this on the horizon? :-)

[Carlos Garcia Campos]

(In reply to Christoph Anton Mitterer from comment #14)
> @Michael: Well that's probably the next thing on the road.
> 
> @Tomáš: Thanks for your comments, though I kinda doubt that the WebKit issue
> is the only reason for my problems (see e.g. my extensive tests, which show
> that even without Evolution or any GUI activity, there's a huge difference
> between 5.2 and 5.5 (worse)... and within each between intel_pstate being
> enabled (worse) and not.
> 
> Having e.g. Evolution run with some WebKit process being in the state of
> high CPU utilisation (which is likely this bug), just makes it worse.
> 
> 
> Could anyone else check whether he sees *this* issue here, with much older
> kernels (i.e. 5.2 and below)?
> 
> Also, any fix for this on the horizon? :-)

I need to reproduce it to fix it. Or some help from someone who can reproduce it to debug the issue and understand the problem. Another solution might be to forget about GdkFrameClock and use a simple timer at 60fps.

[Tomáš Janoušek]

> I need to reproduce it to fix it. Or some help from someone who can reproduce it to debug the issue and understand the problem. Another solution might be to forget about GdkFrameClock and use a simple timer at 60fps.

I'd love to help but I don't know what else I can do here. Any ideas?
Last week you said you'd ping me on IRC on Friday... :-/

[Carlos Garcia Campos]

Created attachment 397337 [details]
Patch

Finally found the problem with help from Tomáš. Thanks!

[Carlos Garcia Campos]

Committed r260567: <https://trac.webkit.org/changeset/260567>

[Sergio Villar Senin]

Comment on attachment 397337 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=397337&action=review

Awesome!

> Source/WebCore/platform/graphics/gtk/DisplayRefreshMonitorGtk.cpp:50
> +    gtk_widget_destroy(m_window);

Do we really need the destroy? Isn't it enough with calling _end_updating()

[Sergio Villar Senin]

(In reply to Sergio Villar Senin from comment #19)
> Comment on attachment 397337 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=397337&action=review
> 
> Awesome!
> 
> > Source/WebCore/platform/graphics/gtk/DisplayRefreshMonitorGtk.cpp:50
> > +    gtk_widget_destroy(m_window);
> 
> Do we really need the destroy? Isn't it enough with calling _end_updating()

Beh, I've just realized that we're already calling it, nevermind.

[Milan Crha]

Is it good idea to:

   ASSERT(frameClock);

on both places? The gtk_widget_get_frame_clock() can return NULL, according to its documentation.

You can also use g_signal_handlers_disconnect_by_data(), which was added in glib 2.32. I do not see which version of glib WebKitGTK depends on (not from FindGLIB.cmake at least).

[Carlos Alberto Lopez Perez]

(In reply to Milan Crha from comment #21)

> You can also use g_signal_handlers_disconnect_by_data(), which was added in
> glib 2.32. I do not see which version of glib WebKitGTK depends on (not from
> FindGLIB.cmake at least).

It's currently set to 2.44 in

Source/cmake/OptionsGTK.cmake:find_package(GLIB 2.44.0 REQUIRED COMPONENTS gio gio-unix gobject gthread gmodule)

And it would be OK to raise that minimum version to 2.56 (its what ships Ubuntu-18.04)

[Milan Crha]

(In reply to Carlos Alberto Lopez Perez from comment #22)
> ...And it would be OK to raise that minimum version...

No need to raise it, from my point of view. As long as you use API in the old version it's all fine.

[Carlos Garcia Campos]

(In reply to Milan Crha from comment #21)
> Is it good idea to:
> 
>    ASSERT(frameClock);
> 
> on both places? The gtk_widget_get_frame_clock() can return NULL, according
> to its documentation.

Yes, but in this case we are creating a toplevel that we manually realize, so the frame clock is already created for sure.

> You can also use g_signal_handlers_disconnect_by_data(), which was added in
> glib 2.32. I do not see which version of glib WebKitGTK depends on (not from
> FindGLIB.cmake at least).

I guess it doesn't matter unless it's more efficient.

[Milan Crha]

(In reply to Carlos Garcia Campos from comment #24)
> I guess it doesn't matter unless it's more efficient.

I doubt it's more efficient. I suggested it rather for readability/convenience. Nothing important.

[Christoph Anton Mitterer]

Hey guys.

I've got the fix no with some recent Debian package,... and the extreme CPU utilisations are in fact fixed.

However, I still see some little sporadic CPU utilisation from Evolution's WebKit processes every now and then... really nothing dramatic, most of the time they're 0%, however they do go up to say 2-3,3% every once in a while, *even though nothing happens at Evolution* (like I do not select any other mail, so that content would have to be re-drawn, nor are there any animated GIFs or so). It even happens when Evolution is minimised.

Is this kinda expected or something that one should follow up.

Thanks,
Chris.

[Milan Crha]

Evolution can invoke repaint of the message preview, indirectly, when the theme style changes. It can happen also when the window gets focus or loses it. I currently do not know what else could cause that, not periodically. Maybe install debuginfo for (or build with it) the evolution itself (not WebKit, it's too huge) and when it happens, supposing there will be enough time to do it, catch a series of backtraces of the offending process, which may or may not shed a bit of light on this. I catch backtraces with this command:

   for i in {1..10}; do gdb --batch --ex "t a a bt" -pid=`pidof evolution` &>bt$i.txt; sleep 0.1; done

You can tweak the delay between them with the sleep command (set to 100ms in the command). The backtraces may not expose any private information, but, please, check the files for any private information, like passwords, email address, server addresses,... I usually search for "pass" at least (quotes for clarity only). Just in case.

I do not know whether we should keep this here, as the bug itself is fixed. Feel free to open a new bug on the evolution side and we can investigate there [1].

[1] https://gitlab.gnome.org/GNOME/evolution/issues/new