NetBSD Problem Report #51710

From martin@aprisoft.de  Mon Dec 12 09:45:41 2016
Return-Path: <martin@aprisoft.de>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client CN "mail.netbsd.org", Issuer "Postmaster NetBSD.org" (verified OK))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 0E8FE7A368
	for <gnats-bugs@gnats.NetBSD.org>; Mon, 12 Dec 2016 09:45:41 +0000 (UTC)
Message-Id: <20161212094531.B43E65CC761@emmas.aprisoft.de>
Date: Mon, 12 Dec 2016 10:45:31 +0100 (CET)
From: martin@NetBSD.org
Reply-To: martin@NetBSD.org
To: gnats-bugs@NetBSD.org
Subject: audio playback works only once
X-Send-Pr-Version: 3.95

>Number:         51710
>Category:       kern
>Synopsis:       audio playback works only once
>Confidential:   no
>Severity:       critical
>Priority:       high
>Responsible:    nat
>State:          closed
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Dec 12 09:50:00 +0000 2016
>Closed-Date:    Sat Dec 24 12:26:05 +0000 2016
>Last-Modified:  Sat Dec 24 12:26:05 +0000 2016
>Originator:     Martin Husemann
>Release:        NetBSD 7.99.46
>Organization:
The NetBSD Foundation, Inc.
>Environment:
System: NetBSD whoever-brings-the-night.aprisoft.de 7.99.46 NetBSD 7.99.46 (WHOEVER) #42: Mon Dec 12 09:03:59 CET 2016 martin@martins.aprisoft.de:/ssd/src/sys/arch/sparc64/compile/WHOEVER sparc64
Architecture: sparc64
Machine: sparc64
>Description:

Audio playback worked once, but further tries do not render any sound.
audioctl hangs when exiting:

 PID TTY    STAT    TIME COMMAND
 724 pts/1- DE   0:00.00 (audioctl)

Will reproduce with a AUDIO_DEBUG kernel later, can't reboot right now.

I also notice that the audio related sysctl variables are not present
any more (but this may be completely unrelated).

Relevant dmesg part:

autri0 at pci2 dev 8 function 0: Acer Labs M5451 AC-Link Controller Audio Device (rev. 0x02)
autri0: interrupting at ivec 7a4
autri0: ac97: Analog Devices AD1881A codec; headphone, Analog Devices Phat Stereo
audio0 at autri0: full duplex, playback, capture, mmap, independent
midi0 at autri0: 4DWAVE MIDI UART


>How-To-Repeat:

Use mpg123 several times on this machine. Notice it only works once.

>Fix:
n/a

>Release-Note:

