Bug#801275: iceweasel wakes up at 60 Hz when idle
sacrificial-spam-address at horizon.com
sacrificial-spam-address at horizon.com
Thu Oct 8 06:28:37 UTC 2015
Package: iceweasel
Version: 41.0.1-1
Architecture: i386
This is probably a generic firefox bug, but I'm starting here to
respoect the firefox/iceweasel split.
Basicallly, when I have iceweasel idling with a lot of tabs open,
it burns 10-20% CPU doing nothing.
The desired behaviour, when there is no UI activity and all pages have
finished loading, is that it use zero. Not approximately zero, but each
and every thread blocked on a system call with no timeout. (If pressed,
I will accept long (> 1000 second) timeouts for cache discard, software
update checks, and so on.)
Upon investigation, I discovered that there is one thread that seems
to be spinning doing (blank lines added):
$ strace -r -p 12917
0.000060 write(27, "\372", 1) = 1
0.000057 clock_gettime(CLOCK_MONOTONIC, {51966, 125267419}) = 0
0.000051 clock_gettime(CLOCK_MONOTONIC, {51966, 125317984}) = 0
0.000049 clock_gettime(CLOCK_MONOTONIC, {51966, 125367361}) = 0
0.000045 clock_gettime(CLOCK_MONOTONIC, {51966, 125412268}) = 0
0.000046 clock_gettime(CLOCK_MONOTONIC, {51966, 125458852}) = 0
0.000047 clock_gettime(CLOCK_MONOTONIC, {51966, 125504807}) = 0
0.000046 clock_gettime(CLOCK_MONOTONIC, {51966, 125550762}) = 0
0.000045 clock_gettime(CLOCK_MONOTONIC, {51966, 125597486}) = 0
0.000055 clock_gettime(CLOCK_MONOTONIC, {51966, 125652590}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 125694075}) = 0
0.000052 futex(0x9a5f910c, FUTEX_WAIT_BITSET_PRIVATE, 1, {51966, 142406075}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.016789 clock_gettime(CLOCK_MONOTONIC, {51966, 142533466}) = 0
0.000042 futex(0x9a5f90f0, FUTEX_WAKE_PRIVATE, 1) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 142604773}) = 0
0.000035 clock_gettime(CLOCK_MONOTONIC, {51966, 142640252}) = 0
0.000040 write(27, "\372", 1) = 1
0.000038 clock_gettime(CLOCK_MONOTONIC, {51966, 142718194}) = 0
0.000038 clock_gettime(CLOCK_MONOTONIC, {51966, 142756187}) = 0
0.000038 clock_gettime(CLOCK_MONOTONIC, {51966, 142793971}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 142827425}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 142860878}) = 0
0.000035 clock_gettime(CLOCK_MONOTONIC, {51966, 142896078}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 142929462}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 142963195}) = 0
0.000035 clock_gettime(CLOCK_MONOTONIC, {51966, 142998744}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 143031848}) = 0
0.000035 futex(0x9a5f910c, FUTEX_WAIT_BITSET_PRIVATE, 1, {51966, 158823848}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.015913 clock_gettime(CLOCK_MONOTONIC, {51966, 158985591}) = 0
0.000050 futex(0x9a5f90f0, FUTEX_WAKE_PRIVATE, 1) = 0
0.000042 clock_gettime(CLOCK_MONOTONIC, {51966, 159072403}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 159109069}) = 0
0.000055 write(27, "\372", 1) = 1
0.000042 clock_gettime(CLOCK_MONOTONIC, {51966, 159205589}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 159243023}) = 0
0.000038 clock_gettime(CLOCK_MONOTONIC, {51966, 159281017}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 159314191}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 159347575}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 159381517}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 159415320}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 159448564}) = 0
0.000036 clock_gettime(CLOCK_MONOTONIC, {51966, 159484951}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 159517986}) = 0
0.000034 futex(0x9a5f910c, FUTEX_WAIT_BITSET_PRIVATE, 1, {51966, 175309986}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.015914 clock_gettime(CLOCK_MONOTONIC, {51966, 175473195}) = 0
0.000052 futex(0x9a5f90f0, FUTEX_WAKE_PRIVATE, 1) = 0
0.000045 clock_gettime(CLOCK_MONOTONIC, {51966, 175562731}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 175599258}) = 0
0.000039 clock_gettime(CLOCK_MONOTONIC, {51966, 175639625}) = 0
0.000046 clock_gettime(CLOCK_MONOTONIC, {51966, 175685022}) = 0
0.000039 clock_gettime(CLOCK_MONOTONIC, {51966, 175723993}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 175757237}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 175791598}) = 0
0.000035 clock_gettime(CLOCK_MONOTONIC, {51966, 175825750}) = 0
0.000034 clock_gettime(CLOCK_MONOTONIC, {51966, 175858994}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 175892937}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 175929813}) = 0
0.000033 clock_gettime(CLOCK_MONOTONIC, {51966, 175962847}) = 0
0.000035 futex(0x9a5f910c, FUTEX_WAIT_BITSET_PRIVATE, 1, {51966, 191752847}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.015947 clock_gettime(CLOCK_MONOTONIC, {51966, 191950603}) = 0
0.000052 futex(0x9a5f90f0, FUTEX_WAKE_PRIVATE, 1) = 0
0.000041 clock_gettime(CLOCK_MONOTONIC, {51966, 192038602}) = 0
0.000037 clock_gettime(CLOCK_MONOTONIC, {51966, 192074640}) = 0
(repeat forever)
The only potentially blocking system calls it makes are
futex(FUTEX_WAIT_BITSET_PRIVATE), where it uses a very short timeout
(FUTEX_WAIT_BITSET uses absolute timeouts based on CLOCK_MONOTONIC),
and write(), which does not actually block in this case.
The one-byte write of 0xfa goes to a pipe to the main thread (12880),
which wakes up and does a whole lot of other stuff.
The write appears to happen at approximately 60 Hz:
$ strace -r -ewrite -p 12917
Process 12917 attached
0.000000 write(27, "\372", 1) = 1
0.017009 write(27, "\372", 1) = 1
0.017013 write(27, "\372", 1) = 1
0.015990 write(27, "\372", 1) = 1
0.016971 write(27, "\372", 1) = 1
0.016985 write(27, "\372", 1) = 1
0.015977 write(27, "\372", 1) = 1
0.016994 write(27, "\372", 1) = 1
0.017022 write(27, "\372", 1) = 1
0.016028 write(27, "\372", 1) = 1
0.016978 write(27, "\372", 1) = 1
0.016981 write(27, "\372", 1) = 1
Freezing thread 12917 (by attaching gdb to it) has some odd UI effects,
most significantly no window update takes place (e.g. form input,
scrolling, changing tabs) until I have moved the cursor out of the window.
But it mostly works, and works a lot more like I want.
(There is still soemthing waking up the main thread every few seconds,
but it's definitely progress.)
After killing that one, there's a second, (pid 12896 for me) that's
doing the same thing but with CLOCK_REALTIME:
0.000074 write(27, "\372", 1) = 1
0.000079 clock_gettime(CLOCK_MONOTONIC, {54281, 785986425}) = 0
0.000079 clock_gettime(CLOCK_MONOTONIC, {54281, 786064576}) = 0
0.000072 gettimeofday({1444243016, 576283}, NULL) = 0
0.000068 futex(0xb71f2ec8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1496113, {1444243016, 588283000}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.012101 clock_gettime(CLOCK_MONOTONIC, {54281, 798312711}) = 0
0.000084 futex(0xb71b2520, FUTEX_WAKE_PRIVATE, 1) = 0
0.000066 write(27, "\372", 1) = 1
0.000078 clock_gettime(CLOCK_MONOTONIC, {54281, 798533337}) = 0
0.000072 gettimeofday({1444243016, 588753}, NULL) = 0
0.000067 futex(0xb71f2ec8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1496115, {1444243017, 76753000}, ffffffff) = 0
0.000125 clock_gettime(CLOCK_MONOTONIC, {54281, 798798102}) = 0
0.000072 gettimeofday({1444243016, 589016}, NULL) = 0
0.000066 futex(0xb71b2520, FUTEX_WAKE_PRIVATE, 1) = 0
0.000057 futex(0xb71f2ec8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1496117, {1444243016, 839016000}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.250041 clock_gettime(CLOCK_MONOTONIC, {54282, 49041507}) = 0
0.000087 futex(0xb71b2520, FUTEX_WAKE_PRIVATE, 1) = 0
0.000068 write(27, "\372", 1) = 1
0.000075 clock_gettime(CLOCK_MONOTONIC, {54282, 49263669}) = 0
0.000072 gettimeofday({1444243016, 839482}, NULL) = 0
0.000066 futex(0xb71f2ec8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1496119, {1444243017, 76482000}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
0.237096 clock_gettime(CLOCK_MONOTONIC, {54282, 286506338}) = 0
0.000088 futex(0xb71b2520, FUTEX_WAKE_PRIVATE, 1) = 0
That seems to be waking up twice every half second:
$ strace -r -ewrite -p 12896
Process 12896 attached
0.000000 write(27, "\372", 1) = 1
0.000965 write(27, "\372", 1) = 1
0.003997 write(27, "\372", 1) = 1
0.000700 write(27, "\372", 1) = 1
0.499486 write(27, "\372", 1) = 1
0.000694 write(27, "\372", 1) = 1
0.499703 write(27, "\372", 1) = 1
0.000401 write(27, "\372", 1) = 1
0.500795 write(27, "\372", 1) = 1
0.000161 write(27, "\372", 1) = 1
0.500586 write(27, "\372", 1) = 1
0.000406 write(27, "\372", 1) = 1
0.499723 write(27, "\372", 1) = 1
0.000434 write(27, "\372", 1) = 1
0.492313 write(27, "\372", 1) = 1
0.007428 write(27, "\372", 1) = 1
0.001384 write(27, "\372", 1) = 1
Attaching a second gdb to that finally gets close to the result I want:
$ strace -r -f -p 12880
[pid 12880] 0.000094 poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}], 6, -1) = 1 ([{fd=5, revents=POLLIN}])
[pid 12880] 1.478302 clock_gettime(CLOCK_MONOTONIC, {54493, 886916307}) = 0
[pid 12880] 0.000284 recvmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"U\2G\316\276\202?\3\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\3\37>\3\0\0", 4096}], msg_controllen=0, msg_flags=0}, 0) = 32
[pid 12880] 0.000336 recvmsg(5, 0xbf8f5774, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 12880] 0.000282 clock_gettime(CLOCK_MONOTONIC, {54493, 887816062}) = 0
[pid 12880] 0.000307 recvmsg(5, 0xbf8f5774, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 12880] 0.000269 poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}], 6, -1) = 1 ([{fd=5, revents=POLLIN}])
[pid 12880] 4.085123 clock_gettime(CLOCK_MONOTONIC, {54497, 973514144}) = 0
[pid 12880] 0.000102 recvmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"U\2G\316\265\222?\3\3\4\4\0\0\0\0\0\0\0\0\4\4\4\4\4\0\0\3\37%\2\0\0", 4096}], msg_controllen=0, msg_flags=0}, 0) = 32
[pid 12880] 0.000257 recvmsg(5, 0xbf8f5774, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 12880] 0.000122 clock_gettime(CLOCK_MONOTONIC, {54497, 973992062}) = 0
[pid 12880] 0.000093 recvmsg(5, 0xbf8f5774, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 12880] 0.000092 poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}], 6, -1^CProcess 12880 detached
fd 5 is /tmp/.X11-unix/X0, and I need to figure out what's causing
*that* activity every few seconds, but I'll worry about that after
I've got these 60 Hz and 2 Hz issues addressed.
More information about the pkg-mozilla-maintainers
mailing list