Duplicate wake-ups in pcm_lib.c

Duplicate wake-ups in pcm_lib.c

[pl bossart]

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

Thanks to Takashi's advice, I managed to find out the reason why I was
seeing null events returned by poll(). This could explain why
PulseAudio doesn't seem to sleep much. It turns out that we have two
calls to wakeup() in pcm_lib.c, and a nice race condition it seems.
See the log below.

A wake-up is generated during the period interrupt, and a second
wake-up is generated during the write loop, after the application was
awaken but just before the pointers are updated. This second wake-up
shouldn't exist, since the write loop actually fills the ring buffer.
By the time the second wake-up is actually handled, there's really no
space left in the buffer and a null event is generated; it'll wake-up
the application a second time for nothing. Maybe we should move the
call to snd_pcm_update_hw_ptr() after the transfer took place?

Can anyone apply the attached patches (only adds printks) and confirm
this issue on their platforms? That would be very useful.
Happy holidays everyone
- Pierre


alsa-lib/test/pcm --verbose -Dhw -c2 -r48000 -f440  --method write_and_poll

[  371.369865] snd_intel8x0_interrupt
[  371.369876]  snd_intel8x0_update
[  371.369884] snd_pcm_period_elapsed
[  371.369890]  snd_pcm_update_hw_ptr_interrupt
[  371.369900]    snd_pcm_update_hw_ptr_post
[  371.369909]     wakeup in snd_pcm_update_hw_ptr_post
sound/core/pcm_lib.c: 214, avail 8194, avail_min 8192
[  371.369935] ALSA: poll event  POLLOUT|POLLWRNORM, avail 8194 avail_min 8192
[  371.375449] snd_pcm_lib_write1: in
[  371.375457] snd_pcm_lib_write1 loop
[  371.375462]  snd_pcm_update_hw_ptr
[  371.375472]    snd_pcm_update_hw_ptr_post
[  371.375481]     wakeup in snd_pcm_update_hw_ptr_post
sound/core/pcm_lib.c: 214, avail 8462, avail_min 8192

>>Between these two points, the appl_ptr is updated, and there's no space left in the buffer. The wake-up is generated too early.

[  371.375514] snd_pcm_lib_write1: out
[  371.375524] ALSA: null poll event, avail 270 avail_min 8192
[  371.540532] snd_intel8x0_interrupt
[  371.540542]  snd_intel8x0_update
[  371.540551] snd_pcm_period_elapsed
[  371.540556]  snd_pcm_update_hw_ptr_interrupt
[  371.540566]    snd_pcm_update_hw_ptr_post
[  371.540575]     wakeup in snd_pcm_update_hw_ptr_post
sound/core/pcm_lib.c: 214, avail 8194, avail_min 8192
[  371.540601] ALSA: poll event  POLLOUT|POLLWRNORM, avail 8194 avail_min 8192
[  371.543734] snd_pcm_lib_write1: in
[  371.543741] snd_pcm_lib_write1 loop
[  371.543746]  snd_pcm_update_hw_ptr
[  371.543755]    snd_pcm_update_hw_ptr_post
[  371.543764]     wakeup in snd_pcm_update_hw_ptr_post
sound/core/pcm_lib.c: 214, avail 8347, avail_min 8192
[  371.543797] snd_pcm_lib_write1: out
[  371.543807] ALSA: null poll event, avail 155 avail_min 8192

[-- Attachment #2: core_pcm.patch --]
[-- Type: text/x-patch, Size: 4359 bytes --]

diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c
index 30f4108..d6f831f 100644
--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -191,6 +191,8 @@ static int snd_pcm_update_hw_ptr_post(struct snd_pcm_substream *substream,
 {
 	snd_pcm_uframes_t avail;
 
+        printk(KERN_ERR "   snd_pcm_update_hw_ptr_post");
+        
 	if (substream->stream == SNDRV_PCM_STREAM_PLAYBACK)
 		avail = snd_pcm_playback_avail(runtime);
 	else
@@ -208,8 +210,10 @@ static int snd_pcm_update_hw_ptr_post(struct snd_pcm_substream *substream,
 			return -EPIPE;
 		}
 	}
-	if (avail >= runtime->control->avail_min)
+	if (avail >= runtime->control->avail_min) {
+                printk(KERN_ERR "    wakeup in snd_pcm_update_hw_ptr_post %s: %d, avail %d, avail_min %d",__FILE__,__LINE__,avail,runtime->control->avail_min );
 		wake_up(&runtime->sleep);
+        }
 	return 0;
 }
 
@@ -231,6 +235,8 @@ static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
 	snd_pcm_sframes_t hdelta, delta;
 	unsigned long jdelta;
 
+        printk(KERN_ERR " snd_pcm_update_hw_ptr_interrupt");
+        
 	old_hw_ptr = runtime->status->hw_ptr;
 	pos = snd_pcm_update_hw_ptr_pos(substream, runtime);
 	if (pos == SNDRV_PCM_POS_XRUN) {
@@ -363,6 +369,8 @@ int snd_pcm_update_hw_ptr(struct snd_pcm_substream *substream)
 	snd_pcm_sframes_t delta;
 	unsigned long jdelta;
 
+        printk(KERN_ERR " snd_pcm_update_hw_ptr");
+        
 	old_hw_ptr = runtime->status->hw_ptr;
 	pos = snd_pcm_update_hw_ptr_pos(substream, runtime);
 	if (pos == SNDRV_PCM_POS_XRUN) {
@@ -1634,6 +1642,8 @@ void snd_pcm_period_elapsed(struct snd_pcm_substream *substream)
 	struct snd_pcm_runtime *runtime;
 	unsigned long flags;
 
+        printk(KERN_ERR "snd_pcm_period_elapsed");
+        
 	if (PCM_RUNTIME_CHECK(substream))
 		return;
 	runtime = substream->runtime;
@@ -1756,6 +1766,8 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 	snd_pcm_uframes_t offset = 0;
 	int err = 0;
 
+        printk(KERN_ERR "snd_pcm_lib_write1: in");
+        
 	if (size == 0)
 		return 0;
 
@@ -1780,8 +1792,10 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
 		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);
+		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING) {
+                    printk(KERN_ERR "snd_pcm_lib_write1 loop");
+                    snd_pcm_update_hw_ptr(substream);
+                }
 		avail = snd_pcm_playback_avail(runtime);
 		if (!avail) {
 			if (nonblock) {
@@ -1836,6 +1850,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
  _end_unlock:
 	snd_pcm_stream_unlock_irq(substream);
  _end:
+        printk(KERN_ERR "snd_pcm_lib_write1: out");
 	return xfer > 0 ? (snd_pcm_sframes_t)xfer : err;
 }
 
@@ -1998,7 +2013,10 @@ static snd_pcm_sframes_t snd_pcm_lib_read1(struct snd_pcm_substream *substream,
 		snd_pcm_uframes_t avail;
 		snd_pcm_uframes_t cont;
 		if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
-			snd_pcm_update_hw_ptr(substream);
+                {
+                    printk(KERN_ERR "snd_pcm_lib_read1 loop");
+                    snd_pcm_update_hw_ptr(substream);
+                }
 		avail = snd_pcm_capture_avail(runtime);
 		if (!avail) {
 			if (runtime->status->state ==
diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c
index 29ab46a..048052a 100644
--- a/sound/core/pcm_native.c
+++ b/sound/core/pcm_native.c
@@ -2903,13 +2903,16 @@ static unsigned int snd_pcm_playback_poll(struct file *file, poll_table * wait)
 	case SNDRV_PCM_STATE_PAUSED:
 		if (avail >= runtime->control->avail_min) {
 			mask = POLLOUT | POLLWRNORM;
+                        printk(KERN_ERR "ALSA: poll event  POLLOUT|POLLWRNORM, avail %d avail_min %d",avail,runtime->control->avail_min );
 			break;
 		}
+                printk(KERN_ERR "ALSA: null poll event, avail %d avail_min %d",avail,runtime->control->avail_min );
 		/* Fall through */
 	case SNDRV_PCM_STATE_DRAINING:
 		mask = 0;
 		break;
 	default:
+                printk(KERN_ERR "ALSA: default, avail %d avail_min %d",avail,runtime->control->avail_min );
 		mask = POLLOUT | POLLWRNORM | POLLERR;
 		break;
 	}

[-- 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: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Wed, 23 Dec 2009, pl bossart wrote:

> Thanks to Takashi's advice, I managed to find out the reason why I was
> seeing null events returned by poll(). This could explain why
> PulseAudio doesn't seem to sleep much. It turns out that we have two
> calls to wakeup() in pcm_lib.c, and a nice race condition it seems.
> See the log below.
>
> A wake-up is generated during the period interrupt, and a second
> wake-up is generated during the write loop, after the application was
> awaken but just before the pointers are updated. This second wake-up
> shouldn't exist, since the write loop actually fills the ring buffer.
> By the time the second wake-up is actually handled, there's really no
> space left in the buffer and a null event is generated; it'll wake-up
> the application a second time for nothing. Maybe we should move the
> call to snd_pcm_update_hw_ptr() after the transfer took place?

The right fix should be to preserve wakeups when write operation is in 
progress (also for interrupts). Something like this (untested):

diff --git a/include/sound/pcm.h b/include/sound/pcm.h
index c83a4a7..8112834 100644
--- a/include/sound/pcm.h
+++ b/include/sound/pcm.h
@@ -272,6 +272,7 @@ struct snd_pcm_runtime {
  	snd_pcm_uframes_t hw_ptr_interrupt; /* Position at interrupt time */
  	unsigned long hw_ptr_jiffies;	/* Time when hw_ptr is updated */
  	snd_pcm_sframes_t delay;	/* extra delay; typically FIFO size */
+	unsigned int nowake: 1;		/* do not wakeup */

  	/* -- HW params -- */
  	snd_pcm_access_t access;	/* access mode */
diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c
index 30f4108..26cf3ff 100644
--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -208,7 +208,7 @@ static int snd_pcm_update_hw_ptr_post(struct snd_pcm_substream *substream,
  			return -EPIPE;
  		}
  	}
-	if (avail >= runtime->control->avail_min)
+	if (!runtime->nowake && avail >= runtime->control->avail_min)
  		wake_up(&runtime->sleep);
  	return 0;
  }
@@ -1776,6 +1776,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
  		goto _end_unlock;
  	}

+	runtime->nowake = 1;
  	while (size > 0) {
  		snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
  		snd_pcm_uframes_t avail;
@@ -1786,17 +1787,18 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
  		if (!avail) {
  			if (nonblock) {
  				err = -EAGAIN;
-				goto _end_unlock;
+				goto _end_wake;
  			}
  			err = wait_for_avail_min(substream, &avail);
  			if (err < 0)
-				goto _end_unlock;
+				goto _end_wake;
  		}
  		frames = size > avail ? avail : size;
  		cont = runtime->buffer_size - runtime->control->appl_ptr % runtime->buffer_size;
  		if (frames > cont)
  			frames = cont;
  		if (snd_BUG_ON(!frames)) {
+			runtime->nowake = 0;
  			snd_pcm_stream_unlock_irq(substream);
  			return -EINVAL;
  		}
@@ -1809,10 +1811,10 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
  		switch (runtime->status->state) {
  		case SNDRV_PCM_STATE_XRUN:
  			err = -EPIPE;
-			goto _end_unlock;
+			goto _end;
  		case SNDRV_PCM_STATE_SUSPENDED:
  			err = -ESTRPIPE;
-			goto _end_unlock;
+			goto _end;
  		default:
  			break;
  		}
@@ -1830,12 +1832,18 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct snd_pcm_substream *substream,
  		    snd_pcm_playback_hw_avail(runtime) >= (snd_pcm_sframes_t)runtime->start_threshold) {
  			err = snd_pcm_start(substream);
  			if (err < 0)
-				goto _end_unlock;
+				goto _end_wake;
  		}
  	}
+ _end_wake:
+ 	runtime->nowake = 0;
+ 	if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
+ 		snd_pcm_update_hw_ptr_post(substream, runtime);
   _end_unlock:
  	snd_pcm_stream_unlock_irq(substream);
+	return xfer > 0 ? (snd_pcm_sframes_t)xfer : err;
   _end:
+ 	runtime->nowake = 0;
  	return xfer > 0 ? (snd_pcm_sframes_t)xfer : err;
  }


-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Raymond Yau]

does it mean that avail_min cannot be larger than buffer size ?

Is this a bug of snd_pcm_sw_params_set_avail_min() ?


PA server set avail_min to 4661 which is even larger than buffer size 2048
when use 2 periods of 4K bytes with au8830

avail will never greater than  runtime->control->avail_min (4661)


However au8830 work quite well on Fedora 10 pulseaudio-0.9.14


D: alsa-util.c:   buffer_size  : 2048
D: alsa-util.c:   period_size  : 1024
D: alsa-util.c:   period_time  : 23219
D: alsa-util.c:   tstamp_mode  : NONE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 4661


2009/12/10 pl bossart <bossart.nospam@gmail.com>
>>> 2) why PA use  snd_pcm_hw_params_get_buffer_size_max() instead of
>>> snd_pcm_hw_params_get_buffer_size() after snd_pcm_hw_params() ?

 >> Precisely to use the maximum preallocated buffer size.


D: alsa-util.c: Maximum hw buffer size is 371 ms
I: module-alsa-sink.c: Successfully opened device front:0.
I: module-alsa-sink.c: Successfully enabled mmap() mode.
I: module-alsa-sink.c: Successfully enabled timer-based scheduling mode.
I: (alsa-lib)control.c: Invalid CTL front:0
I: alsa-util.c: Unable to attach to mixer front:0: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:0'
I: alsa-util.c: Using mixer control "Master".
I: sink.c: Created sink 0
"alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0" with sample spec s16le
2ch 44100Hz and channel map front-left,front-right
I: source.c: Created source 0
"alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0.monitor" with sample
spec s16le 2ch 44100Hz and channel map front-left,front-right

