snd_pcm_close hangs

snd_pcm_close hangs

[Tim Goetze]

hi all,

both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
closing a playback stream if the stream has been linked to the 
same card's capture, has been prepared and written data to, but was
never started:

Program received signal SIGINT, Interrupt.
0x403b8fa4 in ioctl () from /lib/libc.so.6
(gdb) bt
#0  0x403b8fa4 in ioctl () from /lib/libc.so.6
#1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
#2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
#3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
#4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
__in_chrg=0)
    at AlsaStream.cc:41
#5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
    at PyType.h:110
...

this is a minor bug i guess, but it can be annoying. 

cvs is current, access is MMAP_INTERLEAVED. do you need more info?

tim



_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

cvs not compiling cleanly

[Fernando Pablo Lopez-Lezcano]

Hi, today's cvs, fresh download. Not all modules are compiled
when doing a cvscompile from scratch. Last ones are the usb
modules, the whole pci directory is apparently skipped. The
final depmod also fails (maybe because there are modules
missing?):

/sbin/depmod -a -e -b /var/tmp/alsa-driver-root/  2.4.18-8.llsmp
depmod: *** Unresolved symbols in  
/var/tmp/alsa-driver-root//lib/modules/2.4.18-8.llsmp/kernel/drivers/sound/acore/seq/snd-seq-midi.o
depmod: 	snd_midi_event_reset_decode_Rsmp_89a9caf3
depmod: 	snd_midi_event_new_Rsmp_d1f14cea
depmod: 	snd_midi_event_free_Rsmp_0d42135c
depmod: 	snd_midi_event_decode_Rsmp_b1332d2d
depmod: 	snd_midi_event_encode_Rsmp_06daaf77
depmod: *** Unresolved symbols in  
/var/tmp/alsa-driver-root//lib/modules/2.4.18-8.llsmp/kernel/drivers/sound/acore/seq/snd-seq-virmidi.o
depmod: 	snd_midi_event_new_Rsmp_d1f14cea
depmod: 	snd_midi_event_reset_encode_Rsmp_06e732f9
depmod: 	snd_midi_event_free_Rsmp_0d42135c
depmod: 	snd_midi_event_decode_Rsmp_b1332d2d
depmod: 	snd_midi_event_encode_Rsmp_06daaf77

CVS from 2002-05-15.10:15:43 compiles fine on the same machine.
-- Fernando

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: cvs not compiling cleanly

[Patrick Shirkey]

Fernando Pablo Lopez-Lezcano wrote:
> 
> Hi, today's cvs, fresh download. Not all modules are compiled
> when doing a cvscompile from scratch. Last ones are the usb
> modules, the whole pci directory is apparently skipped. The
> final depmod also fails (maybe because there are modules
> missing?):
> 
> /sbin/depmod -a -e -b /var/tmp/alsa-driver-root/  2.4.18-8.llsmp
> depmod: *** Unresolved symbols in
> /var/tmp/alsa-driver-root//lib/modules/2.4.18-8.llsmp/kernel/drivers/sound/acore/seq/snd-seq-midi.o
> depmod:         snd_midi_event_reset_decode_Rsmp_89a9caf3
> depmod:         snd_midi_event_new_Rsmp_d1f14cea
> depmod:         snd_midi_event_free_Rsmp_0d42135c
> depmod:         snd_midi_event_decode_Rsmp_b1332d2d
> depmod:         snd_midi_event_encode_Rsmp_06daaf77
> depmod: *** Unresolved symbols in
> /var/tmp/alsa-driver-root//lib/modules/2.4.18-8.llsmp/kernel/drivers/sound/acore/seq/snd-seq-virmidi.o
> depmod:         snd_midi_event_new_Rsmp_d1f14cea
> depmod:         snd_midi_event_reset_encode_Rsmp_06e732f9
> depmod:         snd_midi_event_free_Rsmp_0d42135c
> depmod:         snd_midi_event_decode_Rsmp_b1332d2d
> depmod:         snd_midi_event_encode_Rsmp_06daaf77
> 
> CVS from 2002-05-15.10:15:43 compiles fine on the same machine.
> -- Fernando
> 

I get a similar problem with the sequencer support for the cmipci. It
has been like that since Monday AFAICR.


-- 
Patrick Shirkey - Boost Hardware Ltd.
For the discerning hardware connoisseur
Http://www.boosthardware.com
Http://www.boosthardware.com/LAU/guide/
=======================================================================

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: cvs not compiling cleanly

[Takashi Iwai]

At Fri, 31 May 2002 12:27:26 +0900,
Patrick Shirkey wrote:
> 
> Fernando Pablo Lopez-Lezcano wrote:
> > 
> > Hi, today's cvs, fresh download. Not all modules are compiled
> > when doing a cvscompile from scratch. Last ones are the usb
> > modules, the whole pci directory is apparently skipped. The
> > final depmod also fails (maybe because there are modules
> > missing?):
> > 
> > /sbin/depmod -a -e -b /var/tmp/alsa-driver-root/  2.4.18-8.llsmp
> > depmod: *** Unresolved symbols in
...
> > 
> > CVS from 2002-05-15.10:15:43 compiles fine on the same machine.
> > -- Fernando
> > 
> 
> I get a similar problem with the sequencer support for the cmipci. It
> has been like that since Monday AFAICR.

