Hang in snd_pcm_writei with alsa-pulse plugin

Hang in snd_pcm_writei with alsa-pulse plugin

[Matthew Gregan]

[-- Attachment #1: Type: text/plain, Size: 3087 bytes --]

Hi,

I think I'm seeing a bug in the alsa-pulse plugin where the buffer
management ends up corrupt and results in a deadlock waiting for free buffer
space.  This occurs when resuming from pause using snd_pcm_pause.  After
resuming, my application tries to write a fixed block of data, expecting
snd_pcm_writei to block if the data is larger than the available buffer size
(the result of snd_pcm_avail_update).

I originally observed this in the wild in Firefox, which pauses and resumes
the sound device whenever network buffering occurs.  I'm planning to include
the workaround mentioned below in the next Firefox release (Mozilla bug
573924).

What happens is that, after resuming with snd_pcm_pause, a call to
snd_pcm_writei never returns.  This happens on the write call that would
have exceeded the available buffer size, which I would expect to block only
until sufficient buffer space became available.

It's possible to get into a similar situation using SND_PCM_NONBLOCK and
waiting on the sound device if it returns EAGAIN, except that snd_pcm_writei
always returns EAGAIN and snd_pcm_wait returns 1 immediately, resulting in a
tight loop in the calling code.

I discovered that I can reliably workaround the problem by ensuring the
first writes after resuming from pause are never larger than what
snd_pcm_avail_update returns.  After writing enough to fill (but not exceed)
the available buffer size, the code returns to the fixed buffer size per
write strategy and continues as normal.

The problem occurs with the following stack:

#0  __poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=<value optimized out>)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#1  snd1_pcm_wait_nocheck (pcm=0x1b9a780, timeout=-1)
    at pcm.c:2367
#2  snd1_pcm_write_areas (pcm=0x1b9a780, 
    areas=0x7fff4ce9b890, offset=<value optimized out>, size=30000, 
    func=0x339ba91d10 <ioplug_priv_transfer_areas>) at pcm.c:6655
#3  snd_pcm_ioplug_writei (pcm=0x1b9a780, 
    buffer=<value optimized out>, size=30000) at pcm_ioplug.c:561
#4  bwrite (pcm=0x1b9a780, towrite=30000) at
    atest2.c:29
#5  main (argc=1, argv=0x7fff4ce9ba68) at atest2.c:86

I'm Fedora 13 x86_64 with all updates from updates-testing.  ALSA is
1.0.22-1, PulseAudio is 0.9.21-6, and the kernel is 2.6.34.7-61.  I've also
tested against the current git versions of alsa-libs and alsa-plugins and
can still reproduce the problem.

I've attached a simple test program that reproduces this problem reliably on
my machine.  It writes a period sized buffer in a loop, waiting half a
period until the next attempt.  Every few iterations, it pauses the sound
device for half a period and then resumes it.  It usually hangs within 2-3
pause/resume cycles.  Running the test with "-r" enables the recovery code I
mentioned above.  It never hangs when tested using the hardware ALSA backend
with alsa-pulse disabled, but my sound hardware doesn't seem to support
snd_pcm_pause.

Cheers,
-mjg
-- 
Matthew Gregan                     |/
                                  /|                    kinetik@flim.org

