Date: Fri, 16 Sep 2005 22:43:59 -0701 From: Jos Backus <jos@catnook.com> To: multimedia@freebsd.org Subject: Curious sound playback slowdown Message-ID: <20050917054421.GA93917@lizzy.catnook.local>
next in thread | raw e-mail | index | archive | help
lizzy:~% uname -a FreeBSD lizzy.catnook.local 7.0-CURRENT FreeBSD 7.0-CURRENT #52: Fri Sep 16 03:22:12 PDT 2005 root@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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20050917054421.GA93917>