sorry, my mistake.  i hope it's now fixed on cvs.
please give a try.


Takashi

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Takashi Iwai]

At Thu, 30 May 2002 17:14:03 +0200 (CEST),
Tim Goetze wrote:
> 
> hi all,
> 
> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
> closing a playback stream if the stream has been linked to the 
> same card's capture, has been prepared and written data to, but was
> never started:
> 
> Program received signal SIGINT, Interrupt.
> 0x403b8fa4 in ioctl () from /lib/libc.so.6
> (gdb) bt
> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
> __in_chrg=0)
>     at AlsaStream.cc:41
> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>     at PyType.h:110

it seems stalling at drain ioctl.  can you figure out which stream is?


Takashi

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

Takashi Iwai wrote:

>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
>Tim Goetze wrote:
>> 
>> hi all,
>> 
>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
>> closing a playback stream if the stream has been linked to the 
>> same card's capture, has been prepared and written data to, but was
>> never started:
>> 
>> Program received signal SIGINT, Interrupt.
>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
>> (gdb) bt
>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
>> __in_chrg=0)
>>     at AlsaStream.cc:41
>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>>     at PyType.h:110
>
>it seems stalling at drain ioctl.  can you figure out which stream is?

playback. 

btw: snd_pcm_close never calls *_drain on a capture stream if my
interpretation of its code is right, and i said 'playback' and
'written .. to' in the original mail. 

tim


_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 2620 bytes --]

me wrote:

>Takashi Iwai wrote:
>
>>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
>>Tim Goetze wrote:
>>> 
>>> hi all,
>>> 
>>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
>>> closing a playback stream if the stream has been linked to the 
>>> same card's capture, has been prepared and written data to, but was
>>> never started:
>>> 
>>> Program received signal SIGINT, Interrupt.
>>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
>>> (gdb) bt
>>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
>>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
>>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
>>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
>>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
>>> __in_chrg=0)
>>>     at AlsaStream.cc:41
>>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>>>     at PyType.h:110
>>
>>it seems stalling at drain ioctl.  can you figure out which stream is?
>
>playback. 

a playback stream not linked to any other stream behaves the same.

before calling snd_pcm_close(), i get

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: PREPARED
trigger_time: 0.000000
tstamp      : 1022886544.305384
delay       : -1053620964
avail       : 0
avail_max   : 0

this is what happens in snd_pcm_playback_drain() when i call
snd_pcm_close() now:

the stream is started ok. the stream state is then switched to
SNDRV_PCM_STATE_DRAINING and then the interruptible loop waiting for
the stream to go to a different state is running forever because
stream->state remains 5 = SNDRV_PCM_STATE_DRAINING. 

at this point, i get

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: <NULL>
trigger_time: 1022886587.196499
tstamp      : 1022886605.224624
delay       : -790953
avail       : 795049
avail_max   : 795049

and a little later

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: <NULL>
trigger_time: 1022886587.196499
tstamp      : 1022886607.877699
delay       : -907955
avail       : 912051
avail_max   : 912051

and so on, so the card is firing irqs (a fact cat /proc/interrupts
confirms). 

if i haven't run my code under gdb i then need to reboot the box to
work with the card because the module is claimed 'busy'.

tim

ps: i think "state: <NULL>" in the output from /proc above suggests
that "char * snd_pcm_state_names[]" (in kernel/pcm.c:139) needs a
revision. a patch is attached.
 