[-- Attachment #2: atest2.c --]
[-- Type: text/x-csrc, Size: 2262 bytes --]

#include <assert.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <alsa/asoundlib.h>

#define RATE 48000

snd_pcm_uframes_t setup(snd_pcm_t ** pcm)
{
  snd_pcm_uframes_t bsize, psize;

  assert(snd_pcm_open(pcm, "default", SND_PCM_STREAM_PLAYBACK, 0) == 0);
  assert(snd_pcm_set_params(*pcm, SND_PCM_FORMAT_S16_LE,
                            SND_PCM_ACCESS_RW_INTERLEAVED,
                            1, RATE, 1, 250000) == 0);
  assert(snd_pcm_get_params(*pcm, &bsize, &psize) == 0);
  assert(bsize / psize >= 4);

  return psize;
}

void bwrite(snd_pcm_t * pcm, snd_pcm_sframes_t towrite)
{
  int r;
  char * garbage;

  garbage = calloc(1, towrite);
  r = snd_pcm_writei(pcm, garbage, towrite);
  free(garbage);

  if (r < 0) {
    fprintf(stderr, "bwrite error recovery\n");
    snd_pcm_recover(pcm, r, 1);
  }
}

snd_pcm_sframes_t fill(snd_pcm_t * pcm)
{
  snd_pcm_sframes_t avail;

  avail = snd_pcm_avail_update(pcm);
  if (avail < 0) {
    fprintf(stderr, "fill error recovery\n");
    snd_pcm_recover(pcm, avail, 1);
    avail = snd_pcm_avail_update(pcm);
  }
  if (avail) {
    bwrite(pcm, avail);
  }

  return avail;
}

int main(int argc, char * argv[])
{
  snd_pcm_t * pcm;
  snd_pcm_uframes_t psize;
  int pause = 0, count = 0, recovery = 0;

  if (argc == 2 && argv[1][0] == '-' && argv[1][1] == 'r') {
    recovery = 1;
  }

  /* set up a mono output device at RATE Hz with at least 4 periods */
  psize = setup(&pcm);

  /* prefill sound buffers and begin playback */
  fill(pcm);

  while (++count) {
    if (pause || count % 7 == 0) {
      fprintf(stderr, pause ? "resuming playback\n" : "pausing playback\n");
      pause = !pause;
      snd_pcm_pause(pcm, pause);

      /* if resuming playback and recovery enabled, fill sound buffers */
      if (recovery && !pause) {
        fprintf(stderr, "recovery, wrote %d frames\n", (int) fill(pcm));
      }
    }

    /* if not paused, write a period of sound data */
    if (!pause) {
      snd_pcm_sframes_t avail = snd_pcm_avail_update(pcm);
      bwrite(pcm, psize);
      fprintf(stderr, "playback, wrote %u frames (needed %d)\n", (unsigned int) psize, (int) avail);
    }

    /* sleep for half a period */
    usleep(psize * 1000000 / RATE / 2);
  }

  return 0;
}

[-- Attachment #3: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Colin Guthrie]

'Twas brillig, and Matthew Gregan at 01/11/10 01:38 did gyre and gimble:
> Hi,
> 
> I think I'm seeing a bug in the alsa-pulse plugin where the buffer
> management ends up corrupt and results in a deadlock waiting for free buffer
> space.  This occurs when resuming from pause using snd_pcm_pause.  After
> resuming, my application tries to write a fixed block of data, expecting
> snd_pcm_writei to block if the data is larger than the available buffer size
> (the result of snd_pcm_avail_update).
> 
> I originally observed this in the wild in Firefox, which pauses and resumes
> the sound device whenever network buffering occurs.  I'm planning to include
> the workaround mentioned below in the next Firefox release (Mozilla bug
> 573924).
> 
> What happens is that, after resuming with snd_pcm_pause, a call to
> snd_pcm_writei never returns.  This happens on the write call that would
> have exceeded the available buffer size, which I would expect to block only
> until sufficient buffer space became available.
> 
> It's possible to get into a similar situation using SND_PCM_NONBLOCK and
> waiting on the sound device if it returns EAGAIN, except that snd_pcm_writei
> always returns EAGAIN and snd_pcm_wait returns 1 immediately, resulting in a
> tight loop in the calling code.
> 
> I discovered that I can reliably workaround the problem by ensuring the
> first writes after resuming from pause are never larger than what
> snd_pcm_avail_update returns.  After writing enough to fill (but not exceed)
> the available buffer size, the code returns to the fixed buffer size per
> write strategy and continues as normal.
> 
> The problem occurs with the following stack:
> 
> #0  __poll (fds=<value optimized out>, 
>     nfds=<value optimized out>, timeout=<value optimized out>)
>     at ../sysdeps/unix/sysv/linux/poll.c:87
> #1  snd1_pcm_wait_nocheck (pcm=0x1b9a780, timeout=-1)
>     at pcm.c:2367
> #2  snd1_pcm_write_areas (pcm=0x1b9a780, 
>     areas=0x7fff4ce9b890, offset=<value optimized out>, size=30000, 
>     func=0x339ba91d10 <ioplug_priv_transfer_areas>) at pcm.c:6655
> #3  snd_pcm_ioplug_writei (pcm=0x1b9a780, 
>     buffer=<value optimized out>, size=30000) at pcm_ioplug.c:561
> #4  bwrite (pcm=0x1b9a780, towrite=30000) at
>     atest2.c:29
> #5  main (argc=1, argv=0x7fff4ce9ba68) at atest2.c:86
> 
> I'm Fedora 13 x86_64 with all updates from updates-testing.  ALSA is
> 1.0.22-1, PulseAudio is 0.9.21-6, and the kernel is 2.6.34.7-61.  I've also
> tested against the current git versions of alsa-libs and alsa-plugins and
> can still reproduce the problem.
> 
> I've attached a simple test program that reproduces this problem reliably on
> my machine.  It writes a period sized buffer in a loop, waiting half a
> period until the next attempt.  Every few iterations, it pauses the sound
> device for half a period and then resumes it.  It usually hangs within 2-3
> pause/resume cycles.  Running the test with "-r" enables the recovery code I
> mentioned above.  It never hangs when tested using the hardware ALSA backend
> with alsa-pulse disabled, but my sound hardware doesn't seem to support
> snd_pcm_pause.

