ALSA calling pcm_pointer excessively?

ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

I'm wondering what is causing ALSA to behave as follows - I have a 64KiB
buffer, which is divided up into 4 16KiB periods.  The log below is from
my soc-dmaengine.c code which supports audio on the Assabet (as we don't
have cyclic DMA support there yet.)

I'm just trying to sort out the DMA engine tx_status residue code, and
am using this as proof that its working.

However, it seems that ALSA for whatever reason likes to hammer away at
the pcm_pointer callback from time to time:

soc_dmaengine_pointer: index 3 stat 1 residue 0018 cookie 3cfe pos 10000 bytes ffe8
soc_dmaengine_pointer: index 3 stat 1 residue 0008 cookie 3cfe pos 10000 bytes fff8
soc_dmaengine_callback: complete
soc_dmaengine_pointer: index 0 stat 1 residue 3ff0 cookie 3cff pos 4000 bytes 0010
soc_dmaengine_submit: submitting index 3 size 4000 cookie 3d02
soc_dmaengine_pointer: index 0 stat 1 residue 3fd0 cookie 3cff pos 4000 bytes 0030
soc_dmaengine_pointer: index 0 stat 1 residue 17b8 cookie 3cff pos 4000 bytes 2848
soc_dmaengine_pointer: index 0 stat 1 residue 1770 cookie 3cff pos 4000 bytes 2890
soc_dmaengine_pointer: index 0 stat 1 residue 1768 cookie 3cff pos 4000 bytes 2898
soc_dmaengine_pointer: index 0 stat 1 residue 1758 cookie 3cff pos 4000 bytes 28a8
soc_dmaengine_pointer: index 0 stat 1 residue 1748 cookie 3cff pos 4000 bytes 28b8
soc_dmaengine_pointer: index 0 stat 1 residue 1740 cookie 3cff pos 4000 bytes 28c0
soc_dmaengine_pointer: index 0 stat 1 residue 1730 cookie 3cff pos 4000 bytes 28d0
soc_dmaengine_pointer: index 0 stat 1 residue 1720 cookie 3cff pos 4000 bytes 28e0
soc_dmaengine_pointer: index 0 stat 1 residue 1718 cookie 3cff pos 4000 bytes 28e8
...
soc_dmaengine_pointer: index 0 stat 1 residue 0018 cookie 3cff pos 4000 bytes 3fe8
soc_dmaengine_pointer: index 0 stat 1 residue 0008 cookie 3cff pos 4000 bytes 3ff8
soc_dmaengine_callback: complete
soc_dmaengine_pointer: index 1 stat 1 residue 3ff0 cookie 3d00 pos 8000 bytes 4010
soc_dmaengine_submit: submitting index 0 size 4000 cookie 3d03
soc_dmaengine_pointer: index 1 stat 1 residue 3fd0 cookie 3d00 pos 8000 bytes 4030
soc_dmaengine_pointer: index 1 stat 1 residue 3b28 cookie 3d00 pos 8000 bytes 44d8
soc_dmaengine_pointer: index 1 stat 1 residue 3b10 cookie 3d00 pos 8000 bytes 44f0
soc_dmaengine_pointer: index 1 stat 1 residue 3b00 cookie 3d00 pos 8000 bytes 4500

'pos' is the end of the current DMA buffer ((index + 1) * period_byte_size)
'residue' is the value returned from tx_status
'bytes' is the value passed into bytes_to_frames() to return from my
pcm_pointer function.

The question is - what would cause ALSA to hammer away at the buffer
like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
seeing around 75% system CPU time, which really isn't good.

The above was captured while aplay was running, with no apparant audio
corruption.