pps: please, please, please somebody of you authors of alsa-driver/*,
do add some comments around the code. i have absolutely no clue why
a stream that is about to be closed needs draining in the first place.

[-- Attachment #2: Type: TEXT/plain, Size: 508 bytes --]

Index: alsa-driver/kernel/pcm.c
===================================================================
RCS file: /cvsroot/alsa/alsa-driver/kernel/Attic/pcm.c,v
retrieving revision 1.120
diff -u -r1.120 pcm.c
--- alsa-driver/kernel/pcm.c	12 Oct 2001 10:43:18 -0000	1.120
+++ alsa-driver/kernel/pcm.c	31 May 2002 23:45:54 -0000
@@ -141,7 +141,9 @@
 	STATE(PREPARED),
 	STATE(RUNNING),
 	STATE(XRUN),
+	STATE(DRAINING),
 	STATE(PAUSED),
+	STATE(SUSPENDED),
 };
 
 char *snd_pcm_access_names[] = {

Re: snd_pcm_close hangs

[Tim Goetze]

me wrote:

>me wrote:
>
>>Takashi Iwai wrote:
>>
>>>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
>>>Tim Goetze wrote:
>>>> 
>>>> hi all,
>>>> 
>>>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
>>>> closing a playback stream if the stream has been linked to the 
>>>> same card's capture, has been prepared and written data to, but was
>>>> never started:
>>>> 
>>>> Program received signal SIGINT, Interrupt.
>>>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
>>>> (gdb) bt
>>>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
>>>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
>>>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
>>>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
>>>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
>>>> __in_chrg=0)
>>>>     at AlsaStream.cc:41
>>>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>>>>     at PyType.h:110
>>>
>>>it seems stalling at drain ioctl.  can you figure out which stream is?
>>
>>playback. 
>
>a playback stream not linked to any other stream behaves the same.
>
>before calling snd_pcm_close(), i get
>
>[~] cat /proc/asound/ice/pcm0p/sub0/status 
>state: PREPARED
>trigger_time: 0.000000
>tstamp      : 1022886544.305384
>delay       : -1053620964
>avail       : 0
>avail_max   : 0
>
>this is what happens in snd_pcm_playback_drain() when i call
>snd_pcm_close() now:
>
>the stream is started ok. the stream state is then switched to
>SNDRV_PCM_STATE_DRAINING and then the interruptible loop waiting for
>the stream to go to a different state is running forever because
>stream->state remains 5 = SNDRV_PCM_STATE_DRAINING. 

since state never changes, i checked what happens when the card is
firing an interrupt. following the code path, i think the only point
the state can be changed is in snd_pcm_update_hw_ptr_interrupt()
where 'avail' is checked against 'runtime->stop_threshold'. if this
value is the same as stop_threshold in 

[~] cat /proc/asound/ice/pcm0p/sub0/sw_params 
tstamp_mode: NONE
period_step: 1
sleep_min: 0
avail_min: 2048
xfer_align: 2048
start_threshold: 4294967295
stop_threshold: 4294967295
silence_threshold: 0
silence_size: 0
boundary: 1073741824

then it will take quite some time to reach (not forever though).

i modified my code to set stop_threshold to exactly ring buffer size,
and a playback stream alone closes on the ice within short time. on
the awe (at 128 frames) snd_pcm_close() hangs for a few seconds and
then i get: 

pcm.c:656: snd_pcm_hw_free: Assertion `snd_pcm_state(pcm) ==
SND_PCM_STATE_SETUP || snd_pcm_state(pcm) == SND_PCM_STATE_PREPARED'
failed.

and

[~] cat /proc/asound/awe64/pcm0p/sub0/status    
state: DRAINING
trigger_time: 1022892601.216727
tstamp      : 1022892616.804303
delay       : -687208
avail       : 687464
avail_max   : 687464

i modified my code to again use capture and playback in a linked setup
with the new stop_threshold, and now i get the same assertion failure
on both cards, plus:

Jun  1 02:20:31 localhost kernel: ALSA pcm_native.c:654: snd_pcm_stop
bogus call from c88e9239?
Jun  1 02:21:02 localhost last message repeated 10529 times

etc etc, on both cards.

giving up. i hope i've gathered enough clues, and expressed them
clearly enough, for somebody with more insight to fix this. en tout
cas, the bug(s) can be easily reproduced and most probably isn't
limited to the specific cards here.

tim




_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

me wrote:

>me wrote:
>
>>me wrote:
>>
>>>Takashi Iwai wrote:
>>>
>>>>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
>>>>Tim Goetze wrote:
>>>>> 
>>>>> hi all,
>>>>> 
>>>>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
>>>>> closing a playback stream if the stream has been linked to the 
>>>>> same card's capture, has been prepared and written data to, but was
>>>>> never started:
>>>>> 
>>>>> Program received signal SIGINT, Interrupt.
>>>>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
>>>>> (gdb) bt
>>>>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
>>>>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
>>>>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
>>>>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
>>>>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
>>>>> __in_chrg=0)
>>>>>     at AlsaStream.cc:41
>>>>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>>>>>     at PyType.h:110
>>>>
>>>>it seems stalling at drain ioctl.  can you figure out which stream is?
>>>
>>>playback. 
>>
>>a playback stream not linked to any other stream behaves the same.
>>
>>before calling snd_pcm_close(), i get
>>
>>[~] cat /proc/asound/ice/pcm0p/sub0/status 
>>state: PREPARED
>>trigger_time: 0.000000
>>tstamp      : 1022886544.305384
>>delay       : -1053620964
>>avail       : 0
>>avail_max   : 0
>>
>>this is what happens in snd_pcm_playback_drain() when i call
>>snd_pcm_close() now:
>>
>>the stream is started ok. the stream state is then switched to
>>SNDRV_PCM_STATE_DRAINING and then the interruptible loop waiting for
>>the stream to go to a different state is running forever because
>>stream->state remains 5 = SNDRV_PCM_STATE_DRAINING. 
>
>since state never changes, i checked what happens when the card is
>firing an interrupt. following the code path, i think the only point
>the state can be changed is in snd_pcm_update_hw_ptr_interrupt()
>where 'avail' is checked against 'runtime->stop_threshold'. if this
>value is the same as stop_threshold in 
>
>[~] cat /proc/asound/ice/pcm0p/sub0/sw_params 
>tstamp_mode: NONE
>period_step: 1
>sleep_min: 0
>avail_min: 2048
>xfer_align: 2048
>start_threshold: 4294967295
>stop_threshold: 4294967295
>silence_threshold: 0
>silence_size: 0
>boundary: 1073741824
>
>then it will take quite some time to reach (not forever though).
>
>i modified my code to set stop_threshold to exactly ring buffer size,
>and a playback stream alone closes on the ice within short time. on
>the awe (at 128 frames) snd_pcm_close() hangs for a few seconds and
>then i get: 
>
>pcm.c:656: snd_pcm_hw_free: Assertion `snd_pcm_state(pcm) ==
>SND_PCM_STATE_SETUP || snd_pcm_state(pcm) == SND_PCM_STATE_PREPARED'
>failed.
>
>and
>
>[~] cat /proc/asound/awe64/pcm0p/sub0/status    
>state: DRAINING
>trigger_time: 1022892601.216727
>tstamp      : 1022892616.804303
>delay       : -687208
>avail       : 687464
>avail_max   : 687464
>
>i modified my code to again use capture and playback in a linked setup
>with the new stop_threshold, and now i get the same assertion failure
>on both cards, plus:
>
>Jun  1 02:20:31 localhost kernel: ALSA pcm_native.c:654: snd_pcm_stop
>bogus call from c88e9239?
>Jun  1 02:21:02 localhost last message repeated 10529 times
>
>etc etc, on both cards.
>
>giving up. i hope i've gathered enough clues, and expressed them
>clearly enough, for somebody with more insight to fix this. en tout
>cas, the bug(s) can be easily reproduced and most probably isn't
>limited to the specific cards here.

here's yet another clue: after running the ice (linked cap +
play) with the new stop_threshold, stopping the streams and then
closing them, my alsa_error_handler says:

pcm_hw.c:282 (snd_pcm_hw_drain): SNDRV_PCM_IOCTL_DRAIN failed, err =
Input/output error (AlsaStream.cc:18)

and, again,

Jun  1 12:49:22 localhost kernel: ALSA pcm_native.c:654: snd_pcm_stop
bogus call from c88e9239?
Jun  1 12:49:53 localhost last message repeated 10676 times

can you enlighten me why it is at all necessary to drain a stream
before closing it?

tim


_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Takashi Iwai]

At Sat, 1 Jun 2002 01:49:00 +0200 (CEST),
Tim Goetze wrote:
> 
> me wrote:
> 
> >Takashi Iwai wrote:
> >
> >>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
> >>Tim Goetze wrote:
> >>> 
> >>> hi all,
> >>> 
> >>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
> >>> closing a playback stream if the stream has been linked to the 
> >>> same card's capture, has been prepared and written data to, but was
> >>> never started:
> >>> 
> >>> Program received signal SIGINT, Interrupt.
> >>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
> >>> (gdb) bt
> >>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
> >>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
> >>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
> >>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
> >>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
> >>> __in_chrg=0)
> >>>     at AlsaStream.cc:41
> >>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
> >>>     at PyType.h:110
> >>
> >>it seems stalling at drain ioctl.  can you figure out which stream is?
> >
> >playback. 
> 
> a playback stream not linked to any other stream behaves the same.
> 
> before calling snd_pcm_close(), i get
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> state: PREPARED
> trigger_time: 0.000000
> tstamp      : 1022886544.305384
> delay       : -1053620964
> avail       : 0
> avail_max   : 0
 
hmm, delay value is bogus, but it's a minor bug of the driver.
should be zero cleared there.

> this is what happens in snd_pcm_playback_drain() when i call
> snd_pcm_close() now:
> 
> the stream is started ok. the stream state is then switched to
> SNDRV_PCM_STATE_DRAINING and then the interruptible loop waiting for
> the stream to go to a different state is running forever because
> stream->state remains 5 = SNDRV_PCM_STATE_DRAINING. 
> 
> at this point, i get
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> state: <NULL>
> trigger_time: 1022886587.196499
> tstamp      : 1022886605.224624
> delay       : -790953
> avail       : 795049
> avail_max   : 795049
 
apparently the avail value is incorrect.
is the buffer_size set to 4096?

> and a little later
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> state: <NULL>
> trigger_time: 1022886587.196499
> tstamp      : 1022886607.877699
> delay       : -907955
> avail       : 912051
> avail_max   : 912051
> 
> and so on, so the card is firing irqs (a fact cat /proc/interrupts
> confirms). 
> 
> if i haven't run my code under gdb i then need to reboot the box to
> work with the card because the module is claimed 'busy'.

hmm, it sounds like a similar problem i fixed once ago...
(although in my case it didn't fire up irqs).


> 
> ps: i think "state: <NULL>" in the output from /proc above suggests
> that "char * snd_pcm_state_names[]" (in kernel/pcm.c:139) needs a
> revision. a patch is attached.

strange, this has to be fixed already.
and the filename in the patch you attached seems invalid.
could you check whether all the sources are updated?
the latest versions are:

	alsa-kernel/core/pcm.c 		rcs rev. 1.12
	alsa-kernel/core/pcm_nativ.c	rcs rev. 1.13
	alsa-kernel/core/pcm_lib.c	rcs rev. 1.12


Takashi

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

Takashi Iwai wrote:

>At Sat, 1 Jun 2002 01:49:00 +0200 (CEST),
>Tim Goetze wrote:
>> 
>> me wrote:
>> 
>> >Takashi Iwai wrote:
>> >
>> >>At Thu, 30 May 2002 17:14:03 +0200 (CEST),
>> >>Tim Goetze wrote:
>> >>> 
>> >>> hi all,
>> >>> 
>> >>> both emu8k and ice1712 pcm drivers hang forever in ioctl(2) when
>> >>> closing a playback stream if the stream has been linked to the 
>> >>> same card's capture, has been prepared and written data to, but was
>> >>> never started:
>> >>> 
>> >>> Program received signal SIGINT, Interrupt.
>> >>> 0x403b8fa4 in ioctl () from /lib/libc.so.6
>> >>> (gdb) bt
>> >>> #0  0x403b8fa4 in ioctl () from /lib/libc.so.6
>> >>> #1  0x40580abc in __DTOR_END__ () from /usr/lib/libasound.so.2
>> >>> #2  0x4053bde9 in snd_pcm_drain (pcm=0x81c6ae8) at pcm.c:813
>> >>> #3  0x4053b649 in snd_pcm_close (pcm=0x81c6ae8) at pcm.c:552
>> >>> #4  0x40462d79 in AlsaStream::~AlsaStream (this=0x81bf6a8,
>> >>> __in_chrg=0)
>> >>>     at AlsaStream.cc:41
>> >>> #5  0x4049ef01 in AlsaOut::~AlsaOut (this=0x81bf6a8, __in_chrg=3)
>> >>>     at PyType.h:110
>> >>
>> >>it seems stalling at drain ioctl.  can you figure out which stream is?
>> >
>> >playback. 
>> 
>> a playback stream not linked to any other stream behaves the same.
>> 
>> before calling snd_pcm_close(), i get
>> 
>> [~] cat /proc/asound/ice/pcm0p/sub0/status 
>> state: PREPARED
>> trigger_time: 0.000000
>> tstamp      : 1022886544.305384
>> delay       : -1053620964
>> avail       : 0
>> avail_max   : 0
> 
>hmm, delay value is bogus, but it's a minor bug of the driver.
>should be zero cleared there.
>
>> this is what happens in snd_pcm_playback_drain() when i call
>> snd_pcm_close() now:
>> 
>> the stream is started ok. the stream state is then switched to
>> SNDRV_PCM_STATE_DRAINING and then the interruptible loop waiting for
>> the stream to go to a different state is running forever because
>> stream->state remains 5 = SNDRV_PCM_STATE_DRAINING. 
>> 
>> at this point, i get
>> 
>> [~] cat /proc/asound/ice/pcm0p/sub0/status 
>> state: <NULL>
>> trigger_time: 1022886587.196499
>> tstamp      : 1022886605.224624
>> delay       : -790953
>> avail       : 795049
>> avail_max   : 795049
> 
>apparently the avail value is incorrect.
>is the buffer_size set to 4096?
>
>> and a little later
>> 
>> [~] cat /proc/asound/ice/pcm0p/sub0/status 
>> state: <NULL>
>> trigger_time: 1022886587.196499
>> tstamp      : 1022886607.877699
>> delay       : -907955
>> avail       : 912051
>> avail_max   : 912051
>> 
>> and so on, so the card is firing irqs (a fact cat /proc/interrupts
>> confirms). 
>> 
>> if i haven't run my code under gdb i then need to reboot the box to
>> work with the card because the module is claimed 'busy'.
>
>hmm, it sounds like a similar problem i fixed once ago...
>(although in my case it didn't fire up irqs).
>
>
>> 
>> ps: i think "state: <NULL>" in the output from /proc above suggests
>> that "char * snd_pcm_state_names[]" (in kernel/pcm.c:139) needs a
>> revision. a patch is attached.
>
>strange, this has to be fixed already.
>and the filename in the patch you attached seems invalid.
>could you check whether all the sources are updated?
>the latest versions are:
>
>	alsa-kernel/core/pcm.c 		rcs rev. 1.12
>	alsa-kernel/core/pcm_nativ.c	rcs rev. 1.13
>	alsa-kernel/core/pcm_lib.c	rcs rev. 1.12

doing a fresh checkout now, stay tuned.

tim


_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

me wrote:

>>strange, this has to be fixed already.
>>and the filename in the patch you attached seems invalid.
>>could you check whether all the sources are updated?
>>the latest versions are:
>>
>>	alsa-kernel/core/pcm.c 		rcs rev. 1.12
>>	alsa-kernel/core/pcm_nativ.c	rcs rev. 1.13
>>	alsa-kernel/core/pcm_lib.c	rcs rev. 1.12
>
>doing a fresh checkout now, stay tuned.

ok. seems my local tree hasn't been following the changes at
kernel inclusion. i'm really sorry.

unfortunately the bug remains, it only manifests differently.

after initializing the ice (cap + play are linked):

[~] cat /proc/asound/ice/pcm0p/sub0/hw_params 
access: MMAP_INTERLEAVED
format: S32_LE
subformat: STD
channels: 10
rate: 44100 (44100/1)
period_size: 128
buffer_size: 256
tick_time: 10000

[~] cat /proc/asound/ice/pcm0p/sub0/sw_params 
tstamp_mode: NONE
period_step: 1
sleep_min: 0
avail_min: 128
xfer_align: 128
start_threshold: 4294967295
stop_threshold: 256
silence_threshold: 0
silence_size: 0
boundary: 1073741824

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: PREPARED
trigger_time: 0.000000
tstamp      : 1023125218.959946
delay       : 36548963
avail       : 0
avail_max   : 0
-----
hw_ptr      : 0
appl_ptr    : 256

calling snd_pcm_close() takes a few seconds during which i see
this:

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: DRAINING
trigger_time: 1023125380.999721
tstamp      : 1023125381.905192
delay       : -39746
avail       : 40002
avail_max   : 40002
-----
hw_ptr      : 40002
appl_ptr    : 256

a little later while still in ioctl() --

[~] cat /proc/asound/ice/pcm0p/sub0/status 
state: DRAINING
trigger_time: 1023125380.999721
tstamp      : 1023125383.741754
delay       : -120739
avail       : 120995
avail_max   : 120995
-----
hw_ptr      : 120995
appl_ptr    : 256

etc etc; then alsa_error_handler reports:

pcm_hw.c:413 (snd_pcm_hw_drain): SNDRV_PCM_IOCTL_DRAIN failed, err =
Input/output error

and printk says:

Jun  3 19:29:51 localhost kernel: ALSA
../alsa-kernel/core/pcm_native.c:1093: playback drain error (DMA or
IRQ trouble?)

and the application then exits normally.

the same setup with stop_threshold = ~0 behaves the same (same printk,
too), only the alsa_error_handler message reads:

pcm_hw.c:276 (snd_pcm_hw_hw_free): SNDRV_PCM_IOCTL_HW_FREE failed, err
= File descriptor in bad state

i did both tests (with the different stop_threshold values) with the
emu8k. it shows exactly the same symptoms: running hw_ptr, delay and
avail, same alsa_error_handler and printk messages.

tim


_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Takashi Iwai]

At Mon, 3 Jun 2002 19:48:56 +0200 (CEST),
Tim Goetze wrote:
> 
> unfortunately the bug remains, it only manifests differently.
> 
> after initializing the ice (cap + play are linked):
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/hw_params 
> access: MMAP_INTERLEAVED
> format: S32_LE
> subformat: STD
> channels: 10
> rate: 44100 (44100/1)
> period_size: 128
> buffer_size: 256
> tick_time: 10000
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/sw_params 
> tstamp_mode: NONE
> period_step: 1
> sleep_min: 0
> avail_min: 128
> xfer_align: 128
> start_threshold: 4294967295
> stop_threshold: 256
> silence_threshold: 0
> silence_size: 0
> boundary: 1073741824
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> state: PREPARED
> trigger_time: 0.000000
> tstamp      : 1023125218.959946
> delay       : 36548963
> avail       : 0
> avail_max   : 0
> -----
> hw_ptr      : 0
> appl_ptr    : 256
 
so far, so good..

> calling snd_pcm_close() takes a few seconds during which i see
> this:
> 
> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> state: DRAINING
> trigger_time: 1023125380.999721
> tstamp      : 1023125381.905192
> delay       : -39746
> avail       : 40002
> avail_max   : 40002
> -----
> hw_ptr      : 40002
> appl_ptr    : 256

the minus delay value is definitely wrong.
something weird goes there...
could you check sw_params during this happens?

 
Takashi

ps.  i'll be at linuxtag, so the next answer will be delayed to the
next week.

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas -- http://devcon.sprintpcs.com/adp/index.cfm

Re: snd_pcm_close hangs

[Tim Goetze]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 1173 bytes --]

Takashi Iwai wrote:

[...]
 
>so far, so good..
>
>> calling snd_pcm_close() takes a few seconds during which i see
>> this:
>> 
>> [~] cat /proc/asound/ice/pcm0p/sub0/status 
>> state: DRAINING
>> trigger_time: 1023125380.999721
>> tstamp      : 1023125381.905192
>> delay       : -39746
>> avail       : 40002
>> avail_max   : 40002
>> -----
>> hw_ptr      : 40002
>> appl_ptr    : 256
>
>the minus delay value is definitely wrong.
>something weird goes there...
>could you check sw_params during this happens?

yes i could, but i won't if you don't insist (they don't change anyway
iirc). instead i have done some more investigations:

remember capture + play are linked, and audio data has been written. 
now draining the playback stream *always* fails in the way already
described.

consequences: if you close capture first and then playback, things
work ok. if you unlink the streams before closing them, things work
ok, and the order of closing does not matter.

i have attached testing boilerplate code that you can use to 
reproduce the error.

tim

ps: now asking for the third time, why is it necessary to 'drain' a
playback stream if it is about to be closed? 

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: TEXT/x-csrc; name="main.c", Size: 7685 bytes --]

/*
	 ALSA stream boilerplate, tabsize is 2.
	 
	 (c) 2002 Tim Goetze <tim@quitte.de>

	 This program is free software; you can redistribute it and/or
	 modify it under the terms of the GNU General Public License
	 as published by the Free Software Foundation; either version 2
	 of the License, or (at your option) any later version.

	 This program is distributed in the hope that it will be useful,
	 but WITHOUT ANY WARRANTY; without even the implied warranty of
	 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
	 GNU General Public License for more details.

	 You should have received a copy of the GNU General Public License
	 along with this program; if not, write to the Free Software
	 Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA
	 02111-1307, USA or point your web browser to http://www.gnu.org.
*/