Reproduced here I presume:
[colin@jimmy pulseaudio (master)]$ ./atest2
playback, wrote 3000 frames (needed 0)
playback, wrote 3000 frames (needed 1480)
playback, wrote 3000 frames (needed 2643)
playback, wrote 3000 frames (needed 3526)
playback, wrote 3000 frames (needed 526)
playback, wrote 3000 frames (needed 1313)
pausing playback
resuming playback
^C
[colin@jimmy pulseaudio (master)]$ ./atest2
playback, wrote 3000 frames (needed 0)
playback, wrote 3000 frames (needed 1584)
playback, wrote 3000 frames (needed 2764)
playback, wrote 3000 frames (needed 3648)
playback, wrote 3000 frames (needed 648)
playback, wrote 3000 frames (needed 1426)
pausing playback
resuming playback
^C

This is with latest PA from stable-queue.

Not sure whether this is "expected" or not, but it's probably worth you
posting this on PA devel list too for some further thought if this
thread doesn't garner much response here.

Cheers
Col




-- 

Colin Guthrie
gmane(at)colin.guthr.ie
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mageia Contributor [http://www.mageia.org/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/2 Colin Guthrie <gmane@colin.guthr.ie>

> 'Twas brillig, and Matthew Gregan at 01/11/10 01:38 did gyre and gimble:
> > Hi,
> >
> > I think I'm seeing a bug in the alsa-pulse plugin where the buffer
> > management ends up corrupt and results in a deadlock waiting for free
> buffer
> > space.  This occurs when resuming from pause using snd_pcm_pause.  After
> > resuming, my application tries to write a fixed block of data, expecting
> > snd_pcm_writei to block if the data is larger than the available buffer
> size
> > (the result of snd_pcm_avail_update).
> >
> > I originally observed this in the wild in Firefox, which pauses and
> resumes
> > the sound device whenever network buffering occurs.  I'm planning to
> include
> > the workaround mentioned below in the next Firefox release (Mozilla bug
> > 573924).
> >
> > What happens is that, after resuming with snd_pcm_pause, a call to
> > snd_pcm_writei never returns.  This happens on the write call that would
> > have exceeded the available buffer size, which I would expect to block
> only
> > until sufficient buffer space became available.
> >
> > It's possible to get into a similar situation using SND_PCM_NONBLOCK and
> > waiting on the sound device if it returns EAGAIN, except that
> snd_pcm_writei
> > always returns EAGAIN and snd_pcm_wait returns 1 immediately, resulting
> in a
> > tight loop in the calling code.
> >
> > I discovered that I can reliably workaround the problem by ensuring the
> > first writes after resuming from pause are never larger than what
> > snd_pcm_avail_update returns.  After writing enough to fill (but not
> exceed)
> > the available buffer size, the code returns to the fixed buffer size per
> > write strategy and continues as normal.
> >
> > The problem occurs with the following stack:
> >
> > #0  __poll (fds=<value optimized out>,
> >     nfds=<value optimized out>, timeout=<value optimized out>)
> >     at ../sysdeps/unix/sysv/linux/poll.c:87
> > #1  snd1_pcm_wait_nocheck (pcm=0x1b9a780, timeout=-1)
> >     at pcm.c:2367
> > #2  snd1_pcm_write_areas (pcm=0x1b9a780,
> >     areas=0x7fff4ce9b890, offset=<value optimized out>, size=30000,
> >     func=0x339ba91d10 <ioplug_priv_transfer_areas>) at pcm.c:6655
> > #3  snd_pcm_ioplug_writei (pcm=0x1b9a780,
> >     buffer=<value optimized out>, size=30000) at pcm_ioplug.c:561
> > #4  bwrite (pcm=0x1b9a780, towrite=30000) at
> >     atest2.c:29
> > #5  main (argc=1, argv=0x7fff4ce9ba68) at atest2.c:86
> >
> > I'm Fedora 13 x86_64 with all updates from updates-testing.  ALSA is
> > 1.0.22-1, PulseAudio is 0.9.21-6, and the kernel is 2.6.34.7-61.  I've
> also
> > tested against the current git versions of alsa-libs and alsa-plugins and
> > can still reproduce the problem.
> >
> > I've attached a simple test program that reproduces this problem reliably
> on
> > my machine.  It writes a period sized buffer in a loop, waiting half a
> > period until the next attempt.  Every few iterations, it pauses the sound
> > device for half a period and then resumes it.  It usually hangs within
> 2-3
> > pause/resume cycles.  Running the test with "-r" enables the recovery
> code I
> > mentioned above.  It never hangs when tested using the hardware ALSA
> backend
> > with alsa-pulse disabled, but my sound hardware doesn't seem to support
> > snd_pcm_pause.
>
> Reproduced here I presume:
> [colin@jimmy pulseaudio (master)]$ ./atest2
> playback, wrote 3000 frames (needed 0)
> playback, wrote 3000 frames (needed 1480)
> playback, wrote 3000 frames (needed 2643)
> playback, wrote 3000 frames (needed 3526)
> playback, wrote 3000 frames (needed 526)
> playback, wrote 3000 frames (needed 1313)
> pausing playback
> resuming playback
> ^C
> [colin@jimmy pulseaudio (master)]$ ./atest2
> playback, wrote 3000 frames (needed 0)
> playback, wrote 3000 frames (needed 1584)
> playback, wrote 3000 frames (needed 2764)
> playback, wrote 3000 frames (needed 3648)
> playback, wrote 3000 frames (needed 648)
> playback, wrote 3000 frames (needed 1426)
> pausing playback
> resuming playback
> ^C
>
> This is with latest PA from stable-queue.
>
> Not sure whether this is "expected" or not, but it's probably worth you
> posting this on PA devel list too for some further thought if this
> thread doesn't garner much response here.
>
>
No much response because there are bugs in atest2.c

  /* prefill sound buffers and begin playback */
  fill(pcm);

  while (++count) {

The program had filled the buffer but the output does not indicate those
write


I can confirm that the program seem hang after a few pause/unpause when
using alsa-pulse plugin

However it assert when using hw device

  assert(bsize / psize >= 4);

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Matthew Gregan]

