Date: Mon, 08 Dec 2003 17:22:59 +0200 From: Ian Freislich <ianf@za.uu.net> To: freebsd-current@freebsd.org Subject: Why are sound ioctl calls so slow? Message-ID: <25518.1070896979@za.uu.net> Resent-Message-ID: <39408.1070975856@za.uu.net>
next in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?25518.1070896979>