Any ideas?

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Thu, May 10, 2012 at 05:06:01PM +0100, Russell King - ARM Linux wrote:
> I'm wondering what is causing ALSA to behave as follows - I have a 64KiB
> buffer, which is divided up into 4 16KiB periods.  The log below is from
> my soc-dmaengine.c code which supports audio on the Assabet (as we don't
> have cyclic DMA support there yet.)
> 
> I'm just trying to sort out the DMA engine tx_status residue code, and
> am using this as proof that its working.
> 
> However, it seems that ALSA for whatever reason likes to hammer away at
> the pcm_pointer callback from time to time:
> 
> soc_dmaengine_pointer: index 3 stat 1 residue 0018 cookie 3cfe pos 10000 bytes ffe8
> soc_dmaengine_pointer: index 3 stat 1 residue 0008 cookie 3cfe pos 10000 bytes fff8
> soc_dmaengine_callback: complete
> soc_dmaengine_pointer: index 0 stat 1 residue 3ff0 cookie 3cff pos 4000 bytes 0010
> soc_dmaengine_submit: submitting index 3 size 4000 cookie 3d02
> soc_dmaengine_pointer: index 0 stat 1 residue 3fd0 cookie 3cff pos 4000 bytes 0030
> soc_dmaengine_pointer: index 0 stat 1 residue 17b8 cookie 3cff pos 4000 bytes 2848
> soc_dmaengine_pointer: index 0 stat 1 residue 1770 cookie 3cff pos 4000 bytes 2890
> soc_dmaengine_pointer: index 0 stat 1 residue 1768 cookie 3cff pos 4000 bytes 2898
> soc_dmaengine_pointer: index 0 stat 1 residue 1758 cookie 3cff pos 4000 bytes 28a8
> soc_dmaengine_pointer: index 0 stat 1 residue 1748 cookie 3cff pos 4000 bytes 28b8
> soc_dmaengine_pointer: index 0 stat 1 residue 1740 cookie 3cff pos 4000 bytes 28c0
> soc_dmaengine_pointer: index 0 stat 1 residue 1730 cookie 3cff pos 4000 bytes 28d0
> soc_dmaengine_pointer: index 0 stat 1 residue 1720 cookie 3cff pos 4000 bytes 28e0
> soc_dmaengine_pointer: index 0 stat 1 residue 1718 cookie 3cff pos 4000 bytes 28e8
> ...
> soc_dmaengine_pointer: index 0 stat 1 residue 0018 cookie 3cff pos 4000 bytes 3fe8
> soc_dmaengine_pointer: index 0 stat 1 residue 0008 cookie 3cff pos 4000 bytes 3ff8
> soc_dmaengine_callback: complete
> soc_dmaengine_pointer: index 1 stat 1 residue 3ff0 cookie 3d00 pos 8000 bytes 4010
> soc_dmaengine_submit: submitting index 0 size 4000 cookie 3d03
> soc_dmaengine_pointer: index 1 stat 1 residue 3fd0 cookie 3d00 pos 8000 bytes 4030
> soc_dmaengine_pointer: index 1 stat 1 residue 3b28 cookie 3d00 pos 8000 bytes 44d8
> soc_dmaengine_pointer: index 1 stat 1 residue 3b10 cookie 3d00 pos 8000 bytes 44f0
> soc_dmaengine_pointer: index 1 stat 1 residue 3b00 cookie 3d00 pos 8000 bytes 4500
> 
> 'pos' is the end of the current DMA buffer ((index + 1) * period_byte_size)
> 'residue' is the value returned from tx_status
> 'bytes' is the value passed into bytes_to_frames() to return from my
> pcm_pointer function.
> 
> The question is - what would cause ALSA to hammer away at the buffer
> like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
> seeing around 75% system CPU time, which really isn't good.
> 
> The above was captured while aplay was running, with no apparant audio
> corruption.
> 
> Any ideas?

bash-2.05a# cat /proc/asound/card0/pcm0p/sub0/sw_params 
tstamp_mode: NONE
period_step: 1
avail_min: 4096
start_threshold: 16384
stop_threshold: 16384
silence_threshold: 0
silence_size: 0
boundary: 1073741824

I think what's happening is that snd_pcm_lib_write1() is looping, and
each time it updates the hardware position, it finds that it can
transfer 8 or 16 bytes to the buffer.  Once it's transferred that,
it re-updates the hardware position which has now advanced by another
8 or 16 bytes.  Repeat, and you find that snd_pcm_lib_write1() spends
a lot of time inefficiently copying the buffer.

It seems that it will only sleep if the hardware pointer stops making
progress.  That implies that I have to purposely reduce the granularity
that I report the current DMA position which isn't a sane thing to do.

Re: ALSA calling pcm_pointer excessively?

[Clemens Ladisch]

Russell King - ARM Linux wrote:
> I think what's happening is that snd_pcm_lib_write1() is looping, and
> each time it updates the hardware position, it finds that it can
> transfer 8 or 16 bytes to the buffer.  Once it's transferred that,
> it re-updates the hardware position which has now advanced by another
> 8 or 16 bytes.  Repeat, and you find that snd_pcm_lib_write1() spends
> a lot of time inefficiently copying the buffer.
>
> It seems that it will only sleep if the hardware pointer stops making
> progress.

I'd guess that most existing hardware is fast enough to transfer
samples and has a big enough granularity (typically 32 byte bursts
for PCI) that the pointer doesn't change in consecutive loop
iterations.

This (untested) patch tries to avoid too many busy looping.


Regards,
Clemens


--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -1894,7 +1894,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	struct snd_pcm_runtime *runtime = substream->runtime;
 	snd_pcm_uframes_t xfer = 0;
 	snd_pcm_uframes_t offset = 0;
-	int err = 0;
+	int busy_loops = 0, err = 0;

 	if (size == 0)
 		return 0;
