DMA buffer gets played only once

DMA buffer gets played only once

[Markus Franke]

Dear Alsa Developers/Users,

I am working on a SoC Alsa driver for the WM8973. Currently I am facing 
the problem that after playing once the whole preallocated DMA buffer 
the playback stops and Alsa returns with

---snip---
ALSA sound/core/pcm_native.c:1526: playback drain error (DMA or IRQ 
trouble?)
---snap---


As far as I understood the callflow is like this:

pcm_prepare() --> pcm_trigger(TRIGGER_START) --> 
snd_pcm_period_elapsed() from interrupt handler or DMA callback --> 
pcm_pointer() --> pcm_trigger(TRIGGER_STOP) --> pcm_prepare() --> .....

With each call of pcm_trigger(TRIGGER_START) I am transfering one period 
of sounddata. For some reason the playback stops once the DMA buffer (in 
my 8 example it holds 8 periods of data) is finished and the pointer 
should wrap around to the beginning through pcm_pointer() callback. I 
checked return values of pcm_pointer() and tried to trace it back 
through Alsa/SoC stack without success. It seems like that after the 8th 
period is transferred pcm_trigger(TRIGGER_STOP) isn't getting called. 
Instead of this I get a lot of calls to pcm_pointer() which result 
finally in the above mentioned Alsa error message. I checked 
pcm_pointer() return values but everything seems to be fine I think.

Below you can find some verbose printk's I added to the source code:

---snip---
vi1888-i2s: vi1888_i2s_startup()-->
vi1888-pcm: vi1888_pcm_open()-->
vi1888-i2s: vi1888_i2s_set_dai_fmt()-->
vi1888-i2s: vi1888_i2s_set_dai_sysclk()-->
vi1888-i2s: vi1888_i2s_hw_params()-->
vi1888-pcm: vi1888_pcm_hw_params()-->
hw_params: DMA for I2S PCM Stereo out initialized (dma_bytes=32768, 
period_size=4096)
vi1888-i2s: vi1888_i2s_set_dai_fmt()-->
vi1888-i2s: vi1888_i2s_set_dai_sysclk()-->
vi1888-pcm: vi1888_pcm_hw_params()-->
hw_params: DMA for I2S PCM Stereo out initialized (dma_bytes=32768, 
period_size=4096)
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 1024
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 2048
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 3072
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 4096
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 5120
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 6144
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 7168
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_prepare()-->
vi1888-i2s: vi1888_i2s_prepare()-->
vi1888-pcm: vi1888_pcm_trigger()-->
vi1888-pcm: vi1888_pcm_dma_userCallback()-->
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 0
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 1024
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 2048
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 3072
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 4096
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 5120
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 6144
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 7168
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 0
vi1888-pcm: vi1888_pcm_pointer()-->
pcm_pointer returns 1024

.
.
.
.
.
.
.

ALSA sound/core/pcm_native.c:1526: playback drain error (DMA or IRQ 
trouble?)
---snap---

I get this output when trying to play a 16-bit stereo WAV file.

Thanks for any help on this,

Regards,
Markus Franke

Re: DMA buffer gets played only once

[Clemens Ladisch]

Markus Franke wrote:
> It seems like that after the 8th period is transferred
> pcm_trigger(TRIGGER_STOP) isn't getting called. 

Indeed.  The stop trigger is called when the entire stream is
to be stopped.

When the start trigger has been called, the hardware (or the driver) is
responsible for playing the ring buffer _repeatedly_.   If the hardware
doesn't do this automatically, the driver has to reprogram it.


HTH
Clemens

Re: DMA buffer gets played only once

[Markus Franke]

Clemens Ladisch wrote:
> Markus Franke wrote:
>> It seems like that after the 8th period is transferred
>> pcm_trigger(TRIGGER_STOP) isn't getting called. 
> 
> Indeed.  The stop trigger is called when the entire stream is
> to be stopped.

Well, start and stop trigger get always called mutually. In pseudo code 
it would look like this:

