Bug#547207: Consistently high CPU usage

[Florian Weimer]

Package: vorbis-tools
Version: 1.2.0-6

I've got a (somewhat dated, admittedly) Core 2 duo, and ogg123 is
using about 50% of one core.  Most of it is in syscalls, though.

A couple of seconds of strace -f -c don't show a smoking gun, though:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.78    0.424026        7852        54           futex
  0.19    0.000828           0    151469           ioctl
  0.03    0.000127           0     25076           poll
  0.00    0.000000           0       185           read
  0.00    0.000000           0         9           write
  0.00    0.000000           0       442           semop
  0.00    0.000000           0         1           restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.424981                177236           total

AFAIK, the kernel CPU accounting implemented by strace is quite
broken, so the futex line likely indicates wall clock time.  For the
other calls, the rate is a bit on the high side (this was just
measuring a few seconds), but it shouldn't really cause that high a
CPU load.

strace cannot decode the ioctl numbers, but here they (this is on
amd64):

[pid 14792] ioctl(5, 0x4122, 0x3)       = 0
[pid 14792] ioctl(5, 0x4122, 0x45b82)   = 0
[pid 14792] ioctl(5, 0x4122, 0)         = 0
[pid 14792] ioctl(5, 0x4122, 0x3)       = 0
[pid 14792] ioctl(5, 0x4122, 0x45b82)   = 0
[pid 14792] ioctl(5, 0x4122, 0x45b82)   = 0
[pid 14792] poll([{fd=4, events=POLLIN|POLLERR|POLLNVAL}], 1, -1) = 1 ([{fd=4, revents=POLLIN}])

The handles are:

ogg123  13503   fw    4r   CHR 116,33      0t0   5158 /dev/snd/timer
ogg123  13503   fw    5u   CHR 116,16      0t0   6109 /dev/snd/pcmC0D0p

Looking at strace -T output, most poll calls return without any
waiting at all, so there's probably some form of busy waiting going
on.