From owner-freebsd-current@FreeBSD.ORG Tue Dec 9 11:29:02 2003 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id E31D216A4CE for ; Tue, 9 Dec 2003 11:29:02 -0800 (PST) Received: from hak.cnd.mcgill.ca (hak.cnd.mcgill.ca [132.216.11.133]) by mx1.FreeBSD.org (Postfix) with ESMTP id 6549643D3B for ; Tue, 9 Dec 2003 11:28:50 -0800 (PST) (envelope-from mat@hak.cnd.mcgill.ca) Received: from hak.cnd.mcgill.ca (localhost [127.0.0.1]) by hak.cnd.mcgill.ca (8.12.9/8.12.8) with ESMTP id hB9JPx15020187; Tue, 9 Dec 2003 14:25:59 -0500 (EST) (envelope-from mat@hak.cnd.mcgill.ca) Received: (from mat@localhost) by hak.cnd.mcgill.ca (8.12.9/8.12.8/Submit) id hB9JPvsE020186; Tue, 9 Dec 2003 14:25:57 -0500 (EST) Date: Tue, 9 Dec 2003 14:25:57 -0500 From: Mathew Kanner To: Ian Freislich Message-ID: <20031209192557.GE11072@cnd.mcgill.ca> References: <25518.1070896979@za.uu.net> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <25518.1070896979@za.uu.net> User-Agent: Mutt/1.4.1i Organization: I speak for myself, operating in Montreal, CANADA X-Spam-Status: No, hits=0.0 required=5.0 tests=none autolearn=no version=2.60 X-Spam-Checker-Version: SpamAssassin 2.60 (1.212-2003-09-23-exp) on hak.cnd.mcgill.ca cc: freebsd-current@freebsd.org Subject: Re: Why are sound ioctl calls so slow? X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 09 Dec 2003 19:29:03 -0000 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/