I: module-alsa-sink.c: Using 2 fragments of size 4096 bytes, buffer time is
46.44ms
I: module-alsa-sink.c: Time scheduling watermark is 20.00ms
D: module-alsa-sink.c: hwbuf_unused_frames=0
D: module-alsa-sink.c: setting avail_min=4661
I: module-alsa-sink.c: Volume ranges from 0 to 31.
I: module-alsa-sink.c: Volume ranges from -46.50 dB to 0.00 dB.
I: alsa-util.c: All 2 channels can be mapped to mixer channels.
I: module-alsa-sink.c: Using hardware volume control. Hardware dB scale
supported.
D: alsa-util.c: snd_pcm_dump():
D: alsa-util.c: Hardware PCM card 0 'Aureal Vortex au8830' device 0
subdevice 0
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 2048
D: alsa-util.c:   period_size  : 1024
D: alsa-util.c:   period_time  : 23219
D: alsa-util.c:   tstamp_mode  : NONE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 4661
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : -1
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 1073741824
D: alsa-util.c:   appl_ptr     : 0
D: alsa-util.c:   hw_ptr       : 0



2009/12/24 Jaroslav Kysela <perex@perex.cz>

> On Wed, 23 Dec 2009, pl bossart wrote:
>
> > Thanks to Takashi's advice, I managed to find out the reason why I was
> > seeing null events returned by poll(). This could explain why
> > PulseAudio doesn't seem to sleep much. It turns out that we have two
> > calls to wakeup() in pcm_lib.c, and a nice race condition it seems.
> > See the log below.
> >
> > A wake-up is generated during the period interrupt, and a second
> > wake-up is generated during the write loop, after the application was
> > awaken but just before the pointers are updated. This second wake-up
> > shouldn't exist, since the write loop actually fills the ring buffer.
> > By the time the second wake-up is actually handled, there's really no
> > space left in the buffer and a null event is generated; it'll wake-up
> > the application a second time for nothing. Maybe we should move the
> > call to snd_pcm_update_hw_ptr() after the transfer took place?
>
> The right fix should be to preserve wakeups when write operation is in
> progress (also for interrupts). Something like this (untested):
>
> diff --git a/include/sound/pcm.h b/include/sound/pcm.h
> index c83a4a7..8112834 100644
> --- a/include/sound/pcm.h
> +++ b/include/sound/pcm.h
> @@ -272,6 +272,7 @@ struct snd_pcm_runtime {
>        snd_pcm_uframes_t hw_ptr_interrupt; /* Position at interrupt time */
>        unsigned long hw_ptr_jiffies;   /* Time when hw_ptr is updated */
>        snd_pcm_sframes_t delay;        /* extra delay; typically FIFO size
> */
> +       unsigned int nowake: 1;         /* do not wakeup */
>
>        /* -- HW params -- */
>        snd_pcm_access_t access;        /* access mode */
> diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c
> index 30f4108..26cf3ff 100644
> --- a/sound/core/pcm_lib.c
> +++ b/sound/core/pcm_lib.c
> @@ -208,7 +208,7 @@ static int snd_pcm_update_hw_ptr_post(struct
> snd_pcm_substream *substream,
>                        return -EPIPE;
>                }
>        }
> -       if (avail >= runtime->control->avail_min)
> +       if (!runtime->nowake && avail >= runtime->control->avail_min)
>                wake_up(&runtime->sleep);
>        return 0;
>  }
> @@ -1776,6 +1776,7 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct
> snd_pcm_substream *substream,
>                goto _end_unlock;
>        }
>
> +       runtime->nowake = 1;
>        while (size > 0) {
>                snd_pcm_uframes_t frames, appl_ptr, appl_ofs;
>                snd_pcm_uframes_t avail;
> @@ -1786,17 +1787,18 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct
> snd_pcm_substream *substream,
>                if (!avail) {
>                        if (nonblock) {
>                                err = -EAGAIN;
> -                               goto _end_unlock;
> +                               goto _end_wake;
>                        }
>                        err = wait_for_avail_min(substream, &avail);
>                        if (err < 0)
> -                               goto _end_unlock;
> +                               goto _end_wake;
>                }
>                frames = size > avail ? avail : size;
>                cont = runtime->buffer_size - runtime->control->appl_ptr %
> runtime->buffer_size;
>                if (frames > cont)
>                        frames = cont;
>                if (snd_BUG_ON(!frames)) {
> +                       runtime->nowake = 0;
>                        snd_pcm_stream_unlock_irq(substream);
>                        return -EINVAL;
>                }
> @@ -1809,10 +1811,10 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct
> snd_pcm_substream *substream,
>                switch (runtime->status->state) {
>                case SNDRV_PCM_STATE_XRUN:
>                        err = -EPIPE;
> -                       goto _end_unlock;
> +                       goto _end;
>                case SNDRV_PCM_STATE_SUSPENDED:
>                        err = -ESTRPIPE;
> -                       goto _end_unlock;
> +                       goto _end;
>                default:
>                        break;
>                }
> @@ -1830,12 +1832,18 @@ static snd_pcm_sframes_t snd_pcm_lib_write1(struct
> snd_pcm_substream *substream,
>                    snd_pcm_playback_hw_avail(runtime) >=
> (snd_pcm_sframes_t)runtime->start_threshold) {
>                        err = snd_pcm_start(substream);
>                        if (err < 0)
> -                               goto _end_unlock;
> +                               goto _end_wake;
>                }
>        }
> + _end_wake:
> +       runtime->nowake = 0;
> +       if (runtime->status->state == SNDRV_PCM_STATE_RUNNING)
> +               snd_pcm_update_hw_ptr_post(substream, runtime);
>   _end_unlock:
>        snd_pcm_stream_unlock_irq(substream);
> +       return xfer > 0 ? (snd_pcm_sframes_t)xfer : err;
>   _end:
> +       runtime->nowake = 0;
>        return xfer > 0 ? (snd_pcm_sframes_t)xfer : err;
>  }
>
>
> -----
> Jaroslav Kysela <perex@perex.cz>
> Linux Kernel Sound Maintainer
> ALSA Project, Red Hat, Inc.
>
>

Re: Duplicate wake-ups in pcm_lib.c

[pl bossart]

>> A wake-up is generated during the period interrupt, and a second
>> wake-up is generated during the write loop, after the application was
>> awaken but just before the pointers are updated. This second wake-up
>> shouldn't exist, since the write loop actually fills the ring buffer.
>> By the time the second wake-up is actually handled, there's really no
>> space left in the buffer and a null event is generated; it'll wake-up
>> the application a second time for nothing. Maybe we should move the
>> call to snd_pcm_update_hw_ptr() after the transfer took place?
>
> The right fix should be to preserve wakeups when write operation is in
> progress (also for interrupts). Something like this (untested):

