Curious sound playback slowdown
Jos Backus
jos at catnook.com
Fri Sep 16 22:42:53 PDT 2005
lizzy:~% uname -a
FreeBSD lizzy.catnook.local 7.0-CURRENT FreeBSD 7.0-CURRENT #52: Fri Sep 16 03:22:12 PDT 2005 root at lizzy.catnook.local:/usr/obj/usr/src/sys/LIZZY i386
lizzy:~% cat /dev/sndstat
FreeBSD Audio Driver (newpcm)
Installed devices:
pcm0: <AudioPCI ES1370> at io 0xa400 irq 14 kld snd_es137x (1p/1r/2v channels duplex default)
lizzy:~% sysctl -a hw.snd
hw.snd.report_soft_formats: 1
hw.snd.targetirqrate: 32
hw.snd.feeder_rate_buffersize: 8192
hw.snd.feeder_rate_scaling: 5
hw.snd.feeder_rate_ratemax: 1102500
hw.snd.feeder_rate_ratemin: 4000
hw.snd.verbose: 1
hw.snd.maxautovchans: 3
hw.snd.unit: 0
hw.snd.pcm0.buffersize: 4096
hw.snd.pcm0.vchans: 2
hw.snd.pcm0.vchanrate: 48000
hw.snd.pcm0.latency_timer: 32
lizzy:~%
The problem: I have noticed for some time that occasionally, when visiting
certain websites, the sound notifications in KDE "slow down" from a particular
point in time on. After some trial and error I have been able to narrow down
the conditions under which this happens predictably:
The steps to reproduce the issue on my system are:
- Start playing an .mp3 with `splay song.mp3';
- Start `firefox http://www.tomshardware.com'
Once the page starts to load a slowdown of the playback speed can be observed
abruptly. A key requirement is that the site has Flash content and that the
Flash6 (haven't tried 7) player is configured in /etc/libmap.conf. When the
Flash6 entries are removed from /etc/libmap.conf the problem doesn't occur.
Some more info:
lizzy:~% splay song.mp3 &
lizzy:~% ktrace -di firefox http://www.tomshardware.com
[Notice sound slowdown upon page load. Quit firefox.]
lizzy:~% kdump | grep NAMI | grep dev
92219 sh NAMI "/dev/null"
92230 sh NAMI "/dev/null"
92231 firefox-bin NAMI "/dev/mixer"
92231 firefox-bin NAMI "/dev/mixer1"
92231 firefox-bin NAMI "/dev/dsp"
92231 firefox-bin NAMI "/dev/mixer"
92231 firefox-bin NAMI "/dev/mixer1"
lizzy:~%
Relevant ktrace info around open of /dev/dsp:
92231 firefox-bin CALL stat(0x29e3b090,0xbfbf6c08)
92231 firefox-bin NAMI "/tmp/.esd/socket"
92231 firefox-bin RET stat -1 errno 2 No such file or directory
92231 firefox-bin CALL open(0x8c9d050,0x6,0xbfbf6c70)
92231 firefox-bin NAMI "/dev/dsp"
92231 firefox-bin RET open 19/0x13
92231 firefox-bin CALL fcntl(0x13,0x4,0)
92231 firefox-bin RET fcntl 0
92231 firefox-bin CALL ioctl(0x13,SNDCTL_DSP_SETFMT,0xbfbf6ca4)
92231 firefox-bin RET ioctl 0
92231 firefox-bin CALL gettimeofday(0xbf8fde58,0)
92231 firefox-bin RET gettimeofday 0
92231 firefox-bin CALL recvfrom(0x17,0x8c89004,0x1000,0,0,0)
92231 firefox-bin GIO fd 23 read 290 bytes
"116\r
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<HTML><HEAD>
<TITLE>302 Found</TITLE>
</HEAD><BODY>
<H1>Found</H1>
The document has moved <A HREF="http://ilinks.industrybrains.com/showc\
t?sid=61&ct=Toms_Hardware_Mainboard&num=4&layt=2">here</A>\
.<P>
</BODY></HTML>
\r
0\r
\r
"
92231 firefox-bin RET recvfrom 290/0x122
92231 firefox-bin CALL write(0x7,0x28339e4d,0x1)
92231 firefox-bin GIO fd 7 wrote 1 byte
"8"
92231 firefox-bin RET write 1
92231 firefox-bin CALL poll(0xbf8fdce0,0x1,0xffffffff)
92231 firefox-bin RET poll 1
92231 firefox-bin CALL read(0x6,0xbf8fdb20,0x400)
92231 firefox-bin GIO fd 6 read 1 byte
"8"
92231 firefox-bin RET read 1
92231 firefox-bin CALL gettimeofday(0xbf8fddf8,0)
92231 firefox-bin RET gettimeofday 0
92231 firefox-bin CALL recvfrom(0x17,0xbf8fdd9f,0x1,0x2,0,0)
92231 firefox-bin RET recvfrom -1 errno 35 Resource temporarily unavailable
92231 firefox-bin CALL poll(0xbf8fdce0,0x1,0xffffffff)
92231 firefox-bin RET fork 0
92231 firefox-bin CALL ioctl(0x13,SNDCTL_DSP_STEREO,0xbfbf6ca0)
92231 firefox-bin RET ioctl 0
92231 firefox-bin CALL ioctl(0x13,SNDCTL_DSP_SPEED,0xbfbf6cdc)
92231 firefox-bin RET ioctl 0
92231 firefox-bin CALL ioctl(0x13,SNDCTL_DSP_SETFRAGMENT,0xbfbf6d08)
92231 firefox-bin RET ioctl 0
92231 firefox-bin CALL ioctl(0x13,SNDCTL_DSP_GETCAPS,0xbfbf6d04)
92231 firefox-bin RET ioctl 0
92231 firefox-bin CALL fcntl(0x13,0x4,0)
92231 firefox-bin RET fcntl 0
92231 firefox-bin CALL close(0x13)
As can be seen in the kdump, several ioctls() are performed on /dev/dsp. Of
course it's very hard to tell whether these ioctls() happen at the time the
slowdown starts, i.e. whether there is a correlation between the two events.
Has anybody else perhaps seen this?
--
Jos Backus
jos at catnook.com
More information about the freebsd-multimedia
mailing list