At 2010-11-02T10:43:54+0800, Raymond Yau wrote:
> No much response because there are bugs in atest2.c
> 
>   /* prefill sound buffers and begin playback */
>   fill(pcm);
> 
>   while (++count) {
> 
> The program had filled the buffer but the output does not indicate those
> write

This doesn't affect the result of the testcase.  count is only used to pause
and resume less frequently than every iteration of the write loop.

> I can confirm that the program seem hang after a few pause/unpause when
> using alsa-pulse plugin
> 
> However it assert when using hw device
> 
>   assert(bsize / psize >= 4);

The assert is present because I've only tested on systems where this
assertion holds true.  It's likely that the loop timing would need to be
changed to work correctly in other cases.

Thanks for confirming that you can reproduce the problem.  I've since
discovered that it's possible to produce the same problem with the
PulseAudio API directly, so I'll take this up on pulseaudio-discuss@.

Cheers,
-mjg
-- 
Matthew Gregan                     |/
                                  /|                    kinetik@flim.org

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/2 Matthew Gregan <kinetik@flim.org>

> At 2010-11-02T10:43:54+0800, Raymond Yau wrote:
> > No much response because there are bugs in atest2.c
> >
> >   /* prefill sound buffers and begin playback */
> >   fill(pcm);
> >
> >   while (++count) {
> >
> > The program had filled the buffer but the output does not indicate those
> > write
>
> This doesn't affect the result of the testcase.  count is only used to
> pause
> and resume less frequently than every iteration of the write loop.
>
> > I can confirm that the program seem hang after a few pause/unpause when
> > using alsa-pulse plugin
> >
> > However it assert when using hw device
> >
> >   assert(bsize / psize >= 4);
>
> The assert is present because I've only tested on systems where this
> assertion holds true.  It's likely that the loop timing would need to be
> changed to work correctly in other cases.
>
> Thanks for confirming that you can reproduce the problem.  I've since
> discovered that it's possible to produce the same problem with the
> PulseAudio API directly, so I'll take this up on pulseaudio-discuss@.
>
> Cheers,
> -mjg
>

The interesting thing is it did not hang when I increase the sleep time to
one period


    /* sleep for half a period */
+    usleep(psize * 1000000 / RATE );
-    usleep(psize * 1000000 / RATE /2 );

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/1 Matthew Gregan <kinetik@flim.org>

> Hi,
>
>
> I've attached a simple test program that reproduces this problem reliably
> on
> my machine.  It writes a period sized buffer in a loop, waiting half a
> period until the next attempt.  Every few iterations, it pauses the sound
> device for half a period and then resumes it.  It usually hangs within 2-3
> pause/resume cycles.  Running the test with "-r" enables the recovery code
> I
> mentioned above.  It never hangs when tested using the hardware ALSA
> backend
> with alsa-pulse disabled, but my sound hardware doesn't seem to support
> snd_pcm_pause.
>
>
when increase the sleep time from half period to one period, the hang occur
after around 50 pause/resume cycles.

did PA server  stop sending data to the sound card immediately when your
program pause ?

But cannot reproduce your problem using the "pause" function of aplay

which sound card are you using and did you change the pulseaudlo daemon.conf
?

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Matthew Gregan]

At 2010-11-04T11:29:39+0800, Raymond Yau wrote:
> when increase the sleep time from half period to one period, the hang occur
> after around 50 pause/resume cycles.
> 
> did PA server  stop sending data to the sound card immediately when your
> program pause ?

Yes.  As far as I can tell, at least.

> But cannot reproduce your problem using the "pause" function of aplay
> 
> which sound card are you using and did you change the pulseaudlo daemon.conf
> ?

I'm using the default daemon.conf shipped with Fedora 13, which contains
nothing but comments and newlines.  The sound card is: Intel Corporation 5
Series/3400 Series Chipset High Definition Audio (rev 06) in a Lenovo W510.
I've seen this problem on other machines (including in VMWare and VirtualBox
based VMs) too, but I don't know what sound hardware they were using.