#include <unistd.h>
#include <stdio.h>
#include <errno.h>
#include <string.h>

#include <alsa/asoundlib.h>

#define abs(x) ((x) < 0 ? -(x) : (x))

void
throw (int err, char * s)
{
	if (err)
		fprintf (stderr, "%s: %s\n", s, strerror (abs (err)));
	else
		fprintf (stderr, "%s\n", s);
	exit (1);
}

#define DO(what,ifnot) \
	{ \
		int error = what; \
		if (error < 0) throw (error, ifnot); \
	}

typedef struct
{
	snd_pcm_t * handle;
	
	snd_pcm_hw_params_t * hw_params;
	snd_pcm_sw_params_t * sw_params;

	int bytes_per_sample, channels;
} AudioStream;	
	
void
AudioStream_construct (AudioStream * s)
{
	int error;
	
	s->handle = 0;
	s->hw_params = 0;
	s->sw_params = 0;

	DO (snd_pcm_hw_params_malloc (&s->hw_params), "hw_params_malloc fails")
	DO (snd_pcm_sw_params_malloc (&s->sw_params), "sw_params_malloc fails")
}

void
AudioStream_destruct (AudioStream * s)
{
	if (s->handle)
		DO (snd_pcm_close (s->handle), "pcm_close fails");
	
	if (s->hw_params)
		snd_pcm_hw_params_free (s->hw_params);
	if (s->sw_params)
		snd_pcm_sw_params_free (s->sw_params);
}

