Re: Why are sound ioctl calls so slow?

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/