Peculiar audio behaviour (9.1)

[Mouse <mouse%Rodents-Montreal.ORG@localhost>]

I'm working with a company that's got a turnkey product running under
9.1.  (They may move to a new version at some point, but still at 9.1
at the moment.)

One of the things their product does is play some audio; historically,
this has been out the machine's built-in audio hardware (they always
select machines with such hardware).

They have recently found the machines they used to use getting
expensive.  They found a cheaper machine...but it was running unusably
slowly.  We eventually tracked this down to an audio subsystem issue.

Here's everything from dmesg.boot that looks audio-related to me (I can
provide the full dmesg.boot if anyone wants it):

hdaudio0 at pci0 dev 31 function 3: HD Audio Controller
hdaudio0: interrupting at msi4 vec 0
hdafg0 at hdaudio0: vendor 8086 product 280b
hdafg0: DP00 8ch: Digital Out [Jack]
hdafg0: 8ch/0ch 48000Hz PCM16*
...
uaudio0 at uhub1 port 9 configuration 1 interface 0
uaudio0: CSCTEK (0x573) USB Audio and HID (0x1573), rev 2.00/80.07, addr 4
uaudio0: audio rev 1.00
audio0 at uaudio0: playback, capture, full duplex, independent
audio0: slinear_le:16 2ch 48000Hz, blk 11520 bytes (60ms) for playback
audio0: slinear_le:16 1ch 48000Hz, blk 5760 bytes (60ms) for recording

If the software opens /dev/audio0 and configures it the way it wants

  /*
  * There is a kernel bug in 9.1.  If you specify play.gain and
  *  play.balance in the same AUDIO_SETINFO ioctl, play.gain gets
  *  ignored(!!).  So we AUDIO_SETINFO twice, the first time setting up
  *  most parameters, including balance, the second setting the gain.
  */
  AUDIO_INITINFO( &ai);
  ai.play.sample_rate = 8000;
  ai.play.channels = 1;
  ai.play.precision = 16; /* 16 seems best... */
  ai.play.encoding = AUDIO_ENCODING_ULINEAR_LE;
  ai.play.port = oai.play.avail_ports;
  ai.play.pause = 0;
  ai.play.balance = AUDIO_MID_BALANCE;
  ai.mode = AUMODE_PLAY | AUMODE_PLAY_ALL;

  if ( ioctl( fd, AUDIO_SETINFO, &ai) < 0)
  {
    fprintf( stderr, "AUDIO_SETINFO: %s\n", strerror( errno));
    exit( 1);
  }

  AUDIO_INITINFO( &ai);
  ai.play.gain = AUDIO_FULL_GAIN;
  ai.monitor_gain = AUDIO_FULL_GAIN;

  if ( ioctl( fd, AUDIO_SETINFO, &ai) < 0)
  {
    fprintf( stderr, "AUDIO_SETINFO: %s\n", strerror( errno));
    exit( 1);
  }

and then simply writes to it (two octets - one sample - at a time), the
audio writes block for ridiculously long times (tens of milliseconds).
It's not syscall overhead; if I instead have it open /dev/null and skip
the audio setup ioctls, the writes complete fast.

I checked with audioctl -a from a different shell while the program is
running, and the play.* values look to me as though they match the
above:

$ audioctl -a | fgrep play
play.rate=8000
play.channels=1
play.precision=16
play.encoding=ulinear_le
play.gain=127
play.balance=32
play.port=0x0
play.avail_ports=0x0
play.seek=0
play.samples=0
play.eof=0
play.pause=0
play.error=0
play.waiting=0
play.open=0
play.active=1
play.buffer_size=65536
$ 

I then tried (a) setting the audio descriptor nonblocking and (b)
keeping some stats, printing them once a second.  This told me:

- The program is trying to write() two octets (representing one sample)
  a bit under 8000 times a second.  (Per second, in successive seconds:
  7461, 7296, 7590, 7128, 7185, 6476, 7741.)

- The writes succeed until a bit over thirty-four thousand samples
  (oddly, more than exactly play.buffer_size bytes) have been written.
  Then they start returning EWOULDBLOCK.  They return EWOULDBLOCK all
  the time after that point.

In the case where the audio descriptor is set non-blocking, the
observations are consistent with the theory that audio isn't playing,
that the bits have just stopped leaving the buffer (if they ever
started).  However, that seems to me to be inconsistent with the
blocking case, where the writes do eventually complete, just in tens of
milliseconds instead of tens of microseconds.

This odd behaviour happens only on the new hardware (dmesg.boot quotes
above); their former machines-of-choice work as expected.  One such is

hdaudio0 at pci0 dev 31 function 3: HD Audio Controller
hdaudio0: interrupting at msi5 vec 0
hdafg0 at hdaudio0: vendor 10ec product 0269
hdafg0: DAC00 2ch: HP Out [Jack]
hdafg0: DAC01 2ch: Speaker [Built-In]
hdafg0: ADC02 2ch: Mic In [Jack]
hdafg0: 2ch/2ch 32000Hz 44100Hz 48000Hz 88200Hz 96000Hz 192000Hz PCM16 PCM20 PCM24 AC3
audio0 at hdafg0: playback, capture, full duplex, independent
audio0: slinear_le:16 2ch 48000Hz, blk 1920 bytes (10ms) for playback
audio0: slinear_le:16 2ch 48000Hz, blk 1920 bytes (10ms) for recording
spkr0 at audio0: PC Speaker (synthesized)
wsbell at spkr0 not configured
hdafg1 at hdaudio0: vendor 8086 product 280b
hdafg1: DP00 8ch: Digital Out [Jack]
hdafg1: 8ch/0ch 48000Hz PCM16*

The kernel configs are identical; I diffed config -x /netbsd output
between the two machines and the only difference, besides comments, is
that the properly working one (not the misbehaving one - I checked) has
a dead-man driver I wrote in the kernel, but it's not getting used.
(The plan was for the kernel to reboot itself in case userland wedges,
but it's not in use here.  Also, the audio worked fine before I wrote
that driver.)

All machines involved are amd64.

Anyone have any ideas what could be behind this?  Or further things I
could try?  More information I could usefully supply?

/~\ The ASCII				  Mouse
\ / Ribbon Campaign
 X  Against HTML		mouse%rodents-montreal.org@localhost
/ \ Email!	     7D C8 61 52 5D E7 2D 39  4E F1 31 3E E8 B3 27 4B