void
AudioStream_open (AudioStream *s, char * name, int type)
{
	DO (snd_pcm_open (&s->handle, name, type, 0), "pcm_open fails")
}

void
AudioStream_prepare (AudioStream *s)
{
	DO (snd_pcm_prepare (s->handle), "pcm_open fails")
}

void
AudioStream_link (AudioStream *s, AudioStream *t)
{
	DO (snd_pcm_link (s->handle, t->handle), "pcm_link fails")
}

void
AudioStream_unlink (AudioStream *s)
{
	DO (snd_pcm_unlink (s->handle), "pcm_unlink fails")
}

void
AudioStream_drain (AudioStream *s)
{
	DO (snd_pcm_drain (s->handle), "pcm_drain fails")
}

void
AudioStream_configure (AudioStream * s, uint sample_rate, uint frames_per_cycle)
{
	int i;
	int error;
	int interleaved;
	int bytes_per_sample;
	int channels;

	snd_pcm_format_t formats [3] = {
		SND_PCM_FORMAT_S32,
		SND_PCM_FORMAT_S16,
		SND_PCM_FORMAT_S8
	};

	DO (snd_pcm_hw_params_any (s->handle, s->hw_params), 
		"no 'any' configuration to start with.");

	DO (snd_pcm_hw_params_set_periods_integer (s->handle, s->hw_params),
		"no integer period size.");
	
	error = snd_pcm_hw_params_set_access 
			(s->handle, s->hw_params, SND_PCM_ACCESS_MMAP_NONINTERLEAVED);
			
	if (error == 0)
		interleaved = 0;
	else
	{
		DO (snd_pcm_hw_params_set_access 
				(s->handle, s->hw_params, SND_PCM_ACCESS_MMAP_INTERLEAVED),
				"memory-mapped access method refused.");
		interleaved = 1;
	}

	/* determine sample format */
	bytes_per_sample = ~0;
	for (i = 0; i < 3; i++)
	{
		error = snd_pcm_hw_params_set_format (s->handle, s->hw_params, formats[i]);
		if (error == 0)
		{
			s->bytes_per_sample =
			bytes_per_sample = 4 >> i;
			break;
		}
	}
			
	if (bytes_per_sample > 4)
		throw (0, "none of (32, 16, 8) bit sample sizes available.");

	DO (snd_pcm_hw_params_set_rate (s->handle, s->hw_params, sample_rate, 0),
		"unsupported sample rate.");

	s->channels =
	channels = snd_pcm_hw_params_get_channels_max (s->hw_params);

	DO (snd_pcm_hw_params_set_channels (s->handle, s->hw_params, channels),
			"no channels available.");

	DO (snd_pcm_hw_params_set_period_size 
		(s->handle, s->hw_params, (uint) frames_per_cycle, 0),
		"hardware refuses this frames_per_cycle setting.");

	DO (snd_pcm_hw_params_set_periods
		(s->handle, s->hw_params, 2, 0),
		"hardware refuses 2 cycles per buffer.");

	DO (snd_pcm_hw_params_set_buffer_size 
		(s->handle, s->hw_params, 2 * frames_per_cycle),
		"hardware refuses a buffer size of 2 * frames_per_cycle.");

	DO (snd_pcm_hw_params (s->handle, s->hw_params),
		"hardware setup failed.");

	/* sw params */
	snd_pcm_sw_params_current (s->handle, s->sw_params);
	
	DO (snd_pcm_sw_params_set_start_threshold (s->handle, s->sw_params, ~0u),
		"cannot turn off start threshold.");
		
	DO (snd_pcm_sw_params_set_stop_threshold (s->handle, s->sw_params, ~0u),
		"cannot turn off stop threshold.");

	DO (snd_pcm_sw_params_set_silence_threshold (s->handle, s->sw_params, 0),
		"cannot set 0 silence threshold.");

	DO (snd_pcm_sw_params_set_silence_size (s->handle, s->sw_params, 0),
		"cannot set 0 silence size.");

	DO (snd_pcm_sw_params_set_avail_min (s->handle, s->sw_params, frames_per_cycle),
		"software setup for minimum available frames failed.");

	DO (snd_pcm_sw_params (s->handle, s->sw_params),
		"software setup failed.");

	fprintf (stderr, "configured for %d %dbit %d %s.\n",
			sample_rate, 8 * bytes_per_sample, frames_per_cycle,
			interleaved ? "interleaved" : "linear");
}