@@ -1919,12 +1919,17 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	runtime->twake = runtime->control->avail_min ? : 1;
 	while (size > 0) {
 		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
-		snd_pcm_uframes_t avail;
+		snd_pcm_uframes_t avail, avail_wait_max;
 		snd_pcm_uframes_t cont;
+
+		if (busy_loops < 5)
+			avail_wait_max = 0;
+		else
+			avail_wait_max = min(runtime->control->avail_min, size);
 		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
 			snd_pcm_update_hw_ptr(substream);
 		avail = snd_pcm_playback_avail(runtime);
-		if (!avail) {
+		if (avail <= avail_wait_max) {
 			if (nonblock) {
 				err = -EAGAIN;
 				goto _end_unlock;
@@ -1934,6 +1939,9 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 			err = wait_for_avail(substream, &avail);
 			if (err < 0)
 				goto _end_unlock;
+			busy_loops = 0;
+		} else {
+			busy_loops++;
 		}
 		frames = size > avail ? avail : size;
 		cont = runtime->buffer_size - runtime->control->appl_ptr % runtime->buffer_size;

Re: ALSA calling pcm_pointer excessively?

[Clemens Ladisch]

I wrote:
> This (untested) patch tries to avoid too many busy looping.

Oops, off-by-one error (avail == avail_min should not wait).


Regards,
Clemens

--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -1894,7 +1894,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	struct snd_pcm_runtime *runtime = substream->runtime;
 	snd_pcm_uframes_t xfer = 0;
 	snd_pcm_uframes_t offset = 0;
-	int err = 0;
+	int busy_loops = 0, err = 0;

 	if (size == 0)
 		return 0;
@@ -1919,12 +1919,17 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	runtime->twake = runtime->control->avail_min ? : 1;
 	while (size > 0) {
 		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
-		snd_pcm_uframes_t avail;
+		snd_pcm_uframes_t avail, avail_nowait_min;
 		snd_pcm_uframes_t cont;
+
+		if (busy_loops < 5)
+			avail_nowait_min = 1;
+		else
+			avail_nowait_min = min(runtime->control->avail_min, size);
 		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
 			snd_pcm_update_hw_ptr(substream);
 		avail = snd_pcm_playback_avail(runtime);
-		if (!avail) {
+		if (avail < avail_nowait_min) {
 			if (nonblock) {
 				err = -EAGAIN;
 				goto _end_unlock;
@@ -1934,6 +1939,9 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 			err = wait_for_avail(substream, &avail);
 			if (err < 0)
 				goto _end_unlock;
+			busy_loops = 0;
+		} else {
+			busy_loops++;
 		}
 		frames = size > avail ? avail : size;
 		cont = runtime->buffer_size - runtime->control->appl_ptr % runtime->buffer_size;

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Thu, May 10, 2012 at 07:13:59PM +0200, Clemens Ladisch wrote:
> I wrote:
> > This (untested) patch tries to avoid too many busy looping.
> 
> Oops, off-by-one error (avail == avail_min should not wait).

This is better - it now sits around 2-14% system time.  I guess the
five loops is rather arbitary?

Re: ALSA calling pcm_pointer excessively?

[Clemens Ladisch]

Russell King - ARM Linux wrote:
> On Thu, May 10, 2012 at 07:13:59PM +0200, Clemens Ladisch wrote:
>> I wrote:
>>> This (untested) patch tries to avoid too many busy looping.
>>
>> Oops, off-by-one error (avail == avail_min should not wait).
>
> This is better - it now sits around 2-14% system time.  I guess the
> five loops is rather arbitary?

Yes.  The minimum loop limit is two (to handle wraparound at the end of
the buffer); more than that probably does not actually make sense.

Jassi Brar wrote:
> If we really want to change the behavior of play, wouldn't we want to do that
> for capture(snd_pcm_lib_read1) as well ?

Indeed.  And we'd want to reuse the twake calculation.


Regards,
Clemens

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Thu, May 10, 2012 at 08:43:40PM +0200, Clemens Ladisch wrote:
> Russell King - ARM Linux wrote:
> > On Thu, May 10, 2012 at 07:13:59PM +0200, Clemens Ladisch wrote:
> >> I wrote:
> >>> This (untested) patch tries to avoid too many busy looping.
> >>
> >> Oops, off-by-one error (avail == avail_min should not wait).
> >
> > This is better - it now sits around 2-14% system time.  I guess the
> > five loops is rather arbitary?
> 
> Yes.  The minimum loop limit is two (to handle wraparound at the end of
> the buffer); more than that probably does not actually make sense.

Ok, I'll test with two there tomorrow.

Re: ALSA calling pcm_pointer excessively?

[Jassi Brar]

On Thu, May 10, 2012 at 10:35 PM, Clemens Ladisch <clemens@ladisch.de> wrote:
>
> --- a/sound/core/pcm_lib.c
> +++ b/sound/core/pcm_lib.c
> @@ -1894,7 +1894,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>        struct snd_pcm_runtime *runtime = substream->runtime;
>        snd_pcm_uframes_t xfer = 0;
>        snd_pcm_uframes_t offset = 0;
> -       int err = 0;
> +       int busy_loops = 0, err = 0;
>
>        if (size == 0)
>                return 0;
> @@ -1919,12 +1919,17 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>        runtime->twake = runtime->control->avail_min ? : 1;
>        while (size > 0) {
>                snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
> -               snd_pcm_uframes_t avail;
> +               snd_pcm_uframes_t avail, avail_wait_max;
>                snd_pcm_uframes_t cont;
> +
> +               if (busy_loops < 5)
> +                       avail_wait_max = 0;
> +               else
> +                       avail_wait_max = min(runtime->control->avail_min, size);
>                if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
>                        snd_pcm_update_hw_ptr(substream);
>                avail = snd_pcm_playback_avail(runtime);
> -               if (!avail) {
> +               if (avail <= avail_wait_max) {
>                        if (nonblock) {
>                                err = -EAGAIN;
>                                goto _end_unlock;
> @@ -1934,6 +1939,9 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>                        err = wait_for_avail(substream, &avail);
>                        if (err < 0)
>                                goto _end_unlock;
> +                       busy_loops = 0;
> +               } else {
> +                       busy_loops++;
>                }
>                frames = size > avail ? avail : size;
>                cont = runtime->buffer_size - runtime->control->appl_ptr % runtime->buffer_size;
>
Hi Clemens,

If we really want to change the behavior of play, wouldn't we want to do that
for capture(snd_pcm_lib_read1) as well ?
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: ALSA calling pcm_pointer excessively?

[Takashi Iwai]

At Thu, 10 May 2012 19:05:56 +0200,
Clemens Ladisch wrote:
> 
> Russell King - ARM Linux wrote:
> > I think what's happening is that snd_pcm_lib_write1() is looping, and
> > each time it updates the hardware position, it finds that it can
> > transfer 8 or 16 bytes to the buffer.  Once it's transferred that,
> > it re-updates the hardware position which has now advanced by another
> > 8 or 16 bytes.  Repeat, and you find that snd_pcm_lib_write1() spends
> > a lot of time inefficiently copying the buffer.
> >
> > It seems that it will only sleep if the hardware pointer stops making
> > progress.
> 
> I'd guess that most existing hardware is fast enough to transfer
> samples and has a big enough granularity (typically 32 byte bursts
> for PCI) that the pointer doesn't change in consecutive loop
> iterations.
> 
> This (untested) patch tries to avoid too many busy looping.

Hmm...  I still can't follow why such a busy loop happens when
avail_min > 1.  If avail_min = 1, a busy loop can't be avoided.
But if avail_min is set (typically equal with period_size),
runtime->twake is either the rest size or the period size, and
wait_for_avail() should wait until that sufficiently.

Russell, which avail_min value is used in your test case?
(I thought aplay uses avail_min = period_size as default, but just to
 be sure.)


thanks,

Takashi

> 
> 
> Regards,
> Clemens
> 
> 
> --- a/sound/core/pcm_lib.c
> +++ b/sound/core/pcm_lib.c
> @@ -1894,7 +1894,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>  	struct snd_pcm_runtime *runtime = substream->runtime;
>  	snd_pcm_uframes_t xfer = 0;
>  	snd_pcm_uframes_t offset = 0;
> -	int err = 0;
> +	int busy_loops = 0, err = 0;
> 
>  	if (size == 0)
>  		return 0;
> @@ -1919,12 +1919,17 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>  	runtime->twake = runtime->control->avail_min ? : 1;
>  	while (size > 0) {
>  		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
> -		snd_pcm_uframes_t avail;
> +		snd_pcm_uframes_t avail, avail_wait_max;
>  		snd_pcm_uframes_t cont;
> +
> +		if (busy_loops < 5)
> +			avail_wait_max = 0;
> +		else
> +			avail_wait_max = min(runtime->control->avail_min, size);
>  		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
>  			snd_pcm_update_hw_ptr(substream);
>  		avail = snd_pcm_playback_avail(runtime);
> -		if (!avail) {
> +		if (avail <= avail_wait_max) {
>  			if (nonblock) {
>  				err = -EAGAIN;
>  				goto _end_unlock;
> @@ -1934,6 +1939,9 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
>  			err = wait_for_avail(substream, &avail);
>  			if (err < 0)
>  				goto _end_unlock;
> +			busy_loops = 0;
> +		} else {
> +			busy_loops++;
>  		}
>  		frames = size > avail ? avail : size;
>  		cont = runtime->buffer_size - runtime->control->appl_ptr % runtime->buffer_size;
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
> 

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Fri, May 11, 2012 at 03:31:08PM +0200, Takashi Iwai wrote:
> At Thu, 10 May 2012 19:05:56 +0200,
> Clemens Ladisch wrote:
> > 
> > Russell King - ARM Linux wrote:
> > > I think what's happening is that snd_pcm_lib_write1() is looping, and
> > > each time it updates the hardware position, it finds that it can
> > > transfer 8 or 16 bytes to the buffer.  Once it's transferred that,
> > > it re-updates the hardware position which has now advanced by another
> > > 8 or 16 bytes.  Repeat, and you find that snd_pcm_lib_write1() spends
> > > a lot of time inefficiently copying the buffer.
> > >
> > > It seems that it will only sleep if the hardware pointer stops making
> > > progress.
> > 
> > I'd guess that most existing hardware is fast enough to transfer
> > samples and has a big enough granularity (typically 32 byte bursts
> > for PCI) that the pointer doesn't change in consecutive loop
> > iterations.
> > 
> > This (untested) patch tries to avoid too many busy looping.
> 
> Hmm...  I still can't follow why such a busy loop happens when
> avail_min > 1.  If avail_min = 1, a busy loop can't be avoided.
> But if avail_min is set (typically equal with period_size),
> runtime->twake is either the rest size or the period size, and
> wait_for_avail() should wait until that sufficiently.

It's exaclty as I explained.  Lets take avail_min = 4096, as it is in my
case.

In snd_pcm_lib_write1(), we loop - here's the simplified version:

        while (size > 0) {
                if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
                        snd_pcm_update_hw_ptr(substream);
                avail = snd_pcm_playback_avail(runtime);
                if (!avail) {
			/* Sleep until avail >= avail_min */
		}
		/* Transfer up to max(avail,size) bytes to buffer */
	}

The problem is this.  On entry to the loop, say, we calculate that we
can transfer 4096 bytes into the buffer, and we do that.  While we're
transferring those bytes, the hardware DMA position has advanced.

So, the second time around the loop, avail will be non-zero - let's
say that the DMA position has advanced 32 bytes.  So avail will be
32 bytes, and we transfer 32 bytes.  Again, while transferring those
bytes, the DMA position has advanced, but not as far.  Let's say 8
bytes.

So, we repeat the loop, and again, we find avail is non-zero.  We
omit sleeping, instead, dropping through to transfer 8 bytes.

Meanwhile, the DMA position has advanced another 8 bytes.

Repeat, endlessly, wasting lots of CPU cycles transferring very small
sets of sample data to the buffer.

That happens because of the requirement for the above code to sleep is
that there has been _no_ advancement of the DMA position while copying
data to the buffer.  Unfortunately, that's not always a realistic
expectation, especially if you have a high data rate.

At no point in the above scenario does avail_min come into it, until
we're lucky enough that we copy data into the buffer without the DMA
position changing.  At that point, we're then allowed to sleep.  The
decision to sleep is based purely upon there being _zero_ bytes of
available buffer space.

Re: ALSA calling pcm_pointer excessively?

[Takashi Iwai]

At Fri, 11 May 2012 15:02:37 +0100,
Russell King - ARM Linux wrote:
> 
> On Fri, May 11, 2012 at 03:31:08PM +0200, Takashi Iwai wrote:
> > At Thu, 10 May 2012 19:05:56 +0200,
> > Clemens Ladisch wrote:
> > > 
> > > Russell King - ARM Linux wrote:
> > > > I think what's happening is that snd_pcm_lib_write1() is looping, and
> > > > each time it updates the hardware position, it finds that it can
> > > > transfer 8 or 16 bytes to the buffer.  Once it's transferred that,
> > > > it re-updates the hardware position which has now advanced by another
> > > > 8 or 16 bytes.  Repeat, and you find that snd_pcm_lib_write1() spends
> > > > a lot of time inefficiently copying the buffer.
> > > >
> > > > It seems that it will only sleep if the hardware pointer stops making
> > > > progress.
> > > 
> > > I'd guess that most existing hardware is fast enough to transfer
> > > samples and has a big enough granularity (typically 32 byte bursts
> > > for PCI) that the pointer doesn't change in consecutive loop
> > > iterations.
> > > 
> > > This (untested) patch tries to avoid too many busy looping.
> > 
> > Hmm...  I still can't follow why such a busy loop happens when
> > avail_min > 1.  If avail_min = 1, a busy loop can't be avoided.
> > But if avail_min is set (typically equal with period_size),
> > runtime->twake is either the rest size or the period size, and
> > wait_for_avail() should wait until that sufficiently.
> 
> It's exaclty as I explained.  Lets take avail_min = 4096, as it is in my
> case.
> 
> In snd_pcm_lib_write1(), we loop - here's the simplified version:
> 
>         while (size > 0) {
>                 if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
>                         snd_pcm_update_hw_ptr(substream);
>                 avail = snd_pcm_playback_avail(runtime);
>                 if (!avail) {
> 			/* Sleep until avail >= avail_min */
> 		}
> 		/* Transfer up to max(avail,size) bytes to buffer */
> 	}
> 
> The problem is this.  On entry to the loop, say, we calculate that we
> can transfer 4096 bytes into the buffer, and we do that.  While we're
> transferring those bytes, the hardware DMA position has advanced.
> 
> So, the second time around the loop, avail will be non-zero - let's
> say that the DMA position has advanced 32 bytes.  So avail will be
> 32 bytes, and we transfer 32 bytes.  Again, while transferring those
> bytes, the DMA position has advanced, but not as far.  Let's say 8
> bytes.
> 
> So, we repeat the loop, and again, we find avail is non-zero.  We
> omit sleeping, instead, dropping through to transfer 8 bytes.
> 
> Meanwhile, the DMA position has advanced another 8 bytes.
> 
> Repeat, endlessly, wasting lots of CPU cycles transferring very small
> sets of sample data to the buffer.
> 
> That happens because of the requirement for the above code to sleep is
> that there has been _no_ advancement of the DMA position while copying
> data to the buffer.  Unfortunately, that's not always a realistic
> expectation, especially if you have a high data rate.
> 
> At no point in the above scenario does avail_min come into it, until
> we're lucky enough that we copy data into the buffer without the DMA
> position changing.  At that point, we're then allowed to sleep.  The
> decision to sleep is based purely upon there being _zero_ bytes of
> available buffer space.

Ah, thanks for clearing, now I got it.

Actually the call of snd_pcm_update_hw_ptr() at the loop entry doesn't
have to be done at each time, supposing the process of the loop
(without wait_for_avail()) is fast enough.

How about the patch below?


Takashi

---
diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c
index 4d18941..faedb14 100644
--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -1894,6 +1894,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	struct snd_pcm_runtime *runtime = substream->runtime;
 	snd_pcm_uframes_t xfer = 0;
 	snd_pcm_uframes_t offset = 0;
+	snd_pcm_uframes_t avail;
 	int err = 0;
 
 	if (size == 0)
@@ -1917,13 +1918,12 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	}
 
 	runtime->twake = runtime->control->avail_min ? : 1;
+	if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
+		snd_pcm_update_hw_ptr(substream);
+	avail = snd_pcm_playback_avail(runtime);
 	while (size > 0) {
 		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
-		snd_pcm_uframes_t avail;
 		snd_pcm_uframes_t cont;
-		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
-			snd_pcm_update_hw_ptr(substream);
-		avail = snd_pcm_playback_avail(runtime);
 		if (!avail) {
 			if (nonblock) {
 				err = -EAGAIN;
@@ -1971,6 +1971,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 		offset += frames;
 		size -= frames;
 		xfer += frames;
+		avail -= frames;
 		if (runtime->status->state == SNDRV_PCM_STATE_PREPARED &&
 		    snd_pcm_playback_hw_avail(runtime) >= (snd_pcm_sframes_t)runtime->start_threshold) {
 			err = snd_pcm_start(substream);
@@ -2111,6 +2112,7 @@ static snd_pcm_sframes_t snd_pcm_lib_read1(struct snd_pcm_substream *substream,
 	struct snd_pcm_runtime *runtime = substream->runtime;
 	snd_pcm_uframes_t xfer = 0;
 	snd_pcm_uframes_t offset = 0;
+	snd_pcm_uframes_t avail;
 	int err = 0;
 
 	if (size == 0)
@@ -2141,13 +2143,12 @@ static snd_pcm_sframes_t snd_pcm_lib_read1(struct snd_pcm_substream *substream,
 	}
 
 	runtime->twake = runtime->control->avail_min ? : 1;
+	if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
+		snd_pcm_update_hw_ptr(substream);
+	avail = snd_pcm_capture_avail(runtime);
 	while (size > 0) {
 		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
-		snd_pcm_uframes_t avail;
 		snd_pcm_uframes_t cont;
-		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
-			snd_pcm_update_hw_ptr(substream);
-		avail = snd_pcm_capture_avail(runtime);
 		if (!avail) {
 			if (runtime->status->state ==
 			    SNDRV_PCM_STATE_DRAINING) {
@@ -2202,6 +2203,7 @@ static snd_pcm_sframes_t snd_pcm_lib_read1(struct snd_pcm_substream *substream,
 		offset += frames;
 		size -= frames;
 		xfer += frames;
+		avail -= frames;
 	}
  _end_unlock:
 	runtime->twake = 0;

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Fri, May 11, 2012 at 04:17:50PM +0200, Takashi Iwai wrote:
> Actually the call of snd_pcm_update_hw_ptr() at the loop entry doesn't
> have to be done at each time, supposing the process of the loop
> (without wait_for_avail()) is fast enough.
> 
> How about the patch below?

This too seems to work fine on playback.  Thanks.

Re: ALSA calling pcm_pointer excessively?

[Takashi Iwai]

At Fri, 11 May 2012 16:04:50 +0100,
Russell King - ARM Linux wrote:
> 
> On Fri, May 11, 2012 at 04:17:50PM +0200, Takashi Iwai wrote:
> > Actually the call of snd_pcm_update_hw_ptr() at the loop entry doesn't
> > have to be done at each time, supposing the process of the loop
> > (without wait_for_avail()) is fast enough.
> > 
> > How about the patch below?
> 
> This too seems to work fine on playback.  Thanks.

Good to hear.  I queued it for linux-next now.


thanks,

Takashi

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Fri, May 11, 2012 at 06:31:53PM +0200, Takashi Iwai wrote:
> At Fri, 11 May 2012 16:04:50 +0100,
> Russell King - ARM Linux wrote:
> > 
> > On Fri, May 11, 2012 at 04:17:50PM +0200, Takashi Iwai wrote:
> > > Actually the call of snd_pcm_update_hw_ptr() at the loop entry doesn't
> > > have to be done at each time, supposing the process of the loop
> > > (without wait_for_avail()) is fast enough.
> > > 
> > > How about the patch below?
> > 
> > This too seems to work fine on playback.  Thanks.
> 
> Good to hear.  I queued it for linux-next now.

Please ensure that it gets:

Tested-by: Russell King <rmk+kernel@arm.linux.org.uk>

and not with this address.  Thanks.

Re: ALSA calling pcm_pointer excessively?

[Takashi Iwai]

At Fri, 11 May 2012 17:38:44 +0100,
Russell King - ARM Linux wrote:
> 
> On Fri, May 11, 2012 at 06:31:53PM +0200, Takashi Iwai wrote:
> > At Fri, 11 May 2012 16:04:50 +0100,
> > Russell King - ARM Linux wrote:
> > > 
> > > On Fri, May 11, 2012 at 04:17:50PM +0200, Takashi Iwai wrote:
> > > > Actually the call of snd_pcm_update_hw_ptr() at the loop entry doesn't
> > > > have to be done at each time, supposing the process of the loop
> > > > (without wait_for_avail()) is fast enough.
> > > > 
> > > > How about the patch below?
> > > 
> > > This too seems to work fine on playback.  Thanks.
> > 
> > Good to hear.  I queued it for linux-next now.
> 
> Please ensure that it gets:
> 
> Tested-by: Russell King <rmk+kernel@arm.linux.org.uk>
> 
> and not with this address.  Thanks.

I didn't add your tested-by tag since it wasn't explicitly given, but
now added with the right address.  Thanks.


Takashi

Re: ALSA calling pcm_pointer excessively?

[Trent Piepho]

On Thu, May 10, 2012 at 12:06 PM, Russell King - ARM Linux
<linux@arm.linux.org.uk> wrote:
> The question is - what would cause ALSA to hammer away at the buffer
> like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
> seeing around 75% system CPU time, which really isn't good.
>
> The above was captured while aplay was running, with no apparant audio
> corruption.

I've had this happen, but not with aplay.  I sent something to the
list a few months ago about it.

The problem is triggered when writing to ALSA with writes that are
unequal to the period size and using sampling rate conversion in an
ALSA plugin.  Code in alsa-lib will get into a loop calling poll() on
the pcm fd, and ALSA's poll() calls the pointer method to figure out
if there is enough buffer space free to return or if it poll() should
block.

That is all fine, but rather than write more data when poll() returns,
alsa-lib decides to call poll() again.  So it's stuck in a tight loop
calling poll() which isn't blocking.  Eventually there will be enough
space in the buffer that alsa will write some data and poll() will
block.

Basically poll() will return when there is at least X bytes available
in the buffer.  X = avail_min.  ALSA will only write more data when
there is at least Y bytes free in the buffer.  The bug is X < Y.  This
only happens when sample rate conversion and only if the app doesn't
call snd_pcm_writei() with full periods.  While the available space in
the buffer is > X and < Y, ALSA is in a tight loop calling poll()
which calls the PCM's pointer method.  If X == Y, then this would
never happen.

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Thu, May 10, 2012 at 12:34:19PM -0400, Trent Piepho wrote:
> On Thu, May 10, 2012 at 12:06 PM, Russell King - ARM Linux
> <linux@arm.linux.org.uk> wrote:
> > The question is - what would cause ALSA to hammer away at the buffer
> > like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
> > seeing around 75% system CPU time, which really isn't good.
> >
> > The above was captured while aplay was running, with no apparant audio
> > corruption.
> 
> I've had this happen, but not with aplay.  I sent something to the
> list a few months ago about it.
> 
> The problem is triggered when writing to ALSA with writes that are
> unequal to the period size and using sampling rate conversion in an
> ALSA plugin.

I'm not using any plugins, and there's definitely no sample rate
conversion going on.  I'm basically piping a raw S16_LE stereo file
into "aplay -c2 -r48000 -fS16_LE" and that's the only format the
hardware supports:

Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Plug PCM: Hardware PCM card 0 'Assabet' device 0 subdevice 0

Its setup is:
stream       : PLAYBACK
access       : RW_INTERLEAVED
format       : S16_LE
subformat    : STD
channels     : 2
rate         : 48000
exact rate   : 48000 (48000/1)
msbits       : 16
buffer_size  : 16384
period_size  : 4096
period_time  : 85333
tick_time    : 0
tstamp_mode  : NONE
period_step  : 1
sleep_min    : 0
avail_min    : 4096
xfer_align   : 4096
start_threshold  : 16384
stop_threshold   : 16384
silence_threshold: 0
silence_size : 0
boundary     : 1073741824

Note that this is not using mmap, as ARM is not cache coherent.

Interestingly, if I use -M to aplay to force it to use mmap, things get
a _lot_ better and I only get a lot fewer calls to the pcm_pointer()
method per period.  I've included in this log the DMA engine output
(which shows the raw DMA address - the buffer is 64K aligned) and where
the pcm_pointer() method was called from.

tx_status: addr:c0f14010
soc_dmaengine_pointer: index 1 stat 1 residue 3ff0 cookie 1792 pos 8000 bytes 4010
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_submit: submitting index 0 size 4000 cookie 1795
tx_status: addr:c0f14060
soc_dmaengine_pointer: index 1 stat 1 residue 3fa0 cookie 1792 pos 8000 bytes 4060
snd_pcm_update_hw_ptr0+0x30/0x24c
tx_status: addr:c0f14130
soc_dmaengine_pointer: index 1 stat 1 residue 3ed0 cookie 1792 pos 8000 bytes 4130
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_callback: complete
tx_status: addr:c0f18010
soc_dmaengine_pointer: index 2 stat 1 residue 3ff0 cookie 1793 pos c000 bytes 8010
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_submit: submitting index 1 size 4000 cookie 1796
tx_status: addr:c0f18060
soc_dmaengine_pointer: index 2 stat 1 residue 3fa0 cookie 1793 pos c000 bytes 8060
snd_pcm_update_hw_ptr0+0x30/0x24c
tx_status: addr:c0f18150
soc_dmaengine_pointer: index 2 stat 1 residue 3eb0 cookie 1793 pos c000 bytes 8150
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_callback: complete
tx_status: addr:c0f1c010
soc_dmaengine_pointer: index 3 stat 1 residue 3ff0 cookie 1794 pos 10000 bytes c010
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_submit: submitting index 2 size 4000 cookie 1797
tx_status: addr:c0f1c060
soc_dmaengine_pointer: index 3 stat 1 residue 3fa0 cookie 1794 pos 10000 bytes c060
snd_pcm_update_hw_ptr0+0x30/0x24c
tx_status: addr:c0f1c130
soc_dmaengine_pointer: index 3 stat 1 residue 3ed0 cookie 1794 pos 10000 bytes c130
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_callback: complete
tx_status: addr:c0f10068
soc_dmaengine_pointer: index 0 stat 1 residue 3f98 cookie 1795 pos 4000 bytes 0068
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_submit: submitting index 3 size 4000 cookie 1798
tx_status: addr:c0f100f0
soc_dmaengine_pointer: index 0 stat 1 residue 3f10 cookie 1795 pos 4000 bytes 00f0
snd_pcm_update_hw_ptr0+0x30/0x24c
tx_status: addr:c0f101c8
soc_dmaengine_pointer: index 0 stat 1 residue 3e38 cookie 1795 pos 4000 bytes 01c8
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_callback: complete
tx_status: addr:c0f14010
soc_dmaengine_pointer: index 1 stat 1 residue 3ff0 cookie 1796 pos 8000 bytes 4010
snd_pcm_update_hw_ptr0+0x30/0x24c
soc_dmaengine_submit: submitting index 0 size 4000 cookie 1799
tx_status: addr:c0f14060
soc_dmaengine_pointer: index 1 stat 1 residue 3fa0 cookie 1796 pos 8000 bytes 4060
snd_pcm_update_hw_ptr0+0x30/0x24c
tx_status: addr:c0f14130
soc_dmaengine_pointer: index 1 stat 1 residue 3ed0 cookie 1796 pos 8000 bytes 4130
snd_pcm_update_hw_ptr0+0x30/0x24c

Re: ALSA calling pcm_pointer excessively?

[Jassi Brar]

On Thu, May 10, 2012 at 9:36 PM, Russell King - ARM Linux
<linux@arm.linux.org.uk> wrote:
>
> The question is - what would cause ALSA to hammer away at the buffer
> like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
> seeing around 75% system CPU time, which really isn't good.
>
> The above was captured while aplay was running, with no apparant audio
> corruption.
>
> Any ideas?
>
I believe it's because the pcm's write tries to keep the data in ring
buffer filled
upto brim and keeps polling the dma position till it keeps reporting
some progress.

I think if you could avoid that behavior if your driver carefully
keeps negligible
progresses to itself and report only considerable ones. Basically, core would
stop polling and wait on queue when two pointer calls return same value i.e no
progress.
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: ALSA calling pcm_pointer excessively?

[Trent Piepho]

On Thu, May 10, 2012 at 1:00 PM, Jassi Brar <jassisinghbrar@gmail.com> wrote:
> On Thu, May 10, 2012 at 9:36 PM, Russell King - ARM Linux
> <linux@arm.linux.org.uk> wrote:
>>
>> The question is - what would cause ALSA to hammer away at the buffer
>> like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
>> seeing around 75% system CPU time, which really isn't good.
>>
>> The above was captured while aplay was running, with no apparant audio
>> corruption.
>>
>> Any ideas?
>>
> I believe it's because the pcm's write tries to keep the data in ring
> buffer filled
> upto brim and keeps polling the dma position till it keeps reporting
> some progress.

Seems like it should sleep until avail_min frames are empty?

Re: ALSA calling pcm_pointer excessively?

[Russell King - ARM Linux]

On Thu, May 10, 2012 at 10:30:44PM +0530, Jassi Brar wrote:
> On Thu, May 10, 2012 at 9:36 PM, Russell King - ARM Linux
> <linux@arm.linux.org.uk> wrote:
> >
> > The question is - what would cause ALSA to hammer away at the buffer
> > like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
> > seeing around 75% system CPU time, which really isn't good.
> >
> > The above was captured while aplay was running, with no apparant audio
> > corruption.
> >
> > Any ideas?
> >
> I believe it's because the pcm's write tries to keep the data in ring
> buffer filled
> upto brim and keeps polling the dma position till it keeps reporting
> some progress.
> 
> I think if you could avoid that behavior if your driver carefully
> keeps negligible
> progresses to itself and report only considerable ones. Basically, core would
> stop polling and wait on queue when two pointer calls return same value i.e no
> progress.

You _could_ but why should drivers work around silly behaviour in the
ALSA core?

Re: ALSA calling pcm_pointer excessively?

[Jassi Brar]

On Thu, May 10, 2012 at 10:34 PM, Russell King - ARM Linux
<linux@arm.linux.org.uk> wrote:
> On Thu, May 10, 2012 at 10:30:44PM +0530, Jassi Brar wrote:
>> On Thu, May 10, 2012 at 9:36 PM, Russell King - ARM Linux
>> <linux@arm.linux.org.uk> wrote:
>> >
>> > The question is - what would cause ALSA to hammer away at the buffer
>> > like that - checking it every 16 or 8 DMA bytes transferred?  I'm also
>> > seeing around 75% system CPU time, which really isn't good.
>> >
>> > The above was captured while aplay was running, with no apparant audio
>> > corruption.
>> >
>> > Any ideas?
>> >
>> I believe it's because the pcm's write tries to keep the data in ring
>> buffer filled
>> upto brim and keeps polling the dma position till it keeps reporting
>> some progress.
>>
>> I think if you could avoid that behavior if your driver carefully
>> keeps negligible
>> progresses to itself and report only considerable ones. Basically, core would
>> stop polling and wait on queue when two pointer calls return same value i.e no
>> progress.
>
> You _could_ but why should drivers work around silly behaviour in the
> ALSA core?
>
One reason I could think of is to save us from under-runs for as long
as possible.
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel