Why are sound ioctl calls so slow?
Mathew Kanner
mat at cnd.mcgill.ca
Tue Dec 9 11:29:03 PST 2003
On Dec 08, Ian Freislich wrote:
> Hi
>
> mpg123 performs ~360 ioctls on startup. A cursory code inspection
> shows that it does this to figure out the capabilities of the sound
> device and find a best match for output. I'm not sure when mpg123
> started doing this, but I noticed the slowdown about a year or so
> ago. On my more modern machine this results in just a small
> hesitation, but on my antediluvian laptop causes a ~9 second pause
> before playing starts.
>
> Now, it seems after some debugging that the ioctl calls are quite
> slow. They take about 23ms on average to complete on a p133 if
> I've read the kdump output correctly
>
> Here's a fragment of the kdump with relative timestamps in the third
> column:
>
> 3224 mpg123 0.002752 CALL open(0x8061850,0x1,0x28066201)
> 3224 mpg123 0.000089 NAMI "/dev/dsp"
> 3224 mpg123 0.069851 RET open 3
> 3224 mpg123 0.000758 CALL ioctl(0x3,SNDCTL_DSP_GETBLKSIZE,0x8066680)
> 3224 mpg123 0.000107 RET ioctl 0
> 3224 mpg123 0.000569 CALL ioctl(0x3,SNDCTL_DSP_RESET,0)
> 3224 mpg123 0.000081 RET ioctl 0
> 3224 mpg123 0.000320 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.027081 RET ioctl 0
> 3224 mpg123 0.000315 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.026421 RET ioctl 0
> 3224 mpg123 0.000924 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.017885 RET ioctl 0
> 3224 mpg123 0.000049 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.025941 RET ioctl 0
> 3224 mpg123 0.001111 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.025938 RET ioctl 0
> 3224 mpg123 0.000491 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.017830 RET ioctl 0
> 3224 mpg123 0.000900 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.025978 RET ioctl 0
> 3224 mpg123 0.000549 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.026046 RET ioctl 0
> 3224 mpg123 0.000486 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.017751 RET ioctl 0
> 3224 mpg123 0.000399 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.026057 RET ioctl 0
> 3224 mpg123 0.000699 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.025951 RET ioctl 0
> 3224 mpg123 0.000665 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.017799 RET ioctl 0
> 3224 mpg123 0.000582 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.025974 RET ioctl 0
> 3224 mpg123 0.000484 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.026056 RET ioctl 0
> 3224 mpg123 0.000698 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.017708 RET ioctl 0
> 3224 mpg123 0.000356 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.026597 RET ioctl 0
> 3224 mpg123 0.000590 CALL ioctl(0x3,SNDCTL_DSP_STEREO,0xbfbff834)
> 3224 mpg123 0.026499 RET ioctl 0
> 3224 mpg123 0.000659 CALL ioctl(0x3,SNDCTL_DSP_SPEED,0xbfbff834)
> 3224 mpg123 0.018124 RET ioctl 0
> 3224 mpg123 0.000748 CALL ioctl(0x3,SNDCTL_DSP_SETFMT,0xbfbff834)
> 3224 mpg123 0.026260 RET ioctl 0
>
> Can someone firstly tell me whether or not if it is reasonable to
> expect the ioctl call to be any faster. Perhaps my reasoning is
> flawed, but I'd expect about 61000 instructions to be executed by
> the CPU (133MHz) in 23ms at an average of 50 clock cycles per
> instruction not taking cache misses into account. I cannot concieve
> of any reason why it should take 61000 instructions to write the
> format, speed or stereo to the sound hardware.
>
> Does each ioctl result in a context switch which means that the cpu
> spends time on other processes for each ioctl call? I'm not sure
> that this is what happens because mpg123 uses 100% cpu for about
> 10 seconds and then settles down to about 40% once it actually
> starts decoding the mp3.
Ian,
Sounds like you understand the problem, maybe you should
investigate :)
My first guess would be the device is rebuilding feeder/mixer
chains every time mpg123 changes format. I would run the test one
more time, disabling vchans and rate conversion.
sysctl hw.snd.report_soft_formats=0 hw.snd.maxautovchans=0
I didn't notice which version of fbsd that you are using.
--Mat
--
Applicants must also have extensive knowledge of UNIX,
although they should have sufficiently good programming
taste to not consider this an achievement.
- MIT AI Lab job ad in the /Boston Globe/
More information about the freebsd-current
mailing list