void
AudioStream_fill (AudioStream * s, uint nframes)
{
	const snd_pcm_channel_area_t * areas;
	snd_pcm_uframes_t offset, frames;
	int i;

	while (nframes)
	{
		frames = nframes;

		DO (snd_pcm_mmap_begin (s->handle, &areas, &offset, &frames),
				"pcm_mmap_begin fails");

		/* drain makes the contents of the ringbuffer audible, so we need some
		 * silence here. this quick hack is probably the most efficient sample 
		 * loop you'll ever see. ;) 
		 */
		for (i = 0; i < s->channels; ++i)
		{
			char * ptr = (char *) areas[i].addr + 
					((areas[i].first + areas[i].step * offset) >> 3);
			int n = frames;

			while (n--)
			{
				memset (ptr, 0, s->bytes_per_sample);
				ptr += areas[i].step >> 3;
			}
		}

		DO (snd_pcm_mmap_commit (s->handle, offset, frames),
				"pcm_mmap_commit fails");
		
		nframes -= frames;

		printf ("%u frames commited.\n", frames);
	}
}

int 
main (int argc, char ** argv)
{
	AudioStream capture, playback;

	/* frames / cycle, aka period_size */
	int fpc = 2048;

	if (argc != 2)
		throw (0, "give me an <alsa-pcm-device-name>.");
	
	AudioStream_construct (&capture);
	AudioStream_construct (&playback);

	AudioStream_open (&capture, argv[1], SND_PCM_STREAM_CAPTURE);
	AudioStream_open (&playback, argv[1], SND_PCM_STREAM_PLAYBACK);

	AudioStream_configure (&capture, 44100, fpc);
	AudioStream_configure (&playback, 44100, fpc);

	AudioStream_link (&capture, &playback);

	AudioStream_prepare (&playback);
	AudioStream_fill (&playback, 2 * fpc);

	printf ("hit enter to close.\n");
	fflush (stdout);
	fgetc (stdin);

	/* draining playback now makes the bug manifest. */
	#if 0
	printf ("draining.\n");
	fflush (stdout);
	AudioStream_drain (&playback);
	#endif

	/* unlinking the streams makes the bug not manifest. */
	#if 0
	printf ("unlink.\n");
	fflush (stdout);
	AudioStream_unlink (&playback);
	#endif
	
	/* reordering these two calls makes the bug not manifest because the
	 * capture stream isn't linked to playback anymore.
	 */
	printf ("closing.\n");
	fflush (stdout);
	AudioStream_destruct (&playback);
	AudioStream_destruct (&capture);

	return 0;
}