Cheers,
-mjg
-- 
Matthew Gregan                     |/
                                  /|                    kinetik@flim.org

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/2 Matthew Gregan <kinetik@flim.org>

> At 2010-11-02T10:43:54+0800, Raymond Yau wrote:
>
>
> Thanks for confirming that you can reproduce the problem.  I've since
> discovered that it's possible to produce the same problem with the
> PulseAudio API directly, so I'll take this up on pulseaudio-discuss@.
>
> Cheers,
> -mjg
>

A buggy PA client can easily crash the PA server

http://0pointer.de/lennart/projects/pulseaudio/doxygen/sample.html

PulseAudio supports any sample rate between 1 Hz and 192000 Hz

http://thread.gmane.org/gmane.comp.audio.pulseaudio.general/7759

Just change the rate of your program ptest.c from 48000 Hz to 1 Hz , this
will abort the PA server

E: sink-input.c: Assertion 'tchunk.length > 0' failed at
pulsecore/sink-input.c:551, function pa_sink_input_peek(). Aborting.

Seem that PA server did not check whether the info send by the PA client is
really supported by the server

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/1 Matthew Gregan <kinetik@flim.org>

> Hi,
>
> I think I'm seeing a bug in the alsa-pulse plugin where the buffer
> management ends up corrupt and results in a deadlock waiting for free
> buffer
> space.  This occurs when resuming from pause using snd_pcm_pause.  After
> resuming, my application tries to write a fixed block of data, expecting
> snd_pcm_writei to block if the data is larger than the available buffer
> size
> (the result of snd_pcm_avail_update).
>
> I originally observed this in the wild in Firefox, which pauses and resumes
> the sound device whenever network buffering occurs.  I'm planning to
> include
> the workaround mentioned below in the next Firefox release (Mozilla bug
> 573924).
>
> What happens is that, after resuming with snd_pcm_pause, a call to
> snd_pcm_writei never returns.  This happens on the write call that would
> have exceeded the available buffer size, which I would expect to block only
> until sufficient buffer space became available.
>