---snip---
TRIGGER_START

transfer one period via DMA

TRIGGER_STOP

update DMAC settings in DMA transfer finished callback and call 
snd_pcm_period_elapsed()

TRIGGER_START

transfer one period via DMA

TRIGGER_STOP

update DMAC settings in DMA transfer finished callback and call 
snd_pcm_period_elapsed()

....and so on.
---snap---

At least this is the behaviour I experienced.

So long,
Markus

Re: DMA buffer gets played only once

[Takashi Iwai]

At Wed, 05 Sep 2007 14:47:22 +0530,
Markus Franke wrote:
> 
> Clemens Ladisch wrote:
> > Markus Franke wrote:
> >> It seems like that after the 8th period is transferred
> >> pcm_trigger(TRIGGER_STOP) isn't getting called. 
> > 
> > Indeed.  The stop trigger is called when the entire stream is
> > to be stopped.
> 
> Well, start and stop trigger get always called mutually. In pseudo code 
> it would look like this:
> 
> ---snip---
> TRIGGER_START
> 
> transfer one period via DMA
> 
> TRIGGER_STOP
> 
> update DMAC settings in DMA transfer finished callback and call 
> snd_pcm_period_elapsed()
> 
> TRIGGER_START
> 
> transfer one period via DMA
> 
> TRIGGER_STOP
> 
> update DMAC settings in DMA transfer finished callback and call 
> snd_pcm_period_elapsed()
> 
> ....and so on.
> ---snap---
> 
> At least this is the behaviour I experienced.

It's your mis-interpretation of START/STOP concenpt in the ALSA
framework.  The trigger START and STOP mean the start/stop of the
whole streaming operation.  It's basically called from the outside,
i.e. the application starts/stops the stream.  If you need to keep
some DMA start/stop operations internally, do it in the driver
lowlevel side internally.


Takashi

Re: DMA buffer gets played only once

[Markus Franke]

Hi,

Takashi Iwai wrote:
>> At least this is the behaviour I experienced.
> 
> It's your mis-interpretation of START/STOP concenpt in the ALSA
> framework.  The trigger START and STOP mean the start/stop of the
> whole streaming operation.  It's basically called from the outside,
> i.e. the application starts/stops the stream.  If you need to keep
> some DMA start/stop operations internally, do it in the driver
> lowlevel side internally.

thanks for reply but as already stated this is the behaviour I 
_experienced_. I don't know why also continuously calls trigger START, 
play one period, trigger STOP. Here is some pseudo code:

---snip---
pcm_trigger()
{
	case SNDRV_PCM_TRIGGER_START:
                 /* start the DMA Transfer */
                 ret = startTransfer(dma_devaddr, params->ch_num, 
num_blocks, vi1888_pcm_dma_userCallback, substream);
                 break;
...
}




