strace shows 200 poll/read EAGAIN errors per second

[Ian! D. Allen]

Binary package hint: firefox-3.5

The latest Ubuntu 9.10 Firefox continues a tradition of looping with
EAGAIN errors. (This also happened under 8.10.) I did a 10-second
"strace" into a file and counted about 2000 poll/read errors. In all
there are about 500 syscalls per second in the 10-second strace.

Under Gnome, the structure of the errors is in repeated groups of five
syscalls: The first poll()'s last (timeout) argument is zero, and it
returns zero (Timeout), followed by a read(3,...) with EAGAIN, followed
by a second poll with a timeout of various numbers (e.g. 3782, 3777,
3775 below) that returns unit 86, followed by a read(86,...) of one byte
that succeeds, followed by yet another read(3,...) returning EAGAIN,
then the cycle repeats, hundreds of times per second:

--- strace under Gnome ---

Process 9266 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 1
read(86, "\372", 1) = 1
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 0) = 0 (Timeout)
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 3782) = 1 ([{fd=86, revents=POLLIN}])
read(86, "\372", 1) = 1
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 0) = 0 (Timeout)
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 3777) = 1 ([{fd=86, revents=POLLIN}])
read(86, "\372", 1) = 1
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 0) = 0 (Timeout)
read(3, 0x7f003b6ab074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=64, events=POLLIN|POLLPRI}, {fd=79, events=POLLIN|POLLPRI}, {fd=81, events=POLLIN|POLLPRI}, {fd=84, events=POLLIN|POLLPRI}, {fd=94, events=POLLIN}, {fd=70, events=POLLIN|POLLPRI}, {fd=116, events=POLLIN}, {fd=124, events=POLLIN}, {fd=86, events=POLLIN}], 11, 3775) = 1 ([{fd=86, revents=POLLIN}])
read(86, "\372", 1) = 1

--- end ---

The full syscall list in about 10 seconds was:

   2761 read
   1981 poll
    118 lseek
    112 write
    108 stat
     34 futex
     24 fcntl
      8 fstat
      8 access
      6 inotify_add_watch
      3 fdatasync
      2 writev
      1 restart_syscall
      1 ftruncate

Going away from Gnome, running Firefox with "-safe-mode" under the plain
"vtwm" window manager (no Gnome overhead), with a new profile created,
the errors change to include futex() in the looping mix:

--- strace under vtwm with -safe-mode ---

Process 24840 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 1
read(22, "\372", 1) = 1
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 463) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
futex(0x7f20370f278c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f20370f2788, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 454) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
futex(0x7f20370f278c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f20370f2788, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=41, events=POLLIN}, {fd=22, events=POLLIN}], 8, 423) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
futex(0x7f20370f278c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f20370f2788, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
read(3, 0x7f2037094074, 4096) = -1 EAGAIN (Resource temporarily unavailable)

--- end ---

The full syscall list in about 10 seconds (under vtwm) was:

   1042 read
    696 poll
    282 futex
      3 write
      3 inotify_add_watch
      1 restart_syscall

Running under vtwm without -safe-mode (but using a new profile), the
looping is less severe - only about 5 syscalls per second now:

--- strace under vtwm ---

poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 3473) = 0 (Timeout)
inotify_add_watch(40, "/home/idallen/.config/ibus/bus", IN_MODIFY|IN_ATTRIB|IN_CLOSE_WRITE|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_UNMOUNT|IN_ONLYDIR) = -1 ENOENT (No such file or directory)
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 3997) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 2891) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
write(25, "8", 1) = 1
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 2887) = 1 ([{fd=22, revents=POLLIN}])
read(22, "\372", 1) = 1
access("/var/lib/update-notifier/user.d/firefox-3.5-restart-required", F_OK) = 0
stat("/var/lib/update-notifier/user.d/firefox-3.5-restart-required", {st_mode=S_IFREG|0644, st_size=460, ...}) = 0
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=17, events=POLLIN|POLLPRI}, {fd=20, events=POLLIN|POLLPRI}, {fd=40, events=POLLIN}, {fd=22, events=POLLIN}], 8, 0) = 0 (Timeout)
read(3, 0x7f8d07c94074, 4096) = -1 EAGAIN (Resource temporarily unavailable)

--- end ---

ProblemType: Bug
Architecture: amd64
Date: Tue Feb 2 01:32:30 2010
DistroRelease: Ubuntu 9.10
InstallationMedia: Ubuntu 9.10 "Karmic Koala" - Release amd64 (20091027)
Package: firefox-3.5 3.5.7+nobinonly-0ubuntu0.9.10.1
ProcEnviron:
 PATH=(custom, user)
 LANG=en_CA.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.31-17.54-generic
SourcePackage: firefox-3.5
Uname: Linux 2.6.31-17-generic x86_64

[Zaus (marcin-konto)]

Same issue with firefox-3.6.2 Ubuntu Karmic 32bit

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.