It depend on whether pulse_write wait until all requested frames are played
or just put to the playback ring buffer

especailly when your program write audio more than the available free buffer
space

http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.htm

If the blocking behaviour is selected and it is running, then routine waits
until all requested frames are played or put to the playback ring buffer.
The returned number of frames can be less only if a signal or underrun
occurred.

If the non-blocking behaviour is selected, then routine doesn't wait at all.







>
> It's possible to get into a similar situation using SND_PCM_NONBLOCK and
> waiting on the sound device if it returns EAGAIN, except that
> snd_pcm_writei
> always returns EAGAIN and snd_pcm_wait returns 1 immediately, resulting in
> a
> tight loop in the calling code.
>
> I discovered that I can reliably workaround the problem by ensuring the
> first writes after resuming from pause are never larger than what
> snd_pcm_avail_update returns.  After writing enough to fill (but not
> exceed)
> the available buffer size, the code returns to the fixed buffer size per
> write strategy and continues as normal.
>
> The problem occurs with the following stack:
>
> #0  __poll (fds=<value optimized out>,
>    nfds=<value optimized out>, timeout=<value optimized out>)
>    at ../sysdeps/unix/sysv/linux/poll.c:87
> #1  snd1_pcm_wait_nocheck (pcm=0x1b9a780, timeout=-1)
>    at pcm.c:2367
> #2  snd1_pcm_write_areas (pcm=0x1b9a780,
>    areas=0x7fff4ce9b890, offset=<value optimized out>, size=30000,
>    func=0x339ba91d10 <ioplug_priv_transfer_areas>) at pcm.c:6655
> #3  snd_pcm_ioplug_writei (pcm=0x1b9a780,
>    buffer=<value optimized out>, size=30000) at pcm_ioplug.c:561
> #4  bwrite (pcm=0x1b9a780, towrite=30000) at
>    atest2.c:29
> #5  main (argc=1, argv=0x7fff4ce9ba68) at atest2.c:86
>
> I'm Fedora 13 x86_64 with all updates from updates-testing.  ALSA is
> 1.0.22-1, PulseAudio is 0.9.21-6, and the kernel is 2.6.34.7-61.  I've also
> tested against the current git versions of alsa-libs and alsa-plugins and
> can still reproduce the problem.
>
> I've attached a simple test program that reproduces this problem reliably
> on
> my machine.  It writes a period sized buffer in a loop, waiting half a
> period until the next attempt.  Every few iterations, it pauses the sound
> device for half a period and then resumes it.  It usually hangs within 2-3
> pause/resume cycles.  Running the test with "-r" enables the recovery code
> I
> mentioned above.  It never hangs when tested using the hardware ALSA
> backend
> with alsa-pulse disabled, but my sound hardware doesn't seem to support
> snd_pcm_pause.
>
> Cheers,
> -mjg
> --
> Matthew Gregan
>
>