Thanks Jaroslav for your feedback. It seems your fix is similar to
what I suggested, that is check the pointers and generate a wake-up
after the write loop completes rather than right before the write
starts. I modified your patch to correct the behavior when errors
occur; the jumps to _end_wake compared to _end_unlock weren't self
explanatory and not always consistent. I only perform a pointer update
if nothing wrong happened. In case of errors, I unlock or just return
the status as before. I am testing the changes and should have a patch
shortly.
Cheers
- Pierre

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Wed, 6 Jan 2010, pl bossart wrote:

>>> A wake-up is generated during the period interrupt, and a second
>>> wake-up is generated during the write loop, after the application was
>>> awaken but just before the pointers are updated. This second wake-up
>>> shouldn't exist, since the write loop actually fills the ring buffer.
>>> By the time the second wake-up is actually handled, there's really no
>>> space left in the buffer and a null event is generated; it'll wake-up
>>> the application a second time for nothing. Maybe we should move the
>>> call to snd_pcm_update_hw_ptr() after the transfer took place?
>>
>> The right fix should be to preserve wakeups when write operation is in
>> progress (also for interrupts). Something like this (untested):
>
> Thanks Jaroslav for your feedback. It seems your fix is similar to
> what I suggested, that is check the pointers and generate a wake-up
> after the write loop completes rather than right before the write
> starts. I modified your patch to correct the behavior when errors
> occur; the jumps to _end_wake compared to _end_unlock weren't self
> explanatory and not always consistent. I only perform a pointer update
> if nothing wrong happened. In case of errors, I unlock or just return
> the status as before. I am testing the changes and should have a patch
> shortly.
> Cheers

The improved and more clean fix in now in my tree:

http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6

Note that you should apply these 4 patches (in reverse order):

4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions
1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines

Patch #3 should definitely fix problems with large avail or delay values 
reported in PA. I finally figured the culprit (and decide to cleanup all
relevant code rather do just another workaround). In other words, new 
hw_ptr pointer should never be less than previous one now.

 						Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Raymond Yau]

2010/1/7 Jaroslav Kysela <perex@perex.cz>

> On Wed, 6 Jan 2010, pl bossart wrote:
>
>
>
> The improved and more clean fix in now in my tree:
>
>
> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>
> Note that you should apply these 4 patches (in reverse order):
>
> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions
> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
>
> Patch #3 should definitely fix problems with large avail or delay values
> reported in PA. I finally figured the culprit (and decide to cleanup all
> relevant code rather do just another workaround). In other words, new
> hw_ptr pointer should never be less than previous one now.
>
>                                                Jaroslav
>
> -
>

using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside Virtual
Box

aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav

"Front Left" sound as "Front Front Left" when playing "Front_left.wav"

only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Mon, 11 Jan 2010, Raymond Yau wrote:

> 2010/1/7 Jaroslav Kysela <perex@perex.cz>
>
>> On Wed, 6 Jan 2010, pl bossart wrote:
>>
>>
>>
>> The improved and more clean fix in now in my tree:
>>
>>
>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>
>> Note that you should apply these 4 patches (in reverse order):
>>
>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions
>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
>>
>> Patch #3 should definitely fix problems with large avail or delay values
>> reported in PA. I finally figured the culprit (and decide to cleanup all
>> relevant code rather do just another workaround). In other words, new
>> hw_ptr pointer should never be less than previous one now.
>>
>>                                                Jaroslav
>>
>> -
>>
>
> using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside Virtual
> Box
>
> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>
> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>
> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug

Thanks for testing.

It means that with other values is no sound generated?

Could you use value 29 for xrun_debug and report all sound related 
messages from dmesg output after playback of "Front_left.wav"?

 					Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Raymond Yau]

2010/1/11 Jaroslav Kysela <perex@perex.cz>

> On Mon, 11 Jan 2010, Raymond Yau wrote:
>
>  2010/1/7 Jaroslav Kysela <perex@perex.cz>
>>
>>  On Wed, 6 Jan 2010, pl bossart wrote:
>>>
>>>
>>>
>>> The improved and more clean fix in now in my tree:
>>>
>>>
>>>
>>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>>
>>> Note that you should apply these 4 patches (in reverse order):
>>>
>>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer
>>> positions
>>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
>>>
>>> Patch #3 should definitely fix problems with large avail or delay values
>>> reported in PA. I finally figured the culprit (and decide to cleanup all
>>> relevant code rather do just another workaround). In other words, new
>>> hw_ptr pointer should never be less than previous one now.
>>>
>>>                                               Jaroslav
>>>
>>> -
>>>
>>>
>> using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside Virtual
>> Box
>>
>> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>>
>> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>>
>> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug
>>
>
> Thanks for testing.
>
> It means that with other values is no sound generated?
>
> Could you use value 29 for xrun_debug and report all sound related messages
> from dmesg output after playback of "Front_left.wav"?
>
>                                        Jaroslav
>
> -----



do you mean 27 instead of 29 since the echo only occur when the value
contain XRUN_DEBUG_JIFFIESCHECK  bit  ?

aplay -Dplughw:0,0 and mplayer -ao alsa:device=hw=0,0 work normal

except when the value of xrun_debug contain XRUN_DEBUG_JIFFIESCHECK  bit  (
same result for the three  virtual box audio backend oss, pulseaudio and
alsa )

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Wed, 13 Jan 2010, Raymond Yau wrote:

> 2010/1/11 Jaroslav Kysela <perex@perex.cz>
>
>> On Mon, 11 Jan 2010, Raymond Yau wrote:
>>
>>  2010/1/7 Jaroslav Kysela <perex@perex.cz>
>>>
>>>  On Wed, 6 Jan 2010, pl bossart wrote:
>>>>
>>>>
>>>>
>>>> The improved and more clean fix in now in my tree:
>>>>
>>>>
>>>>
>>>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>>>
>>>> Note that you should apply these 4 patches (in reverse order):
>>>>
>>>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>>>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>>>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer
>>>> positions
>>>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
>>>>
>>>> Patch #3 should definitely fix problems with large avail or delay values
>>>> reported in PA. I finally figured the culprit (and decide to cleanup all
>>>> relevant code rather do just another workaround). In other words, new
>>>> hw_ptr pointer should never be less than previous one now.
>>>>
>>>>                                               Jaroslav
>>>>
>>>> -
>>>>
>>>>
>>> using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside Virtual
>>> Box
>>>
>>> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>>>
>>> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>>>
>>> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug
>>>
>>
>> Thanks for testing.
>>
>> It means that with other values is no sound generated?
>>
>> Could you use value 29 for xrun_debug and report all sound related messages
>> from dmesg output after playback of "Front_left.wav"?
>>
>>                                        Jaroslav
>>
>> -----
>
>
>
> do you mean 27 instead of 29 since the echo only occur when the value
> contain XRUN_DEBUG_JIFFIESCHECK  bit  ?
>
> aplay -Dplughw:0,0 and mplayer -ao alsa:device=hw=0,0 work normal
>
> except when the value of xrun_debug contain XRUN_DEBUG_JIFFIESCHECK  bit  (
> same result for the three  virtual box audio backend oss, pulseaudio and
> alsa )

