Why are sound ioctl calls so slow?

From: Ian Freislich <ianf_at_za.uu.net>
Date: Mon, 08 Dec 2003 17:22:59 +0200
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
Received on Tue Dec 09 2003 - 04:17:40 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:37:33 UTC