>Audit-Trail:
From: Martin Husemann <martin@duskware.de>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/51710: audio playback works only once
Date: Mon, 12 Dec 2016 13:13:20 +0100

 Here is dmesg with a audio debug kernel:

 autri0 at pci2 dev 8 function 0: Acer Labs M5451 AC-Link Controller Audio Device (rev. 0x02)
 autri0: interrupting at ivec 7a4
 autri0: ac97: Analog Devices AD1881A codec; headphone, Analog Devices Phat Stereo
 audioprobe: type=0 sa=0x2004fa8 hw=0x178c488
 audio0 at autri0: full duplex, playback, capture, mmap, independent
 audiosetinfo sc=0x108fc4000 ai=0x2004890
 audiosetinfo() Setting record params: enc=7 2ch 16/16bit 44100Hz
 audiosetinfo() Setting play params: enc=7 2ch 16/16bit 44100Hz
 audio_setup_pfilters: HW-buffer=0x108f04ac8 pustream=0x108f04848
 [0] enc=7 2ch 16/16bit 44100Hz
 [HW] enc=6 2ch 16/16bit 44100Hz
 audio_setup_rfilters: HW-buffer=0x108f04b68 pustream=0x108f04c38
 [HW] enc=6 2ch 16/16bit 44100Hz
 [0] enc=7 2ch 16/16bit 44100Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56720
 audiostartp: start=0x25f9d2000 used=0(hi=65536 blk=8816) mmapped=0
 audiostartp: wakeup and return
 audiosetinfo sc=0x108fc4000 ai=0x2004890
 audiosetinfo() Setting record params: enc=7 2ch 16/16bit 44100Hz
 audiosetinfo() Setting play params: enc=7 2ch 16/16bit 44100Hz
 audio_setup_pfilters: HW-buffer=0x108f04ac8 pustream=0x108f04848
 [0] enc=7 2ch 16/16bit 44100Hz
 [HW] enc=6 2ch 16/16bit 44100Hz
 audio_setup_rfilters: HW-buffer=0x108f04b68 pustream=0x108f04c38
 [HW] enc=6 2ch 16/16bit 44100Hz
 [0] enc=7 2ch 16/16bit 44100Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audiostartp: start=0x25f9d2000 used=0(hi=65536 blk=8816) mmapped=0
 audiostartp: wakeup and return
 audio_attach: inputs ports=0x7, input master=29, output ports=0x0, output master=3
 audioprobe: type=1 sa=0x2004fa8 hw=0x178c458


 When in bad state, a new try to play audio from userland looks like
 this:

 audio_open: flags=0x2 sc=0x108fc4000 hdl=0x107697b08
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audiosetinfo sc=0x108fc4000 ai=0x2606b7460
 audiosetinfo() Setting record params: enc=1 1ch 8/8bit 8000Hz
 audiosetinfo() Setting play params: enc=1 1ch 8/8bit 8000Hz
 audio_setup_pfilters: HW-buffer=0x1093452c8 pustream=0x109345048
 [0] enc=1 1ch 8/8bit 8000Hz
 [1] enc=7 1ch 16/16bit 8000Hz
 [HW] enc=7 2ch 16/16bit 44100Hz
 audio_setup_rfilters: HW-buffer=0x109345368 pustream=0x109345480
 [HW] enc=7 2ch 16/16bit 44100Hz
 [0] enc=7 1ch 16/16bit 8000Hz
 [1] enc=1 1ch 8/8bit 8000Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56716
 audiostartp: start=0x10b182000 used=0(hi=65536 blk=8816) mmapped=0
 audiostartp: wakeup and return
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56720
 audio_open: done sc_mode = 0x5
 audio_ioctl(136,'A',22)
 AUDIO_SETINFO mode=0x5
 audiosetinfo sc=0x108fc4000 ai=0x10b071f68
 audiosetinfo() Setting play params: enc=3 1ch 16/16bit 8000Hz
 audio_setup_pfilters: HW-buffer=0x1093452c8 pustream=0x109345048
 [0] enc=7 1ch 16/16bit 8000Hz
 [HW] enc=7 2ch 16/16bit 44100Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56716
 audio_ioctl(136,'A',22) result 0
 audio_ioctl(136,'A',22)
 AUDIO_SETINFO mode=0x5
 audiosetinfo sc=0x108fc4000 ai=0x10b071f68
 audio_ioctl(136,'A',22) result 0
 audio_close: sc=0x108fc4000
 audio_drain: enter busy=0
 audio_drain: n=0, used=0, drops=0

 ... here userland hangs

 and when I ^C the mpg123 process, it continues:

 mix_write: call trigger_output


 I have placed full (lenghty) audio debug output at
 	http://www.netbsd.org/~martin/audio.log


 Martin

From: Martin Husemann <martin@duskware.de>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/51710: audio playback works only once
Date: Mon, 12 Dec 2016 13:19:11 +0100

 On Mon, Dec 12, 2016 at 12:15:01PM +0000, Martin Husemann wrote:
 >  audio_setup_pfilters: HW-buffer=0x1093452c8 pustream=0x109345048
 >  [0] enc=1 1ch 8/8bit 8000Hz
 >  [1] enc=7 1ch 16/16bit 8000Hz
 >  [HW] enc=7 2ch 16/16bit 44100Hz

 Side note: this makes me a bit nervous. The [0] channel is the keyboard
 bell (I guess) that I should remove completely from this kernel.

 But [1] is obviously not what I would like mpg123 to use when playing
 music...

 Martin