Re: Hang in snd_pcm_writei with alsa-pulse plugin

[Raymond Yau]

2010/11/1 Matthew Gregan <kinetik@flim.org>

> Hi,
>
> I think I'm seeing a bug in the alsa-pulse plugin where the buffer
> management ends up corrupt and results in a deadlock waiting for free
> buffer
> space.  This occurs when resuming from pause using snd_pcm_pause.  After
> resuming, my application tries to write a fixed block of data, expecting
> snd_pcm_writei to block if the data is larger than the available buffer
> size
> (the result of snd_pcm_avail_update).
>
> I originally observed this in the wild in Firefox, which pauses and resumes
> the sound device whenever network buffering occurs.  I'm planning to
> include
> the workaround mentioned below in the next Firefox release (Mozilla bug
> 573924).
>
> What happens is that, after resuming with snd_pcm_pause, a call to
> snd_pcm_writei never returns.  This happens on the write call that would
> have exceeded the available buffer size, which I would expect to block only
> until sufficient buffer space became available.
>
> It's possible to get into a similar situation using SND_PCM_NONBLOCK and
> waiting on the sound device if it returns EAGAIN, except that
> snd_pcm_writei
> always returns EAGAIN and snd_pcm_wait returns 1 immediately, resulting in
> a
> tight loop in the calling code.
>
> I discovered that I can reliably workaround the problem by ensuring the
> first writes after resuming from pause are never larger than what
> snd_pcm_avail_update returns.  After writing enough to fill (but not
> exceed)
> the available buffer size, the code returns to the fixed buffer size per
> write strategy and continues as normal.
>
> The problem occurs with the following stack:
>
> #0  __poll (fds=<value optimized out>,
>    nfds=<value optimized out>, timeout=<value optimized out>)
>    at ../sysdeps/unix/sysv/linux/poll.c:87
> #1  snd1_pcm_wait_nocheck (pcm=0x1b9a780, timeout=-1)
>    at pcm.c:2367
> #2  snd1_pcm_write_areas (pcm=0x1b9a780,
>    areas=0x7fff4ce9b890, offset=<value optimized out>, size=30000,
>    func=0x339ba91d10 <ioplug_priv_transfer_areas>) at pcm.c:6655
> #3  snd_pcm_ioplug_writei (pcm=0x1b9a780,
>    buffer=<value optimized out>, size=30000) at pcm_ioplug.c:561
> #4  bwrite (pcm=0x1b9a780, towrite=30000) at
>    atest2.c:29
> #5  main (argc=1, argv=0x7fff4ce9ba68) at atest2.c:86
>
> I'm Fedora 13 x86_64 with all updates from updates-testing.  ALSA is
> 1.0.22-1, PulseAudio is 0.9.21-6, and the kernel is 2.6.34.7-61.  I've also
> tested against the current git versions of alsa-libs and alsa-plugins and
> can still reproduce the problem.
>
> I've attached a simple test program that reproduces this problem reliably
> on
> my machine.  It writes a period sized buffer in a loop, waiting half a
> period until the next attempt.  Every few iterations, it pauses the sound
> device for half a period and then resumes it.  It usually hangs within 2-3
> pause/resume cycles.  Running the test with "-r" enables the recovery code
> I
> mentioned above.  It never hangs when tested using the hardware ALSA
> backend
> with alsa-pulse disabled, but my sound hardware doesn't seem to support
> snd_pcm_pause.
>
> using your test program and follow the instruction in
http://colin.guthr.ie/2010/09/compiling-and-running-pulseaudio-from-git/

