Why are sound ioctl calls so slow?
Ian Freislich
ianf at za.uu.net
Tue Dec 9 05:17:40 PST 2003
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
More information about the freebsd-current
mailing list