From: Martin Husemann <martin@duskware.de>
To: gnats-bugs@NetBSD.org
Cc: 
Subject: Re: kern/51710: audio playback works only once
Date: Tue, 20 Dec 2016 15:00:33 +0100

 I added a bit more debug output and got a backtrace from the failing
 cv_wait_sig() call:

 AUDIO_DEBUG log from starting the second playback:

 audio_open: flags=0x2 sc=0x108f44000 hdl=0x107697b08
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audiosetinfo sc=0x108f44000 ai=0x2607f7460
 audiosetinfo() Setting record params: enc=1 1ch 8/8bit 8000Hz
 audiosetinfo() Setting play params: enc=1 1ch 8/8bit 8000Hz
 audio_setup_pfilters: HW-buffer=0x1093f92c8 pustream=0x1093f9048
 [0] enc=1 1ch 8/8bit 8000Hz
 [1] enc=7 1ch 16/16bit 8000Hz
 [HW] enc=7 2ch 16/16bit 44100Hz
 audio_setup_rfilters: HW-buffer=0x1093f9368 pustream=0x1093f9480
 [HW] enc=7 2ch 16/16bit 44100Hz
 [0] enc=7 1ch 16/16bit 8000Hz
 [1] enc=1 1ch 8/8bit 8000Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56716
 audiostartp: start=0x10a8a2000 used=0(hi=65536 blk=8816) mmapped=0
 audiostartp: wakeup and return
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56720
 audio_open: done sc_mode = 0x5
 audio_ioctl(136,'A',22)
 AUDIO_SETINFO mode=0x5
 audiosetinfo sc=0x108f44000 ai=0x10a7f9e28
 audiosetinfo() Setting play params: enc=3 1ch 16/16bit 8000Hz
 audio_setup_pfilters: HW-buffer=0x1093f92c8 pustream=0x1093f9048
 [0] enc=7 1ch 16/16bit 8000Hz
 [HW] enc=7 2ch 16/16bit 44100Hz
 audiosetinfo: filter setup is completed.
 audio_calc_blksize: record blksize=8820
 audio_calc_blksize: play blksize=8820
 audio_initbufs: mode=0x5
 audio_init_ringbuffer: MI blksize=8816
 audio_init_ringbuffer: final blksize=8816
 audio_calcwater: plow=49152 phigh=65536 rlow=0 rhigh=56716
 audio_ioctl(136,'A',22) result 0
 audio_ioctl(136,'A',22)
 AUDIO_SETINFO mode=0x5
 audiosetinfo sc=0x108f44000 ai=0x10a7f9e28
 audio_ioctl(136,'A',22) result 0
 audio_close: sc=0x108f44000
 audio_drain: enter busy=0
 audio_drain: n=0, used=0, drops=0
 audio_waitio: cv_wait_sig for condvar 0x108f5c0e0 with mutex 0x107697b10
 audio_waitio: cv_wait_sig for condvar 0x108f5c0e0 with mutex 0x107697b10 returned -3

 The call stack at this point is:

 audio_waitio+0xfc
 audio_drain+0x170
 audio_close+0x31c
 audioclose+0xec
 spec_close+0x1bc
 ufsspec_close+0x50
 VOP_CLOSE+0x30
 vn_close+0x84
 closef+0x5c
 sys_close+0x14
 syscall+0x4f4


 It seems that it is waiting for output to drain but that never happens.
 Maybe a driver specific bug? Any hints?

 Martin

Responsible-Changed-From-To: kern-bug-people->nat
Responsible-Changed-By: nat@NetBSD.org
Responsible-Changed-When: Fri, 23 Dec 2016 21:03:45 +0000
Responsible-Changed-Why:
I'll take this.


State-Changed-From-To: open->feedback
State-Changed-By: nat@NetBSD.org
State-Changed-When: Fri, 23 Dec 2016 21:03:45 +0000
State-Changed-Why:
Changes have been committed.


From: "Nathanial Sloss" <nat@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/51710 CVS commit: src/sys/dev
Date: Fri, 23 Dec 2016 21:01:00 +0000

 Module Name:	src
 Committed By:	nat
 Date:		Fri Dec 23 21:01:00 UTC 2016

 Modified Files:
 	src/sys/dev: audio.c

 Log Message:
 Simplify.  Handle draining of vc[0] differently.

 Addresses PR kern/51710 audio playback works only once.


 To generate a diff of this commit:
 cvs rdiff -u -r1.285 -r1.286 src/sys/dev/audio.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

State-Changed-From-To: feedback->closed
State-Changed-By: martin@NetBSD.org
State-Changed-When: Sat, 24 Dec 2016 12:26:05 +0000
State-Changed-Why:
Fixed, thanks!


>Unformatted:

Home	PR Database Search