Date: Tue, 9 Dec 2003 14:25:57 -0500 From: Mathew Kanner <mat@cnd.mcgill.ca> To: Ian Freislich <ianf@za.uu.net> Cc: freebsd-current@freebsd.org Subject: Re: Why are sound ioctl calls so slow? Message-ID: <20031209192557.GE11072@cnd.mcgill.ca> In-Reply-To: <25518.1070896979@za.uu.net> References: <25518.1070896979@za.uu.net>
next in thread | previous in thread | raw e-mail | index | archive | help
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/
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20031209192557.GE11072>