Ok, I understand now. It would be better to use value 101 then - to see 
last 10 ring buffer positions when jiffies correction occurs. Also, 
get latest snapshot - there is a fix for jiffies check. Thanks.

 					Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Raymond Yau]

2010/1/13 Jaroslav Kysela <perex@perex.cz>

> On Wed, 13 Jan 2010, Raymond Yau wrote:
>
>  2010/1/11 Jaroslav Kysela <perex@perex.cz>
>>
>>  On Mon, 11 Jan 2010, Raymond Yau wrote:
>>>
>>>  2010/1/7 Jaroslav Kysela <perex@perex.cz>
>>>
>>>>
>>>>  On Wed, 6 Jan 2010, pl bossart wrote:
>>>>
>>>>>
>>>>>
>>>>>
>>>>> The improved and more clean fix in now in my tree:
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>>>>
>>>>> Note that you should apply these 4 patches (in reverse order):
>>>>>
>>>>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>>>>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>>>>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer
>>>>> positions
>>>>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use
>>>>> defines
>>>>>
>>>>> Patch #3 should definitely fix problems with large avail or delay
>>>>> values
>>>>> reported in PA. I finally figured the culprit (and decide to cleanup
>>>>> all
>>>>> relevant code rather do just another workaround). In other words, new
>>>>> hw_ptr pointer should never be less than previous one now.
>>>>>
>>>>>                                              Jaroslav
>>>>>
>>>>> -
>>>>>
>>>>>
>>>>>  using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside
>>>> Virtual
>>>> Box
>>>>
>>>> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>>>>
>>>> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>>>>
>>>> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug
>>>>
>>>>
>>> Thanks for testing.
>>>
>>> It means that with other values is no sound generated?
>>>
>>> Could you use value 29 for xrun_debug and report all sound related
>>> messages
>>> from dmesg output after playback of "Front_left.wav"?
>>>
>>>                                       Jaroslav
>>>
>>> -----
>>>
>>
>>
>>
>> do you mean 27 instead of 29 since the echo only occur when the value
>> contain XRUN_DEBUG_JIFFIESCHECK  bit  ?
>>
>> aplay -Dplughw:0,0 and mplayer -ao alsa:device=hw=0,0 work normal
>>
>> except when the value of xrun_debug contain XRUN_DEBUG_JIFFIESCHECK  bit
>>  (
>> same result for the three  virtual box audio backend oss, pulseaudio and
>> alsa )
>>
>
> Ok, I understand now. It would be better to use value 101 then - to see
> last 10 ring buffer positions when jiffies correction occurs. Also, get
> latest snapshot - there is a fix for jiffies check. Thanks.
>
>                                        Jaroslav
>
>
 alsa-driver-1.0.22.1.1.g231e3.61.g42efb
copying file alsa/kernel/core/sound.c
patchfile file sound.c
Hunk# 12  FAILED at 518
1 out of 12 hunks FAILED -- saving rejects to file sound.c.rej


seem related to
http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=8a822c23333694e7d1e6ccb15267e251af6d8f4f

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Wed, 20 Jan 2010, Raymond Yau wrote:

> 2010/1/13 Jaroslav Kysela <perex@perex.cz>
>
>> On Wed, 13 Jan 2010, Raymond Yau wrote:
>>
>>  2010/1/11 Jaroslav Kysela <perex@perex.cz>
>>>
>>>  On Mon, 11 Jan 2010, Raymond Yau wrote:
>>>>
>>>>  2010/1/7 Jaroslav Kysela <perex@perex.cz>
>>>>
>>>>>
>>>>>  On Wed, 6 Jan 2010, pl bossart wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> The improved and more clean fix in now in my tree:
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>>>>>
>>>>>> Note that you should apply these 4 patches (in reverse order):
>>>>>>
>>>>>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>>>>>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>>>>>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer
>>>>>> positions
>>>>>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use
>>>>>> defines
>>>>>>
>>>>>> Patch #3 should definitely fix problems with large avail or delay
>>>>>> values
>>>>>> reported in PA. I finally figured the culprit (and decide to cleanup
>>>>>> all
>>>>>> relevant code rather do just another workaround). In other words, new
>>>>>> hw_ptr pointer should never be less than previous one now.
>>>>>>
>>>>>>                                              Jaroslav
>>>>>>
>>>>>> -
>>>>>>
>>>>>>
>>>>>>  using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside
>>>>> Virtual
>>>>> Box
>>>>>
>>>>> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>>>>>
>>>>> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>>>>>
>>>>> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug
>>>>>
>>>>>
>>>> Thanks for testing.
>>>>
>>>> It means that with other values is no sound generated?
>>>>
>>>> Could you use value 29 for xrun_debug and report all sound related
>>>> messages
>>>> from dmesg output after playback of "Front_left.wav"?
>>>>
>>>>                                       Jaroslav
>>>>
>>>> -----
>>>>
>>>
>>>
>>>
>>> do you mean 27 instead of 29 since the echo only occur when the value
>>> contain XRUN_DEBUG_JIFFIESCHECK  bit  ?
>>>
>>> aplay -Dplughw:0,0 and mplayer -ao alsa:device=hw=0,0 work normal
>>>
>>> except when the value of xrun_debug contain XRUN_DEBUG_JIFFIESCHECK  bit
>>>  (
>>> same result for the three  virtual box audio backend oss, pulseaudio and
>>> alsa )
>>>
>>
>> Ok, I understand now. It would be better to use value 101 then - to see
>> last 10 ring buffer positions when jiffies correction occurs. Also, get
>> latest snapshot - there is a fix for jiffies check. Thanks.
>>
>>                                        Jaroslav
>>
>>
> alsa-driver-1.0.22.1.1.g231e3.61.g42efb
> copying file alsa/kernel/core/sound.c
> patchfile file sound.c
> Hunk# 12  FAILED at 518
> 1 out of 12 hunks FAILED -- saving rejects to file sound.c.rej
>
>
> seem related to
> http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=8a822c23333694e7d1e6ccb15267e251af6d8f4f

The problem should be fixed now. Thanks for the notice.

 						Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Raymond Yau]

2010/1/20 Jaroslav Kysela <perex@perex.cz>

