[webkit-gtk] futex connection timed out ~ 500ms delay when loading

[Jérémy Lal]

Hi,

i always wondered why loading bytes into an already instantiated webview
took so much time (~600ms) between the webkit_web_view_load_bytes() call
and the first
"change" event.

Today i noticed that doing it twice in a row (< one second) reduced that
time for
the second call from ~600ms to ~100ms.

I straced it and got the small files attached.
There is a "futex connection timed out" that would explain quite nicely the
huge
delay if the configured time out was 500ms.

What can i do now to locate the culprit and get more info ?

Regards,
Jérémy.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.webkit.org/pipermail/webkit-gtk/attachments/20160603/15a8473b/attachment.html>
-------------- next part --------------
write(1, "loading bytes http://localhost:3"..., 58loading bytes
) = 58
futex(0x7f4878000900, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
write(33, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x7f4878000900, FUTEX_WAKE_PRIVATE, 1) = 1
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
read(20, "\1\0\0\0\0\0\0\0", 16)        = 8
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
poll([{fd=19, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=19, revents=POLLOUT}])
writev(19, [{"5 \4\0.\0`\0\t\0`\0\0\4\0\3\213\4\6\0/\0`\0.\0`\0&\0\0\0"..., 172}, {NULL, 0}, {"", 0}], 3) = 172
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
epoll_wait(5, [], 1024, 4)              = 0
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
read(20, "\1\0\0\0\0\0\0\0", 16)        = 8
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
write(33, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x7f4878000900, FUTEX_WAKE_PRIVATE, 1) = 1
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
read(20, "\7\0\0\0\0\0\0\0", 16)        = 8
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
write(1, "change 0 1 http://localhost:3000"..., 99change event 0 1
) = 99
-------------- next part --------------
write(1, "loading bytes http://localhost:3"..., 58loading bytes
) = 58
madvise(0x7f48e5f54000, 4096, MADV_NORMAL) = 0
write(33, "\1\0\0\0\0\0\0\0", 8)        = 8
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
read(20, "\1\0\0\0\0\0\0\0", 16)        = 8
write(33, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x7f4878000900, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f48e5ff3114, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 13, {1464945462, 621346433}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f48e5ff30e8, FUTEX_WAKE_PRIVATE, 1) = 0
read(20, "\1\0\0\0\0\0\0\0", 16)        = 8
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
read(20, 0x7ffe468905e0, 16)            = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 0 (Timeout)
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
write(33, "\1\0\0\0\0\0\0\0", 8)        = 8
poll([{fd=19, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=19, revents=POLLOUT}])
writev(19, [{"5 \4\0!\0`\0\t\0`\0\0\4\0\3\213\4\6\0\"\0`\0!\0`\0&\0\0\0"..., 112}, {NULL, 0}, {"", 0}], 3) = 112
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
recvmsg(19, 0x7ffe46890430, 0)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 3, 0) = 1 ([{fd=20, revents=POLLIN}])
read(20, "\7\0\0\0\0\0\0\0", 16)        = 8
write(20, "\1\0\0\0\0\0\0\0", 8)        = 8
write(1, "change 0 1 http://localhost:3000"..., 99change event 0 1
) = 99