It seem that PA server lost some of the audio at rewind when it resume from
cork and uncork, if you enable DEBUG_TIMING, in alsa-sink.c  PA server seem
still writing

Are there any statistics about how much data received from the client and
how much data PA server wrute to the sound card


: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 351936 bytes.
D: alsa-sink.c: before: 87984
D: alsa-sink.c: after: 87984
D: alsa-sink.c: Rewound 351936 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 2337
D: sink-input.c: Have to rewind 351936 bytes on render memblockq.
D: source.c: Processing rewind...
D: core-subscribe.c: Dropped redundant event due to change event.
D: reserve-wrap.c: Device lock status of
reserve-monitor-wrapper@Audio1changed: not busy
D: protocol-dbus.c: Interface org.PulseAudio.Core1.Stream added for object
/org/pulseaudio/core1/playback_stream0
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10032 bytes.
D: alsa-sink.c: before: 2508
D: alsa-sink.c: after: 2508
D: alsa-sink.c: Rewound 10032 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 2259
D: sink-input.c: Have to rewind 10032 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10704 bytes.
D: alsa-sink.c: before: 2676
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: alsa-sink.c: after: 2676
D: alsa-sink.c: Rewound 10704 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 2012
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10672 bytes.
D: alsa-sink.c: before: 2668
D: alsa-sink.c: after: 2668
D: alsa-sink.c: Rewound 10672 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 2012
D: sink-input.c: Have to rewind 10672 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: alsa-sink.c: Limited to 10672 bytes.
D: alsa-sink.c: before: 2668
D: alsa-sink.c: after: 2668
D: alsa-sink.c: Rewound 10672 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1720
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10672 bytes.
D: alsa-sink.c: before: 2668
D: alsa-sink.c: after: 2668
D: alsa-sink.c: Rewound 10672 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1690
D: sink-input.c: Have to rewind 10672 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: alsa-sink.c: Limited to 10704 bytes.
D: alsa-sink.c: before: 2676
D: alsa-sink.c: after: 2676
D: alsa-sink.c: Rewound 10704 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1457
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: alsa-sink.c: Limited to 10672 bytes.
D: alsa-sink.c: before: 2668
D: alsa-sink.c: after: 2668
D: alsa-sink.c: Rewound 10672 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1369
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10672 bytes.
D: alsa-sink.c: before: 2668
D: alsa-sink.c: after: 2668
D: alsa-sink.c: Rewound 10672 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1372
D: sink-input.c: Have to rewind 10672 bytes on render memblockq.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: alsa-sink.c: Limited to 10704 bytes.
D: alsa-sink.c: before: 2676
D: alsa-sink.c: after: 2676
D: alsa-sink.c: Rewound 10704 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1352
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes idle,
timeout in 5 seconds.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: sink-input.c: Requesting rewind due to uncorking
D: alsa-sink.c: Requested to rewind 352768 bytes.
D: module-suspend-on-idle.c: Sink alsa_output.1.analog-stereo becomes busy.
D: alsa-sink.c: Limited to 10704 bytes.
D: alsa-sink.c: before: 2676
D: alsa-sink.c: after: 2676
D: alsa-sink.c: Rewound 10704 bytes.
D: sink.c: Processing rewind...
D: sink.c: latency = 1409
D: source.c: Processing rewind...
D: sink-input.c: Requesting rewind due to corking