> On Wed, 20 Jan 2010, Raymond Yau wrote:
>
>  2010/1/13 Jaroslav Kysela <perex@perex.cz>
>>
>>  On Wed, 13 Jan 2010, Raymond Yau wrote:
>>>
>>>  2010/1/11 Jaroslav Kysela <perex@perex.cz>
>>>
>>>>
>>>>  On Mon, 11 Jan 2010, Raymond Yau wrote:
>>>>
>>>>>
>>>>>  2010/1/7 Jaroslav Kysela <perex@perex.cz>
>>>>>
>>>>>
>>>>>>  On Wed, 6 Jan 2010, pl bossart wrote:
>>>>>>
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> The improved and more clean fix in now in my tree:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>>>>>>
>>>>>>> Note that you should apply these 4 patches (in reverse order):
>>>>>>>
>>>>>>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>>>>>>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>>>>>>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer
>>>>>>> positions
>>>>>>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use
>>>>>>> defines
>>>>>>>
>>>>>>> Patch #3 should definitely fix problems with large avail or delay
>>>>>>> values
>>>>>>> reported in PA. I finally figured the culprit (and decide to cleanup
>>>>>>> all
>>>>>>> relevant code rather do just another workaround). In other words, new
>>>>>>> hw_ptr pointer should never be less than previous one now.
>>>>>>>
>>>>>>>                                             Jaroslav
>>>>>>>
>>>>>>> -
>>>>>>>
>>>>>>>
>>>>>>>  using alsa-driver-1.0.22.1.1.g231e3.14.g812cb and Fedora 12 inside
>>>>>>>
>>>>>> Virtual
>>>>>> Box
>>>>>>
>>>>>> aplay -D plughw:0,0 /usr/share/sounds/alsa/*.wav
>>>>>>
>>>>>> "Front Left" sound as "Front Front Left" when playing "Front_left.wav"
>>>>>>
>>>>>> only when echo 4 > /proc/asound/card0/pcm0p/xrun_debug
>>>>>>
>>>>>>
>>>>>>  Thanks for testing.
>>>>>
>>>>> It means that with other values is no sound generated?
>>>>>
>>>>> Could you use value 29 for xrun_debug and report all sound related
>>>>> messages
>>>>> from dmesg output after playback of "Front_left.wav"?
>>>>>
>>>>>                                      Jaroslav
>>>>>
>>>>> -----
>>>>>
>>>>>
>>>>
>>>>
>>>> do you mean 27 instead of 29 since the echo only occur when the value
>>>> contain XRUN_DEBUG_JIFFIESCHECK  bit  ?
>>>>
>>>> aplay -Dplughw:0,0 and mplayer -ao alsa:device=hw=0,0 work normal
>>>>
>>>> except when the value of xrun_debug contain XRUN_DEBUG_JIFFIESCHECK  bit
>>>>  (
>>>> same result for the three  virtual box audio backend oss, pulseaudio and
>>>> alsa )
>>>>
>>>>
>>> Ok, I understand now. It would be better to use value 101 then - to see
>>> last 10 ring buffer positions when jiffies correction occurs. Also, get
>>> latest snapshot - there is a fix for jiffies check. Thanks.
>>>
>>>                                       Jaroslav
>>>
>>>
>>>  alsa-driver-1.0.22.1.1.g231e3.61.g42efb
>> copying file alsa/kernel/core/sound.c
>> patchfile file sound.c
>> Hunk# 12  FAILED at 518
>> 1 out of 12 hunks FAILED -- saving rejects to file sound.c.rej
>>
>>
>> seem related to
>>
>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=8a822c23333694e7d1e6ccb15267e251af6d8f4f
>>
>
> The problem should be fixed now. Thanks for the notice.
>
>                                                Jaroslav
>
> -----
>
>
alsa-lib/test/pcm --verbose -Dhw -c2 -r48000 -f440  --method write_and_poll

How do I know the double wake up is fixed ?

do it mean that fixing this bug will fix the pulseaudio problem ?

do I need to test with other format , rate, channel, and sine wave frequency
?

the echo still exist only XRUN_DEBUG_JIFFIESCHECK  bit is set

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Tue, 26 Jan 2010, Raymond Yau wrote:

>>>> Ok, I understand now. It would be better to use value 101 then - to see
>>>> last 10 ring buffer positions when jiffies correction occurs. Also, get
>>>> latest snapshot - there is a fix for jiffies check. Thanks.
>
> alsa-lib/test/pcm --verbose -Dhw -c2 -r48000 -f440  --method write_and_poll
>
> How do I know the double wake up is fixed ?

As far as know, only pulseaudio reports this issue in verbose mode.

> the echo still exist only XRUN_DEBUG_JIFFIESCHECK  bit is set

Please, could you set 101 to xrun_debug proc file and report relevant 
messages in dmesg as I asked before? I am curious where the problem is.

 						Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[pl bossart]

> The improved and more clean fix in now in my tree:
>
> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>

The race condition is definitely gone. However I still see a NULL
event in snd_pcm_playback_poll() in pcm_native.c.

[13312.575829] snd_intel8x0_interrupt
[13312.575839]  snd_intel8x0_update
[13312.575847] snd_pcm_period_elapsed
[13312.575853]  snd_pcm_update_hw_ptr0
[13312.575862]    snd_pcm_update_state
[13312.575870]     wakeup in snd_pcm_update_state: avail 8194, avail_min 8192
[13312.575894] ALSA: poll event  POLLOUT|POLLWRNORM, avail 8194 avail_min 8192
[13312.581259] snd_pcm_lib_write1: in
[13312.581267] snd_pcm_lib_write1 loop
[13312.581273]  snd_pcm_update_hw_ptr0
[13312.581282]    snd_pcm_update_state
[13312.581312] snd_pcm_lib_write1: end
[13312.581317]    snd_pcm_update_state
[13312.581328] ALSA: null poll event, avail 262 avail_min 8192
[13312.746498] snd_intel8x0_interrupt
[13312.746511]  snd_intel8x0_update
[13312.746520] snd_pcm_period_elapsed
[13312.746526]  snd_pcm_update_hw_ptr0
[13312.746536]    snd_pcm_update_state
[13312.746544]     wakeup in snd_pcm_update_state: avail 8194, avail_min 8192
[13312.746571] ALSA: poll event  POLLOUT|POLLWRNORM, avail 8194 avail_min 8192
[13312.751990] snd_pcm_lib_write1: in
[13312.751998] snd_pcm_lib_write1 loop
[13312.752004]  snd_pcm_update_hw_ptr0
[13312.752013]    snd_pcm_update_state
[13312.755285] snd_pcm_lib_write1: end
[13312.755293]    snd_pcm_update_state
[13312.755305] ALSA: null poll event, avail 265 avail_min 8192

I couldn't figure out who generates this null event, and even better
it does not show in the report printed by my test app. I am somewhat
lost here as to how snd_pcm_playback_poll works.
- Pierre

Re: Duplicate wake-ups in pcm_lib.c

[pl bossart]

> I couldn't figure out who generates this null event, and even better
> it does not show in the report printed by my test app. I am somewhat
> lost here as to how snd_pcm_playback_poll works.

Not sure if this is related to my previous post, but PulseAudio seems
to only sleep every other time poll is called. Somehow there's still a
spurious wakeup.

E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 188 ms
E: rtpoll.c: Process time 0 ms; sleep time 188 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 189 ms
E: rtpoll.c: Process time 0 ms; sleep time 0 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: rtpoll finish
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 188 ms
E: rtpoll.c: Process time 0 ms; sleep time 189 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 189 ms
E: rtpoll.c: Process time 0 ms; sleep time 0 ms

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Mon, 11 Jan 2010, pl bossart wrote:

>> I couldn't figure out who generates this null event, and even better
>> it does not show in the report printed by my test app. I am somewhat
>> lost here as to how snd_pcm_playback_poll works.
>
> Not sure if this is related to my previous post, but PulseAudio seems
> to only sleep every other time poll is called. Somehow there's still a
> spurious wakeup.
>
> E: rtpoll.c: rtpoll_run
> E: rtpoll.c: poll timeout: 188 ms
> E: rtpoll.c: Process time 0 ms; sleep time 188 ms

Is ALSA fd the culprit of wakeup?

 					Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Mon, 11 Jan 2010, pl bossart wrote:

>> The improved and more clean fix in now in my tree:
>>
>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>
>
> The race condition is definitely gone. However I still see a NULL
> event in snd_pcm_playback_poll() in pcm_native.c.

> [13312.755305] ALSA: null poll event, avail 265 avail_min 8192
>
> I couldn't figure out who generates this null event, and even better
> it does not show in the report printed by my test app. I am somewhat
> lost here as to how snd_pcm_playback_poll works.

Note that do_poll() in linux/fs/select.c first checks all given fds
if there's an event. So probably the userspace just called poll() for a 
reason in different timing than sound one (processing event from another 
fd or so). I believe it's normal behaviour.

 						Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[pl bossart]

>> I couldn't figure out who generates this null event, and even better
>> it does not show in the report printed by my test app. I am somewhat
>> lost here as to how snd_pcm_playback_poll works.
>
> Note that do_poll() in linux/fs/select.c first checks all given fds
> if there's an event. So probably the userspace just called poll() for a
> reason in different timing than sound one (processing event from another fd
> or so). I believe it's normal behaviour.

This was tested with alsa-lib/test/pcm.c; there's only one call to
poll() with a -1 timeout value. What I fail to understand is why I see
this null event in pcm_native.c, and nothing reported in userspace by
the wait_for_poll() loop in alsa-lib/test/pcm.c

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Mon, 11 Jan 2010, pl bossart wrote:

>>> I couldn't figure out who generates this null event, and even better
>>> it does not show in the report printed by my test app. I am somewhat
>>> lost here as to how snd_pcm_playback_poll works.
>>
>> Note that do_poll() in linux/fs/select.c first checks all given fds
>> if there's an event. So probably the userspace just called poll() for a
>> reason in different timing than sound one (processing event from another fd
>> or so). I believe it's normal behaviour.
>
> This was tested with alsa-lib/test/pcm.c; there's only one call to
> poll() with a -1 timeout value. What I fail to understand is why I see
> this null event in pcm_native.c, and nothing reported in userspace by
> the wait_for_poll() loop in alsa-lib/test/pcm.c

Userspace: poll() syscall
Kernel: do_poll()
 	1) call f_ops->poll callback to ensure that poll condition is
 	   not set (it's usually your null event)
 	2) go to sleep and wait for wake_up
 	3) call f_ops->poll callback again to check which fd woke up
 	4) leave to user space

The f_ops->poll callback is called twice in a normal situation.

 					Jaroslav


-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Colin Guthrie]

Hi Jaroslav,

'Twas brillig, and Jaroslav Kysela at 07/01/10 14:59 did gyre and gimble:
> The improved and more clean fix in now in my tree:
> 
> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
> 
> Note that you should apply these 4 patches (in reverse order):
> 
> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions
> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
> 
> Patch #3 should definitely fix problems with large avail or delay values 
> reported in PA. I finally figured the culprit (and decide to cleanup all
> relevant code rather do just another workaround). In other words, new 
> hw_ptr pointer should never be less than previous one now.


Just wanted to ask about the status of this.

We included the fixes in Mandriva cooker kernel for wider testing but
some users are seeing issues.

These four *seem* to be OK, but after also adding the "something must be
really wrong" commit
(http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=7b3a177b0d4f92b3431b8dca777313a07533a710)
folks started getting some errors.

We also added the jiffies fix commit
(http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=ed69c6a8eef679f2783848ed624897a937a434ac)
but that didn't seem to help.

This is handled in our bug report here:
https://qa.mandriva.com/show_bug.cgi?id=57010

For reference relating to comment 12:
2.6.32.3-1mnb: First introduced the above 4 fixes.
2.6.32.3-2mnb: included 7b3a177
2.6.32.4-0.rc1.1mnb: included ed69c6a

Is there something more that needs done?

Col



-- 

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

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: Duplicate wake-ups in pcm_lib.c

[Jaroslav Kysela]

On Mon, 18 Jan 2010, Colin Guthrie wrote:

> Hi Jaroslav,
>
> 'Twas brillig, and Jaroslav Kysela at 07/01/10 14:59 did gyre and gimble:
>> The improved and more clean fix in now in my tree:
>>
>> http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=1250932e48d3b698415b1f04775433cf1da688d6
>>
>> Note that you should apply these 4 patches (in reverse order):
>>
>> 4: ALSA: pcm_lib - optimize wake_up() calls for PCM I/O
>> 3: ALSA: pcm_lib - cleanup & merge hw_ptr update functions
>> 2: ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions
>> 1: ALSA: pcm_lib.c - convert second xrun_debug() parameter to use defines
>>
>> Patch #3 should definitely fix problems with large avail or delay values
>> reported in PA. I finally figured the culprit (and decide to cleanup all
>> relevant code rather do just another workaround). In other words, new
>> hw_ptr pointer should never be less than previous one now.
>
>
> Just wanted to ask about the status of this.
>
> We included the fixes in Mandriva cooker kernel for wider testing but
> some users are seeing issues.
>
> These four *seem* to be OK, but after also adding the "something must be
> really wrong" commit
> (http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=7b3a177b0d4f92b3431b8dca777313a07533a710)
> folks started getting some errors.
>
> We also added the jiffies fix commit
> (http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=ed69c6a8eef679f2783848ed624897a937a434ac)
> but that didn't seem to help.
>
> This is handled in our bug report here:
> https://qa.mandriva.com/show_bug.cgi?id=57010
>
> For reference relating to comment 12:
> 2.6.32.3-1mnb: First introduced the above 4 fixes.
> 2.6.32.3-2mnb: included 7b3a177
> 2.6.32.4-0.rc1.1mnb: included ed69c6a
>
> Is there something more that needs done?

Thanks for feedback. Please, provide debug information:

http://www.alsa-project.org/main/index.php/XRUN_Debug

Use 101 or 29 values for xrun_debug and try to put ksyslog messages 
to a relation with the audiable problems.

 				Thanks,
 					Jaroslav

-----
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project, Red Hat, Inc.

Re: Duplicate wake-ups in pcm_lib.c

[Colin Guthrie]

Hi,

'Twas brillig, and Jaroslav Kysela at 18/01/10 21:39 did gyre and gimble:
> On Mon, 18 Jan 2010, Colin Guthrie wrote:
>> This is handled in our bug report here:
>> https://qa.mandriva.com/show_bug.cgi?id=57010
>>
>> For reference relating to comment 12:
>> 2.6.32.3-1mnb: First introduced the above 4 fixes.
>> 2.6.32.3-2mnb: included 7b3a177
>> 2.6.32.4-0.rc1.1mnb: included ed69c6a
>>
>> Is there something more that needs done?
> 
> Thanks for feedback. Please, provide debug information:
> 
> http://www.alsa-project.org/main/index.php/XRUN_Debug
> 
> Use 101 or 29 values for xrun_debug and try to put ksyslog messages 
> to a relation with the audiable problems.

Just following up on this on behalf of a colleage.

He's set the 101 value and this annoyingly seems to fix his problem
(well, no glitches to the ear anyway!).

However he does get the following messages:

kernel: PCM: hw_ptr skipping! [Q] (pos=1024, delta=8192, period=1024,
jdelta=0/170/0, hw_ptr=140116992/140116992)

When he does the 29 value it spams the log >one every second and he
didn't try too long to get it to fail before he switched to 101. I can
get the full log of the above too if it's useful or run the 29 test and
capture the output if it'll still help even tho it's not showing the error.

Col

-- 

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

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: Duplicate wake-ups in pcm_lib.c

[Colin Guthrie]

'Twas brillig, and Colin Guthrie at 20/01/10 01:24 did gyre and gimble:
> Hi,
> 
> 'Twas brillig, and Jaroslav Kysela at 18/01/10 21:39 did gyre and gimble:
>> On Mon, 18 Jan 2010, Colin Guthrie wrote:
>>> This is handled in our bug report here:
>>> https://qa.mandriva.com/show_bug.cgi?id=57010
>>>
>>> For reference relating to comment 12:
>>> 2.6.32.3-1mnb: First introduced the above 4 fixes.
>>> 2.6.32.3-2mnb: included 7b3a177
>>> 2.6.32.4-0.rc1.1mnb: included ed69c6a
>>>
>>> Is there something more that needs done?
>>
>> Thanks for feedback. Please, provide debug information:
>>
>> http://www.alsa-project.org/main/index.php/XRUN_Debug
>>
>> Use 101 or 29 values for xrun_debug and try to put ksyslog messages 
>> to a relation with the audiable problems.
> 
> Just following up on this on behalf of a colleage.
> 
> He's set the 101 value and this annoyingly seems to fix his problem
> (well, no glitches to the ear anyway!).
> 
> However he does get the following messages:
> 
> kernel: PCM: hw_ptr skipping! [Q] (pos=1024, delta=8192, period=1024,
> jdelta=0/170/0, hw_ptr=140116992/140116992)
> 
> When he does the 29 value it spams the log >one every second and he
> didn't try too long to get it to fail before he switched to 101. I can
> get the full log of the above too if it's useful or run the 29 test and
> capture the output if it'll still help even tho it's not showing the error.

Another reply on the bug with some debug output:

https://qa.mandriva.com/show_bug.cgi?id=57010#c14


hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900536/1884160
hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=1900544/1900544)
PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
jdelta=1/371/0, hw_ptr=4882432/4882432)
PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
jdelta=0/371/0,hw_ptr=11395072/11395072)
PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=13156352/13156352)
PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=13893632/13893632)
PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=20209664/20209664)
PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=27860992/27860992)
PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
jdelta=0/371/0, hw_ptr=28639232/28639232)


-- 

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

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: Duplicate wake-ups in pcm_lib.c

[Colin Guthrie]

'Twas brillig, and Colin Guthrie at 20/01/10 15:12 did gyre and gimble:
> 'Twas brillig, and Colin Guthrie at 20/01/10 01:24 did gyre and gimble:
>> Hi,
>>
>> 'Twas brillig, and Jaroslav Kysela at 18/01/10 21:39 did gyre and gimble:
>>> On Mon, 18 Jan 2010, Colin Guthrie wrote:
>>>> This is handled in our bug report here:
>>>> https://qa.mandriva.com/show_bug.cgi?id=57010
>>>>
>>>> For reference relating to comment 12:
>>>> 2.6.32.3-1mnb: First introduced the above 4 fixes.
>>>> 2.6.32.3-2mnb: included 7b3a177
>>>> 2.6.32.4-0.rc1.1mnb: included ed69c6a
>>>>
>>>> Is there something more that needs done?
>>>
>>> Thanks for feedback. Please, provide debug information:
>>>
>>> http://www.alsa-project.org/main/index.php/XRUN_Debug
>>>
>>> Use 101 or 29 values for xrun_debug and try to put ksyslog messages 
>>> to a relation with the audiable problems.
>>
>> Just following up on this on behalf of a colleage.
>>
>> He's set the 101 value and this annoyingly seems to fix his problem
>> (well, no glitches to the ear anyway!).
>>
>> However he does get the following messages:
>>
>> kernel: PCM: hw_ptr skipping! [Q] (pos=1024, delta=8192, period=1024,
>> jdelta=0/170/0, hw_ptr=140116992/140116992)
>>
>> When he does the 29 value it spams the log >one every second and he
>> didn't try too long to get it to fail before he switched to 101. I can
>> get the full log of the above too if it's useful or run the 29 test and
>> capture the output if it'll still help even tho it's not showing the error.
> 
> Another reply on the bug with some debug output:
> 
> https://qa.mandriva.com/show_bug.cgi?id=57010#c14
> 
> 
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=16376/8192/16384,
> hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900536/1884160
> hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
> hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
> hwptr log: pcmC0D0p:0: j=3421759, pos=0/8192/16384, hwptr=1900544/1900544
> PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=1900544/1900544)
> PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
> jdelta=1/371/0, hw_ptr=4882432/4882432)
> PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
> jdelta=0/371/0,hw_ptr=11395072/11395072)
> PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=13156352/13156352)
> PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=13893632/13893632)
> PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=20209664/20209664)
> PCM: hw_ptr skipping! [Q] (pos=8192, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=27860992/27860992)
> PCM: hw_ptr skipping! [Q] (pos=0, delta=16384, period=8192,
> jdelta=0/371/0, hw_ptr=28639232/28639232)


Does this info help at all? Is there anything else I can get the guys
suffering with this to do?

Col

-- 

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

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: Duplicate wake-ups in pcm_lib.c

[Colin Guthrie]

'Twas brillig, and Colin Guthrie at 25/01/10 11:52 did gyre and gimble:
> 'Twas brillig, and Colin Guthrie at 20/01/10 15:12 did gyre and gimble:
>> 'Twas brillig, and Colin Guthrie at 20/01/10 01:24 did gyre and gimble:
> Does this info help at all? Is there anything else I can get the guys
> suffering with this to do?

Following this thread:
hw_ptr_interrupt removal broke interrupt pointer updates

I'm guessing the fixes mentioned will address this bug. We're pushing
out a new kernel with these in so will let you know if any more problems
crop up. If I don't follow up, then assume it fixes things :)

Cheers

Col

-- 

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

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]