vi1888_pcm_dma_userCallback() // gets called upon completion of DMA 
transfer
{
         prtd->period_ptr += prtd->period_size;
         if (prtd->period_ptr >= prtd->dma_buffer_end) {
                 prtd->period_ptr = prtd->dma_buffer;
         }

	/* reconfigure channel according to new period pointer */

         /* start the next DMA Transfer */
         ret = startTransfer(dma_devaddr, params->ch_num, num_blocks, 
vi1888_pcm_dma_userCallback, substream();

         /* notify Alsa for the elapsed periods */
         snd_pcm_period_elapsed(substream);
}

---snap---

After each call to snd_pcm_period_elapsed() Alsa calls 
pcm_trigger(TRIGGER_STOP).

Please tell me what I am doing wrong in these callbacks?


Thanks in advance,
Markus

Re: DMA buffer gets played only once

[Trent Piepho]

On Thu, 6 Sep 2007, Markus Franke wrote:
> Takashi Iwai wrote:
> >> At least this is the behaviour I experienced.
> >
> > It's your mis-interpretation of START/STOP concenpt in the ALSA
> > framework.  The trigger START and STOP mean the start/stop of the
> > whole streaming operation.  It's basically called from the outside,
> > i.e. the application starts/stops the stream.  If you need to keep
> > some DMA start/stop operations internally, do it in the driver
> > lowlevel side internally.
>
> thanks for reply but as already stated this is the behaviour I
> _experienced_. I don't know why also continuously calls trigger START,
> play one period, trigger STOP. Here is some pseudo code:
>
>
> vi1888_pcm_dma_userCallback() // gets called upon completion of DMA
> transfer
> {
>          prtd->period_ptr += prtd->period_size;
>          if (prtd->period_ptr >= prtd->dma_buffer_end) {
>                  prtd->period_ptr = prtd->dma_buffer;
>          }

You need to make sure the buffer size is an integer multiple of the period
size if you wrap like this.

> After each call to snd_pcm_period_elapsed() Alsa calls
> pcm_trigger(TRIGGER_STOP).
>
> Please tell me what I am doing wrong in these callbacks?

I found that ALSA would call TRIGGER_STOP if it detected an overrun.

Check the value returned for every call of your pointer callback.  I found out
that ALSA was calling the pointer callback before the first IRQ, which was
something I hadn't planned on and the values confused ALSA.

Re: DMA buffer gets played only once

[Markus Franke]

Hi,

Trent Piepho wrote:
> You need to make sure the buffer size is an integer multiple of the period
> size if you wrap like this.

Yeah I have to take care of this but right now my buffersize is 32768 
bytes and the period size is 4096 bytes which should work I think.

> I found that ALSA would call TRIGGER_STOP if it detected an overrun.

Yeah that's right. I guess this is my case because xrun() is getting 
called somewhere. So how can I fix this underrun problem?

> Check the value returned for every call of your pointer callback.  I found out
> that ALSA was calling the pointer callback before the first IRQ, which was
> something I hadn't planned on and the values confused ALSA.

That's not my case. pcm_pointer gets called after the first DMA 
transaction is finished. (DMA transfer finished callback gets called 
before pcm_pointer) Also the values which are returned by pcm_pointer 
look quite reasonable. (see also my very first posting in this thread, 
look for the printk's "pcm_pointer returns <value>")


Thanks for your effort,

Markus Franke

Re: DMA buffer gets played only once

[Markus Franke]

I just found out that the problem of multiple calls of 
TRIGGER_START/TRIGGER_STOP might be caused by using ossplay (oss 
emulation layer) for testing. If I use aplay, TRIGGER_START gets called 
once but then Alsa goes in a loop continuously calling pcm_pointer().
Return values of pcm_pointer() look like the following:

---snip---
pcm_pointer returns 0
pcm_pointer returns 1024
pcm_pointer returns 2048
pcm_pointer returns 3072
pcm_pointer returns 4096
pcm_pointer returns 5120
pcm_pointer returns 6144
pcm_pointer returns 7168
pcm_pointer returns 0
pcm_pointer returns 1024
pcm_pointer returns 2048
pcm_pointer returns 3072
pcm_pointer returns 4096
pcm_pointer returns 5120
pcm_pointer returns 6144
pcm_pointer returns 7168
---snap---

Finally I get a message saying:

---snip---
ALSA sound/core/pcm_native.c:1525: playback drain error (DMA or IRQ 
trouble?)
---snap---

Hope this helps.

Regards,
Markus Franke

Markus Franke wrote:
> Hi,
> 
> Trent Piepho wrote:
>> You need to make sure the buffer size is an integer multiple of the period
>> size if you wrap like this.
> 
> Yeah I have to take care of this but right now my buffersize is 32768 
> bytes and the period size is 4096 bytes which should work I think.
> 
>> I found that ALSA would call TRIGGER_STOP if it detected an overrun.
> 
> Yeah that's right. I guess this is my case because xrun() is getting 
> called somewhere. So how can I fix this underrun problem?
> 
>> Check the value returned for every call of your pointer callback.  I found out
>> that ALSA was calling the pointer callback before the first IRQ, which was
>> something I hadn't planned on and the values confused ALSA.
> 
> That's not my case. pcm_pointer gets called after the first DMA 
> transaction is finished. (DMA transfer finished callback gets called 
> before pcm_pointer) Also the values which are returned by pcm_pointer 
> look quite reasonable. (see also my very first posting in this thread, 
> look for the printk's "pcm_pointer returns <value>")
> 
> 
> Thanks for your effort,
> 
> Markus Franke
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
> 

Re: DMA buffer gets played only once

[Takashi Iwai]

At Thu, 06 Sep 2007 11:57:03 +0530,
Markus Franke wrote:
> 
> I just found out that the problem of multiple calls of 
> TRIGGER_START/TRIGGER_STOP might be caused by using ossplay (oss 
> emulation layer) for testing. If I use aplay, TRIGGER_START gets called 
> once but then Alsa goes in a loop continuously calling pcm_pointer().

OK this explains the behavior partly.  The repeating call of
TRIGGER_START is because of the automatic recovery from XRUN status in
OSS emulation code.  In ALSA code, it's not automatically recovered
but kept stopped as default.

But, it still doesn't explain why XRUN is detected.

> Return values of pcm_pointer() look like the following:
> 
> ---snip---
> pcm_pointer returns 0
> pcm_pointer returns 1024
> pcm_pointer returns 2048
> pcm_pointer returns 3072
> pcm_pointer returns 4096
> pcm_pointer returns 5120
> pcm_pointer returns 6144
> pcm_pointer returns 7168
> pcm_pointer returns 0
> pcm_pointer returns 1024
> pcm_pointer returns 2048
> pcm_pointer returns 3072
> pcm_pointer returns 4096
> pcm_pointer returns 5120
> pcm_pointer returns 6144
> pcm_pointer returns 7168
> ---snap---
> 
> Finally I get a message saying:
> 
> ---snip---
> ALSA sound/core/pcm_native.c:1525: playback drain error (DMA or IRQ 
> trouble?)
> ---snap---

So, until this the driver runs well but at this point, the driver gets
no longer irq.  Maybe you can add some debug messages in the irq
handler and the code reprogramming the next DMA chunk.
Also, in prepare callback, try to output the important parameters,
such as format, channels, period_size and buffer_size.  Unless you set
extra hw_constraints, the buffer_size and period_size aren't always
aligned.


Takashi

Re: DMA buffer gets played only once

[Trent Piepho]

On Thu, 6 Sep 2007, Markus Franke wrote:
> I just found out that the problem of multiple calls of
> TRIGGER_START/TRIGGER_STOP might be caused by using ossplay (oss
> emulation layer) for testing. If I use aplay, TRIGGER_START gets called
> once but then Alsa goes in a loop continuously calling pcm_pointer().
> Return values of pcm_pointer() look like the following:

I found it very helpful to print timestamps for the various calls (trigger,
pointer, and my IRQ handler).  The code inside the #if 0, around lines 53 and
191, is what I wrote to use the time cycle counter for accurate timestamps.
http://linuxtv.org/hg/v4l-dvb/file/tip/linux/drivers/media/video/cx88/cx88-alsa.c


> ---snip---
> pcm_pointer returns 0
> pcm_pointer returns 1024
> pcm_pointer returns 2048
> pcm_pointer returns 3072

This is where a timestamp would be nice.  Is pcm_pointer getting called after
each period is elapsed, in microseconds?  Or is the pointer advancing much too
quickly?  It should take about 23220 us for the pointer to increase by 1024
frames at 44.1 kHz.

AFAIK, the only way a driver has to communicate with ALSA during pcm capture
or playback is via the return value of the pointer callback, and when and how
often the driver calls snd_pcm_period_elapsed().

If ALSA is detecting an underrun, it must be something about those two
functions that is causing it.

Be sure to check the period and buffer size from the runtime in your
callbacks, if you haven't already.  They might not be what you expected them
to be, which would easily explain the problem.