[Webkit-unassigned] [Bug 210561] New: excessive wakeups/polling due to gdk_frame_clock_begin_updating
bugzilla-daemon at webkit.org
bugzilla-daemon at webkit.org
Wed Apr 15 11:46:57 PDT 2020
https://bugs.webkit.org/show_bug.cgi?id=210561
Bug ID: 210561
Summary: excessive wakeups/polling due to
gdk_frame_clock_begin_updating
Product: WebKit
Version: Other
Hardware: PC
OS: Linux
Status: NEW
Severity: Normal
Priority: P2
Component: WebKitGTK
Assignee: webkit-unassigned at lists.webkit.org
Reporter: webkit at tomi.nomi.cz
CC: bugs-noreply at webkitgtk.org
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 at entry=0x555abd114690) at ../../../glib/gmain.c:3974
#23 0x00007f34a0b9f890 in g_main_context_iterate
(context=0x555abd114690, block=block at entry=1, dispatch=dispatch at 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
--
You are receiving this mail because:
You are the assignee for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.webkit.org/pipermail/webkit-unassigned/attachments/20200415/04a06a93/attachment-0001.htm>
More information about the webkit-unassigned
mailing list