Re: snd_pcm_close hangs

[Takashi Iwai]

At Tue, 4 Jun 2002 23:10:20 +0200 (CEST),
Tim Goetze wrote:
> 
> Takashi Iwai wrote:
> 
> [...]
>  
> >so far, so good..
> >
> >> calling snd_pcm_close() takes a few seconds during which i see
> >> this:
> >> 
> >> [~] cat /proc/asound/ice/pcm0p/sub0/status 
> >> state: DRAINING
> >> trigger_time: 1023125380.999721
> >> tstamp      : 1023125381.905192
> >> delay       : -39746
> >> avail       : 40002
> >> avail_max   : 40002
> >> -----
> >> hw_ptr      : 40002
> >> appl_ptr    : 256
> >
> >the minus delay value is definitely wrong.
> >something weird goes there...
> >could you check sw_params during this happens?
> 
> yes i could, but i won't if you don't insist (they don't change anyway
> iirc). instead i have done some more investigations:
> 
> remember capture + play are linked, and audio data has been written. 
> now draining the playback stream *always* fails in the way already
> described.
 
oh, then it's related with the linkage...

> consequences: if you close capture first and then playback, things
> work ok. if you unlink the streams before closing them, things work
> ok, and the order of closing does not matter.
> 
> i have attached testing boilerplate code that you can use to 
> reproduce the error.

thanks, i'll test this later.


Takashi

_______________________________________________________________

Don't miss the 2002 Sprint PCS Application Developer's Conference
August 25-28 in Las Vegas - http://devcon.sprintpcs.com/adp/index.cfm?source=osdntextlink