Created attachment 252250 [details]
shell testcase

This testcase (shell script using gst-launch) produces normal sound for hours (playing sound from alsasrc to alsasink) before it produces abnormal sound without message.

It uses hw:0 alsa interface by default, you can use another alsa interface modifying alsa_iface variable in source code.

Created attachment 252251 [details]
python3 testcase

This testcase (Python 3 script) produces normal sound for hours (playing sound from alsasrc to alsasink) before it produces abnormal sound without message.

It uses hw:0 alsa interface by default, you can use another alsa interface modifying alsa_iface variable in source code.

Can you check in the basesink, audioringbuffer, audiobase*, audiosink, audiosrc, alsa* debug categories if there are any interesting warnings at the time when everything goes bad?

I run my pipelines with GST_DEBUG=3 and there is no warning at all when the pipeline becomes silently. The only way to know that the pipeline is broken is to play a sound physically and attempt to hear it physically.

I can't use GST_DEBUG > 3 because load due to verbosity prevents the process to run properly, I can never hear a sound with a higher level of GST_DEBUG, so I cannot hear when the sound goes off, because it has never started. :)

When the pipeline becomes silent, I do 
pipeline.set_state(Gst.State.NULL)
pipeline.set_state(Gst.State.PLAYING)
Then the sound comes back. The pipeline is not really broken. I don't need to destroy it, only pause and re-playback it. It's running but does not do what to do.

Unfortunately the timing of the bug is quite unpredictable, it is often more than 12 hours, so I usually can not do more than one test per day…

Is it enough to set the pipeline back to PAUSED and then PLAYING to make it work again? Or is NULL really required? Are the source and sink both on the same physical device, thus sharing a hardware clock?

And are they using the same sample rate or does resampling happen?

> Is it enough to set the pipeline back to PAUSED
> and then PLAYING to make it work again? Or is
> NULL really required?

NULL seems required.

> Are the source and sink both on the same physical
> device, thus sharing a hardware clock?

The "alsasrc ! … ! alsasink" pipeline is only for demonstration purpose : the bug appears *also* with this pipeline, and I can verify the bug with this simple pipeline putting a physical source and physical monitor to ear sound (or not due to the bug when the bug appears :) ).

But I have tested thoses pipelines (written from memory, you get the idea) :

1. Using alsasrc without alsasink

alsasrc ! something

2. Using alsasink without alsasrc

something ! alsasink

3. Pipelining alsasrc to alsasink with same interface

alsasrc device="hw:0" ! something ! alsasink device="hw:0"

4. Pipelining alsasrc to alsasink with different interface

alsasrc device="hw:0" ! something ! alsasink device="hw:1"

5. Using alsasrc or alsasink using dmix or dsnoop alsa module (software mixer to not monopolize the interface)

alsasrc device="dsnoop:hw:0" ! something
something ! alsasink device="dmix:hw:0"

6. Using alsasrc or alsasink using plug alsa module (resampling and conversion done on the alsa side)

alsasrc device="plug:hw:0" ! something
something ! alsasink device="plug:hw:0"

7. Using alsasrc and/or alsasink with a combination of plug and dmix alsa modules.

alsasrc device="intel_in" ! something

with that in ~/.asoundrc :

---8<------------------------------------
pcm.intel_in {
	type plug
	slave.pcm {
		type dsnoop
		ipc_key 1024
		slave {
		        pcm "hw:1,0" 
		}
	}
}
---8<------------------------------------

8. Using alsasrc and/or alsasink with audioconvert and audioresample Gstreamer module

alsasrc ! audioconvert ! audioresample ! something

9. Using alsasrc and/or alsasink with audioconvert and audioresample Gstreamer module plus plug and/or dmix or dsnoop alsa module

alsasrc device="intel_in" ! audioconvert ! audioresample ! something

10. using same interface with same format and same sampling

11. using same or different interfaces (with or without alsa module) with forced different format and/or sampling

alsasrc ! 'audio/x-raw, format=S16LE, rate=44100' ! audioconvert! audioresample ! 'audio/x-raw, format=F32LE, rate=96000' ! audioconvert ! audioresample ! 'audio/x-raw, format=S16LE, rate=48000' ! alsasink

(Or something like that)

12. using similar pipeline but changing only the alsasrc or alsasink module

with bug : 

alsasrc ! audioconvert ! audioresample ! 'somecaps' ! opusenc ! rtpopuspay ! udpsink

without bug :

jackaudiosrc ! audioconvert ! audioresample ! 'somecaps' ! opusenc ! rtpopuspay ! udpsink

All the modules used in the pipelines using alsasrc or alsasink module where tested in another pipelines without alsasrc or alsasink module, and the bug appears only with the alsasrc and alsasink modules.

IRL, I use more complexe scenario like that :

alsasrc ! something ! jackaudiosink → (jack patchbay with multiple jack clients, some of them doing) → jackaudiosrc ! something ! opusenc ! rtpopuspay ! udpsink → (network) → udpsrc ! rtpjitterbuffer ! rtpopusdepay ! something ! jackaudiosink → (another jack patchbay with multiple jack clients, some of them doing) → jackaudiosrc ! something ! alsasink

I am streaming sound over the network from and to multiple distant sites with jack pachbay on each sites and some alsasrc / alsasink modules dynamically plugged or unplugged to the jack patchbay.

The pipeline "alsasrc ! something ! alsasink" is only a reduced testcase which is sufficient to find the bug. :)

Note : I always use "sync=false" when pipelining alsasrc or alsasink module with another realtime module (like pipelining alsasrc with alsasink or alsasrc with jackaudiosink, for example). I've never had good sound (noisy, silent or jerky) using "sync=true" with the alsasrc module or the alsasink module.

The bug only appears in very long waiting. For example I'm trying to run a test for more than 18 hours to make a backtrace as requested here:

http://gstreamer-devel.966125.n4.nabble.com/long-run-gstreamer-stops-working-without-message-td4655520.html#message4661617

But the bug is not yet appeared (but sometimes the bug appears even in only three hours, it is variable)…

It is difficult to track ! :)

Good News, I have a "silent pipeline" near to me ! :)

(from developer mail list) :
2013/8/19 Robert Krakora <rob.krakora@messagenetsystems.com>:
> Hi Thomas,
> Have you used gdb to attach to the process running your pipeline and
> examined the back traces on each thread?  That would be helpful.

OK, I have a "silent pipeline" with gdb attached on it near to me.

Yesterday I have launched this pipeline (without alsa software mixer or converter) :

gst-launch-1.0 -v alsasrc device="hw:1" ! audioconvert ! audioresample ! "audio/x-raw, format=S16LE, channels=2" ! alsasink device="hw:1" sync=false

Same audio interface, same sampling (audio interface physically configured to 44100), same format.

The Interface is a Zoom H2n http://www.zoom.co.jp/products/h2n/ which is cool to do some test :
* no hardware mixer (does not allow multiple recording or multiple playing simultaneously)
* hardware volume control of input and output can't be controlled from software
* hardware volume control can only be controlled manually on the interface (analogic input volume control, numeric output volume control)
* vumeter integrated to the interface (shows input level)
* the sampling configuration (48000 or 44100) is set manually on the audio interface at power on and cannot be changed on the fly

There is no doubt with this audio interface : I am testing on the PC only Gstreamer and alsa, not another hidden thing.

===== Software versions : =======

illwieckz@computer ~ $ lsb_release -i -c -r
Distributor ID:	Ubuntu
Release:	13.04
Codename:	raring

illwieckz@computer ~ $ uname -s -r -v -p -o
Linux 3.8.0-29-generic #42-Ubuntu SMP Tue Aug 13 19:40:39 UTC 2013 x86_64 GNU/Linux

illwieckz@computer ~ $ gst-inspect-1.0 alsasrc | grep Version
  Version:		1.0.6
illwieckz@computer ~ $ gst-inspect-1.0 alsasink | grep Version
  Version:		1.0.6

illwieckz@computer ~ $ apt-cache show gstreamer1.0-tools | grep Version
Version: 1.0.6-1
illwieckz@computer ~ $ apt-cache show gstreamer1.0-alsa | grep Version
Version: 1.0.6-1
Gstreamer-Version: 1.0
illwieckz@computer ~ $ apt-cache show alsa-base | grep Version
Version: 1.0.25+dfsg-0ubuntu4

=================================

This the stdios (nothing since yesterday) :

---8<-------------------------------------------------------------------------
illwieckz@computer ~ $ gst-launch-1.0 -v alsasrc device="$alsa_iface" ! audioconvert ! audioresample ! "audio/x-raw, format=S16LE, channels=2" ! alsasink device="$alsa_iface" sync=false
gst-launch-1.0 -v alsasrc device="$alsa_iface" ! audioconvert ! audioresample ! "audio/x-raw, format=S16LE, channels=2" ! alsasink device="$alsa_iface" sync=false
Définition du pipeline à PAUSED...
Le pipeline est actif et n'a pas besoin de phase PREROLL...
0:00:00.126688143  8539      0x1265370 FIXME                default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<alsasrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
Passage du pipeline à la phase PLAYING...
New clock: GstAudioSrcClock
0:00:00.128505331  8539      0x1265370 WARN                    alsa pcm_hw.c:1401:_snd_pcm_hw_open: alsalib error: Invalid value for card
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0: actual-buffer-time = 200000
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0: actual-latency-time = 10000
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioConvert:audioconvert0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioResample:audioresample0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstCapsFilter:capsfilter0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAlsaSink:alsasink0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstCapsFilter:capsfilter0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioResample:audioresample0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioConvert:audioconvert0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
---8<-------------------------------------------------------------------------
(nothing new since yesterday, nothing printed when bug appears)


More than 18 hours later (just now), the pipeline become silent.

I hear the audio source (physically) , also, the audio interface has an integrated vu-metter showing the input level, the audio input is ok (vu-metter showing the volume of the sound and variations).
But the output of the audio interface is silent.

====== schema, yesterday ======

physical audio source
↓
[→ physical speaker (sound ok)
↓
physical input of audiointerface (vu metter ok)
[computer with gstreamer "alsasrc ! … ! alsasink" pipeline]
physical output of audiointerface
↓
physical speaker (sound ok)

============================

====== schema, today ==========

physical audio source
↓
[→ physical speaker (sound ok)
↓
physical input of audiointerface (vu metter ok)
[computer with gstreamer "alsasrc ! … ! alsasink" pipeline]
physical output of audiointerface
↓
physical speaker (sound not ok, silence)

============================

This is a strace BEFORE bug (yesterday) :

---8<-------------------------------------------------------------------------
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
---8<-------------------------------------------------------------------------
(endlessly)

This a gdb trace BEFORE bug (yesterday) :

---8<-------------------------------------------------------------------------
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff7268b000
0x00007f045fb233cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) info threads
  Id   Target Id         Frame
  4    Thread 0x7f045a7d1700 (LWP 8540) "alsasrc0:src" 0x00007f045fe09ca4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  3    Thread 0x7f0459fd0700 (LWP 8541) "audiosrc-ringbu" 0x00007f045fb27747 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
  2    Thread 0x7f04597cf700 (LWP 8542) "audiosink-ringb" 0x00007f045fb233cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
* 1    Thread 0x7f0460a42740 (LWP 8539) "gst-launch-1.0" 0x00007f045fb233cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread apply all backtrace

+ Trace 232403

I'm not familiar with gdb, what can I do for you ?

I can keep the bugged processes alive some hours or day if you have some things to ask me to do. And pray that I do not have power outages. :)

take care, bugzilla have truncated my message (merged two traces), please expand the trace to get my full message.

Hi Thomas,

Two things to try so that we can narrow down to a definite cause.

1)  Put a queue (see below pipeline) right before alsasink and rerun test (if you have not already tried placing a queue right before alsasink already).

gst-launch-1.0 -v alsasrc device="$alsa_iface" ! audioconvert !
audioresample ! "audio/x-raw, format=S16LE, channels=2" ! queue ! alsasink
device="$alsa_iface" sync=false

2)  Cut the number of channels down to one (see below pipeline) and rerun test.

gst-launch-1.0 -v alsasrc device="$alsa_iface" ! audioconvert !
audioresample ! "audio/x-raw, format=S16LE, channels=1" ! alsasink
device="$alsa_iface" sync=false

Best Regards,

Rob

P.S. I know that this is monotonous and tedious.  I just got done fixing a bug that required me to do numerous runs of a pipeline over 24->48 hour periods to identify, fix and test.

> 1)  Put a queue (see below pipeline) right before alsasink
> and rerun test (if you have not already tried placing a
> queue right before alsasink already).

Already done. same result.

But this was more than one year ago, with linux 2.6 kernel, gstreamer 0.10 etc.
Before retrying I want to be sure to do the maximum I can with my currently "out of order pipeline" (still running but silently). ;)

> 2)  Cut the number of channels down to one (see below
> pipeline) and rerun test.

Already done, with two cases :

* Stereo interface (the more common on the market), usage of "channels=1" means sound is physically recorded on both channels but Gstreamer uses only one channel.

* Multiple and independent channels interface (like the Juli@ XTE http://www.esi-audio.com/products/juliaxte/ ), usage of "channels=1" means sound is physically recorded only on the first channel.

Same result in both cases.

This tests was done more recently (one month or two).

Because I have near me an "out of order pipeline" (seems running well but silently) which is hard to get and precious, if you have some manipulation to do on it (without killing it) do not hesitate to suggest. :)

This is very interesting from a prior comment on this bug report...

When the pipeline becomes silent, I do 
pipeline.set_state(Gst.State.NULL)
pipeline.set_state(Gst.State.PLAYING)
Then the sound comes back. The pipeline is not really broken. I don't need to
destroy it, only pause and re-playback it. It's running but does not do what to
do.

Have you tried a pipeline like this...

gst-launch-1.0 -v alsasrc device="$alsa_iface" ! queue ! alsasink
device="$alsa_iface" sync=false

...to try to isolate the problem without audio conversion and resampling?

> This is very interesting from a prior
> comment on this bug report...

Be careful, when I wrote "only pause and re-playback it", the word "pause" was
not really correct, "stop" is better.

This is what I mean (it works):

pipeline.set_state(Gst.State.NULL)
pipeline.set_state(Gst.State.PLAYING)

This is NOT what I mean (it does not work):

pipeline.set_state(Gst.State.PAUSED)
pipeline.set_state(Gst.State.PLAYING)

> Have you tried a pipeline like this...
> 
> gst-launch-1.0 -v alsasrc device="$alsa_iface" ! queue
> ! alsasink device="$alsa_iface" sync=false
> 
> ...to try to isolate the problem without audio conversion and resampling?

I will do this. But for your information, audioconvert and audioresample function properly with other modules (like jackaudiosrc or jackaudiosink).

I'll try to get a computer with multiple sound cards for doing several different tests in parallel.

OK. I have the another computer with plenty of soundcards! :)

*********** first computer:

** hw:0 / hw:Intel (Integrated PCI HDA Intel 82801H)
shell$ gst-launch-1.0 audiotestsrc ! alsasink device=hw:0

state: running at this time. Is this pipeline will survive ?

** hw:1 / hw:H2n (USB-Audio ZOOM Corporation H2n)
shell$ gst-launch-1.0 -v alsasrc device="hw:1" ! audioconvert ! audioresample ! "audio/x-raw, format=S16LE, channels=2" ! alsasink device="hw:1" sync=false

state : stuck silently

*********** second computer:

** hw:0 / hw:XFi (PCI Creative X-Fi 20K1 SB-XFi)
shell$ gst-launch-1.0 -v alsasrc device=hw:XFi ! queue ! alsasink device=hw:XFi sync=false

state: running at this time. Is this pipeline will survive ?

** hw:1 / hw:Intel (Integrated PCI HDA Intel 82801H)
shell$ gst-launch-1.0 -v alsasrc device=hw:Intel ! alsasink device=hw:Intel sync=false

state: running at this time. Is this pipeline will survive ?

** hw:2 / hw:Juli (PCIe ESI Juli@ ICE1724)
python3> import gi
python3> gi.require_version("Gst", "1.0")
python3> from gi.repository import Gst, GObject
python3> GObject.threads_init()
python3> Gst.init(None)
python3> mainloop = GObject.MainLoop()
python3> pipeline_src = Gst.parse_launch("alsasrc device=hw:Juli ! capsfilter caps=\"audio/x-raw, format=S32LE, rate=48000, channels=2\" ! audioconvert ! audioresample ! capsfilter caps=\"audio/x-raw, format=F32LE, rate=48000, channels=2\" ! jackaudiosink client-name=pipeline_src sync=false connect=none")
python3> pipeline_sink = Gst.parse_launch("jackaudiosrc client-name=pipeline_sink connect=none ! capsfilter caps=\"audio/x-raw, format=F32LE, rate=48000, channels=2\" ! audioconvert ! audioresample ! capsfilter caps=\"audio/x-raw, format=S32LE, rate=48000, channels=2\" ! alsasink device=hw:Juli")
python3> pipeline_src.set_state(Gst.State.PLAYING)
python3> pipeline_sink.set_state(Gst.State.PLAYING)
python3> mainloop.run()

shell$ jack_connect pipeline_src:out_jackaudiosink0_1 pipeline_sink:in_jackaudiosrc0_1
shell$ jack_connect pipeline_src:out_jackaudiosink0_2 pipeline_sink:in_jackaudiosrc0_2

I have two pipelines, one for recording (alsa to jack), one for playing (jack to alsa), they are independent.

state: running at this time. Is this pipelines will survive ?

** hw:3 / hw:Live (PCI Creative SB Live! PCI512 [CT4790] EMU10K1)
(doing nothing for the moment, available for testing without interrupting other current tests)

** hw:4 / hw:Live1 (PCI Creative SB Live! Value [CT4832] EMU10K1)
(doing nothing for the moment, available for testing without interrupting other current tests)

** hw:5 / hw:CODEC (USB-Audio - USB Audio Behringer UCA202 PCM2902 CODEC)
shell$ arecord -D hw:CODEC -f cd | aplay -D hw:CODEC -f cd -vv -V stereo 2>/dev/null

It's an equivalent to "alsasrc device=hw:CODEC ! audio/x-raw, format=S16LE, rate=44100, channels=2 ! alsasink device=hw:CODEC" plus this give to me a minimalistic vu-meter. If I plug any soundcard output to this USB soundcard, I will have an audio level on the vu-meter plus sound on the output. (Note: I've never seen this command having a bug).

I will tell you in 20 hours, which will happened to these tests.

If someone have an idea to analyze the pipeline that is currently blocked, feel free. :)
(I can publish a core dump of the stuck pipeline, too)

I don't know if it's related, but the "jackaudiosrc ! something ! alsasink" pipeline is already silent, with this warnings :

3:10:28.749922345  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22368487 > 20000000
3:10:28.835282275  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26789292 > 20000000
3:10:28.899285230  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20226399 > 20000000
3:10:28.984600807  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24902673 > 20000000
3:10:29.069924610  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 29023691 > 20000000
3:10:29.133922377  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22257800 > 20000000
3:10:29.219280882  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26694174 > 20000000
3:10:29.283289478  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20142525 > 20000000
3:10:29.368592074  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24828802 > 20000000
3:10:29.453926063  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28960996 > 20000000
3:10:29.517934841  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22203243 > 20000000
3:10:29.603280942  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26648728 > 20000000
3:10:29.667273221  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20103653 > 20000000
3:10:29.752589982  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24797089 > 20000000
3:10:29.837923860  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28930699 > 20000000
3:10:29.901932864  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22178304 > 20000000
3:10:29.987273560  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26629207 > 20000000
3:10:30.051276782  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20088428 > 20000000
3:10:30.136589190  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24788652 > 20000000
3:10:30.221924657  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28930763 > 20000000
3:10:30.285925718  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22180885 > 20000000
3:10:30.371283903  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26634003 > 20000000
3:10:30.435292035  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20092789 > 20000000
3:10:30.520599902  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24794938 > 20000000
3:10:30.605926257  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28936300 > 20000000
3:10:30.669925694  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22185918 > 20000000
3:10:30.755283493  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26638436 > 20000000
3:10:30.819283934  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20096819 > 20000000
3:10:30.904630750  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24798486 > 20000000
3:10:30.989924298  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28939424 > 20000000
3:10:31.053924563  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22188759 > 20000000
3:10:31.139290315  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26640937 > 20000000
3:10:31.203290190  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20099092 > 20000000
3:10:31.288589956  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24800488 > 20000000
3:10:31.373930484  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 28941188 > 20000000
3:10:31.437924383  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 22192806 > 20000000
3:10:31.523296157  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 26647106 > 20000000
3:10:31.587281206  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20104701 > 20000000
3:10:31.672592811  4684 0xb0102690 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24807950 > 20000000
(endlessly)

But the bug that I track do not emits warnings usually…

Interesting...let me take a look a the source and see what it is complaining about..

Check this out:

http://gstreamer-devel.966125.n4.nabble.com/Timestamp-drift-when-using-dmix-dsnoop-plugins-with-alsasrc-sink-td4658874.html

Have you tried adding "slave-method=2 provide-clock=true" properties to the alsasink plugin in the pipeline?  Try...

"jackaudiosrc ! something ! alsasink slave-method=2 provide-clock=true"

...since "jackaudiosrc ! something ! alsasink" seems to fail the quickest...

Also it can help to use provide-clock=false on alsasrc and alsasink. In that case it will use the systemclock for the pipeline and will try to use the driver timestamps of both devices to properly synchronize everything.

Robert Krakora wrote:
> Check this out:
> http://gstreamer-devel.966125.n4.nabble.com/Timestamp-drift-when-using-dmix-dsnoop-plugins-with-alsasrc-sink-td4658874.html

That's interesting, it's very similar to my problem, but with some differences :

1. For him these three usecases has different effects :

* alsasrc device="default"
* alsasrc device="dsnoop:hw:0"
* alsasrc device="hw:0"

For me, these three usecases has same effect.

2. For him, the problem occurs according to the usecase and we hear right now if it does not work well.

For me the problem occurs in any case and can not be heard immediately, it takes hours to check.

3. He have warnings when the pipeline goes wrong.

Except for the pipeline of yesterday (jackaudiosrc ! … ! alsasink), I have no warnings. Perhaps with this particular pipeline I also get the same bug that he, in addition.

But these two bugs are probably related.

4. He can publish small log

He had attached a small "GST_DEBUG=5" log (57K uncompressed) that shows his bug.

Yesterday I have found a computer that can run my pipeline with "GST_DEBUG=5" and which is fast enough to output debug information without interfering with the sound processing. The bug has not yet occurred, and I have already more than 1.1Gb of compressed log (with xz). If unfortunately I will not be exactly next to the machine to hear when the bug will happen, to say "I can cut the log, the problem is just at the end", I'll have to search through billions of lines.

Robert Krakora wrote:
> Have you tried adding "slave-method=2 provide-clock=true"
> properties to the alsasink plugin in the pipeline?  Try...
> "jackaudiosrc ! something ! alsasink slave-method=2 provide-clock=true"

Sebastian Dröge wrote:
> Also it can help to use provide-clock=false on alsasrc
> and alsasink. In that case it will use the systemclock
> for the pipeline and will try to use the driver
> timestamps of both devices to properly synchronize
> everything.

OK I have two soundcards that are not used yet, I'll try both.
Sebastian, which slave-method I have to use to test the "provide-clock=false" ?

Sorry, for my previous "alsasrc ! something ! jackaudiosink" (the one with warnings) I have forgotten to write "sync=false". This test is probably not reliable. I usually use this option and the pipeline requires more time to bug.

I'm running these tests :

** hw:3 / hw:Live (PCI Creative SB Live! PCI512 [CT4790] EMU10K1)

gst-launch-1.0 jackaudiosrc client-name=live_sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:Live slave-method=2 provide-clock=true

(within 5 min the sound is stuttering)

Trying this new test (but does that make sense?):

gst-launch-1.0 jackaudiosrc client-name=live_sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:Live slave-method=2 provide-clock=true sync=false

** hw:4 / hw:Live1 (PCI Creative SB Live! Value [CT4832] EMU10K1)

gst-launch-1.0 alsasrc device=hw:Live1 ! alsasink device=hw:Live1 provide-clock=false

I think Sebastian's Comment #20, setting provide-clock=false for both alsasrc and alsasink will be the most telling.  It is a very good suggestion.

OK, I'm testing this right now :

** hw:4 / hw:Live1 (PCI Creative SB Live! Value [CT4832] EMU10K1)

gst-launch-1.0 alsasrc device=hw:Live1 provide-clock=false ! alsasink device=hw:Live1 provide-clock=false

(for information, no other tests have yet failed, they was launched less than 20 hours ago :/ )

The "alsasrc device=hw:Live1 provide-clock=false ! alsasink
device=hw:Live1 provide-clock=false" pipeline is stuttering

With these warnings (sorry, I forget to export LANG=C before running the pipeline) :

AVERTISSEMENT : de l'élément /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0 : Impossible d'enregistrer assez rapidement les données audio
Information de débogage supplémentaire :
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0:
Dropped 8192 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:22:20.197899874  5471  0x8436490 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<alsasrc0> create DISCONT of 8192 samples at sample 59109376
0:22:20.197975561  5471  0x8436490 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Impossible d'enregistrer assez rapidement les données audio
0:22:20.198000943  5471  0x8436490 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Dropped 8192 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

OK...that was a good test though.  These are the type of warning messages I would expect you to see when your original pipelines fail.  The trace above is an overrun scenario.

Getting back to your original pipeline's that fail after some 24 or so, does audio ever come back?

In english the warnings are :

WARNING: from element /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0: Can't record audio fast enough
Additional debug info:
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0:
Dropped 8192 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
0:20:28.942838168  5477  0x862fc90 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<alsasrc0> create DISCONT of 8192 samples at sample 54202368
0:20:28.942891492  5477  0x862fc90 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Can't record audio fast enough
0:20:28.942915922  5477  0x862fc90 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Dropped 8192 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

(yes it fails within 20min without sync=false)

Robert Krakora
> OK...that was a good test though.  These are the type
> of warning messages I would expect you to see when your
> original pipelines fail.  The trace above is an overrun
> scenario.

Actually, I remember that it is because I get similar behavior in every pipeline that I use "sync=false" everywhere since two years, it's like a trick.

The differences between pipeline using or not "sync=false" are:

with "sync=false":

* fails within an hour, sometime immediately
* sound is stuttering

without "sync=false"

* fails within many hours (3 hours to 24 hours, usually more than 12 hours)
* silence

Varying other parameters than "sync" are only changing the way the sound is deteriorated (stuttering, noise, silence) or the time before that happens.

> Getting back to your original pipeline's that fail after
> some 24 or so, does audio ever come back?

Audio never comes back.

I was lucky enough to be there sometimes when the sound cut. The cut is clean, as if the pipeline stopped. No noise, no stuttering. The sound stops cleanly.

"sync=true" means sync with video stream.  I use "sync=false" with video only and audio only streams.

The fact that audio goes out and never comes back sure sounds like an audio drift scenario, but the fact that you never see any warning messages is certainly disconcerting.  This is a big problem.

(In reply to comment #28)
> "sync=true" means sync with video stream.  I use "sync=false" with video only
> and audio only streams.

No it does not mean that. You should only ever use sync=false if you don't care if your media is played in realtime or not.

Really.  OK.  I thought it needed to be set to "true" when audio playback was slaved to video clock or visa/versa (as it seems to be implicitly set to "true").

In fact I use "sync = false" because it is the only thing that made ​​my pipelines working several hours.

But actually my application is supposed to be real time. The jack server and the kernel are already configured in real time, but I have not tried to do with GStreamer.

Is "sync = true" means real-time? In that event, this is what I should use, although it does not work.

You should use sync=true, and if that doesn't work this has to be fixed :)

Really.  OK.  I thought it needed to be set to "true" when audio playback was slaved to video clock or visa/versa (as it seems to be implicitly set to "true").

I see.  I have only experienced "sync=true" working on A/V streams and not on audio only or video only streams.  On those I have had to use "sync=false" like Thomas.

Good News ! I have a failed pipeline running with GST_DEBUG=5.
I have 36Gb of uncompressed logfile, but it shows me endless xruns in DEBUG since the silence occurs.

Cool.

The first xrun since the silence (there was two or three xruns since the start but are unrelated) is at 14:28:48, or 52128s (it does not look like a known magic number).

Normal output:

----8<------------------------------------------
0:14:43.766123708 26625      0x1610190 DEBUG             GST_MEMORY gstmemory.c:133:gst_memory_init: new memory 0x7f8b2c0126a0, maxsize:1543 offset:0 size:1536
0:14:43.766122801 26625      0x1610230 DEBUG               basesink gstbasesink.c:3168:gst_base_sink_chain_unlocked:<alsasink0> got times start: 0:14:42.747210884, end: 0:14:42.755918367
0:14:43.766139077 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 101379, sample 38929536, read from 101379-0, to_read 384, diff 0, segtotal 23, segsize 1536
0:14:43.766154333 26625      0x1610230 DEBUG               basesink gstbasesink.c:1803:gst_base_sink_get_sync_times:<alsasink0> got times start: 0:14:42.747210884, stop: 0:14:42.755918367, do_sync 0
0:14:43.766166008 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1281:wait_segment:<audiosrcringbuffer0> waiting..
0:14:43.766180904 26625      0x1610230 DEBUG               basesink gstbasesink.c:3209:gst_base_sink_chain_unlocked:<alsasink0> rendering object 0x7f8b2c011300
0:14:43.766205628 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1664:gst_audio_base_sink_render:<alsasink0> time 0:14:42.747210884, offset 38929152, start 0:00:00.000000000, samples 384
0:14:43.766219843 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1701:gst_audio_base_sink_render:<alsasink0> sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
0:14:43.766230219 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1751:gst_audio_base_sink_render:<alsasink0> no sync needed. Using render_start=38941056
0:14:43.766238838 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1885:gst_audio_base_sink_render:<alsasink0> rendering at 38941056 384/384
0:14:43.766250048 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1490:default_commit: pointer at 101400, write to 101409-0, diff 9, segtotal 23, segsize 1536, base 0
0:14:43.766260279 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1521:default_commit:<audiosinkringbuffer0> write @0x7f8b34003400 seg 2, sps 384, off 0, avail 1536
0:14:43.766269660 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1547:default_commit: copy 1536 bytes
0:14:43.766278604 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1896:gst_audio_base_sink_render:<alsasink0> wrote 384 of 384
0:14:43.766287674 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1928:gst_audio_base_sink_render:<alsasink0> next sample expected at 38941440
0:14:43.766296194 26625      0x1610230 DEBUG               basesink gstbasesink.c:3248:gst_base_sink_chain_unlocked:<alsasink0> object unref after render 0x7f8b2c011300
0:14:43.766305118 26625      0x1610230 DEBUG             GST_MEMORY gstmemory.c:86:_gst_memory_free: free memory 0x7f8b2c012000
0:14:43.766319326 26625      0x1610230 DEBUG         queue_dataflow gstqueue.c:1149:gst_queue_loop:<queue0> queue is empty
0:14:43.771431920 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written 384 frames out of 384
0:14:43.774634964 26625 0x7f8b2c003630 INFO              ringbuffer gstaudioringbuffer.c:1966:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer0> Storing timestamp 99:99:99.999999999 @ 18
0:14:43.774683267 26625 0x7f8b2c003630 DEBUG             ringbuffer gstaudioringbuffer.c:1851:gst_audio_ring_buffer_advance:<audiosrcringbuffer0> signal waiter
0:14:43.774771007 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 101380, sample 38929536, read from 101379-0, to_read 384, diff 1, segtotal 23, segsize 1536
0:14:43.774818365 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1733:gst_audio_ring_buffer_read:<audiosrcringbuffer0> read @0x7f8b2c00d930 seg 18, off 0, sampleslen 384
0:14:43.774844454 26625      0x1610190 INFO              ringbuffer gstaudioringbuffer.c:1761:gst_audio_ring_buffer_read:<audiosrcringbuffer0> Retrieved timestamp 99:99:99.999999999 @ 18
0:14:43.774850959 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:821:gst_audio_base_src_create:<alsasrc0> read 384 of 384
0:14:43.774860402 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2213:gst_base_src_do_sync:<alsasrc0> no sync needed
0:14:43.774866679 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2414:gst_base_src_get_range:<alsasrc0> buffer ok
0:14:43.774893048 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2351:gst_base_src_get_range:<alsasrc0> calling create offset 18446744073709551615 length 0, time 0
0:14:43.774900158 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:721:gst_audio_base_src_get_offset:<alsasrc0> at segment 101380 and sample 38929920
0:14:43.774905381 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:744:gst_audio_base_src_get_offset:<alsasrc0> reading from 101380, we are at 101380, sample 38929920
0:14:43.774910744 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:799:gst_audio_base_src_create:<alsasrc0> reading from sample 38929920 length 1536
----8<------------------------------------------
(endlessly)

Abnormal output (after the silence occurs):

----8<------------------------------------------
14:29:05.895356358 26625      0x1610190 DEBUG             GST_MEMORY gstmemory.c:133:gst_memory_init: new memory 0x7f8b2c0126a0, maxsize:1543 offset:0 size:1536
14:29:05.895368792 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 5986895, sample 2298967680, read from 5986895-0, to_read 384, diff 0, segtotal 23, segsize 1536
14:29:05.895380135 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1281:wait_segment:<audiosrcringbuffer0> waiting..
14:29:05.895314747 26625      0x1610230 DEBUG         queue_dataflow gstqueue.c:1161:gst_queue_loop:<queue0> queue is not empty
14:29:05.895407136 26625      0x1610230 DEBUG               basesink gstbasesink.c:3168:gst_base_sink_chain_unlocked:<alsasink0> got times start: 14:28:50.777687074, end: 14:28:50.786394557
14:29:05.895419691 26625      0x1610230 DEBUG               basesink gstbasesink.c:1803:gst_base_sink_get_sync_times:<alsasink0> got times start: 14:28:50.777687074, stop: 14:28:50.786394557, do_sync 0
14:29:05.895431416 26625      0x1610230 DEBUG               basesink gstbasesink.c:3209:gst_base_sink_chain_unlocked:<alsasink0> rendering object 0x7f8b2c0111f0
14:29:05.895442079 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1664:gst_audio_base_sink_render:<alsasink0> time 14:28:50.777687074, offset 2298967296, start 0:00:00.000000000, samples 384
14:29:05.895454969 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1701:gst_audio_base_sink_render:<alsasink0> sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
14:29:05.895465726 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1751:gst_audio_base_sink_render:<alsasink0> no sync needed. Using render_start=18446744071713611904
14:29:05.895475361 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1885:gst_audio_base_sink_render:<alsasink0> rendering at 18446744071713611904 384/384
14:29:05.895485044 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1490:default_commit: pointer at 5987050, write to -1436853525-0, diff -1442840575, segtotal 23, segsize 1536, base 0
14:29:05.895494841 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1521:default_commit:<audiosinkringbuffer0> write @0x7f8b33fff200 seg -9, sps 384, off 0, avail 1536
14:29:05.895504454 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1547:default_commit: copy 1536 bytes
14:29:05.895514573 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1896:gst_audio_base_sink_render:<alsasink0> wrote 384 of 384
14:29:05.895522992 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1928:gst_audio_base_sink_render:<alsasink0> next sample expected at 18446744071713612288
14:29:05.895531653 26625      0x1610230 DEBUG               basesink gstbasesink.c:3248:gst_base_sink_chain_unlocked:<alsasink0> object unref after render 0x7f8b2c0111f0
14:29:05.895540936 26625      0x1610230 DEBUG             GST_MEMORY gstmemory.c:86:_gst_memory_free: free memory 0x7f8b2c012000
14:29:05.895552551 26625      0x1610230 DEBUG         queue_dataflow gstqueue.c:1149:gst_queue_loop:<queue0> queue is empty
14:29:05.897220447 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written 384 frames out of 384
14:29:05.903790547 26625 0x7f8b2c003630 INFO              ringbuffer gstaudioringbuffer.c:1966:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer0> Storing timestamp 99:99:99.999999999 @ 18
14:29:05.903814778 26625 0x7f8b2c003630 DEBUG             ringbuffer gstaudioringbuffer.c:1851:gst_audio_ring_buffer_advance:<audiosrcringbuffer0> signal waiter
14:29:05.903834577 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 5986896, sample 2298967680, read from 5986895-0, to_read 384, diff 1, segtotal 23, segsize 1536
14:29:05.903850805 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1733:gst_audio_ring_buffer_read:<audiosrcringbuffer0> read @0x7f8b2c00d930 seg 18, off 0, sampleslen 384
14:29:05.903862467 26625      0x1610190 INFO              ringbuffer gstaudioringbuffer.c:1761:gst_audio_ring_buffer_read:<audiosrcringbuffer0> Retrieved timestamp 99:99:99.999999999 @ 18
14:29:05.903873311 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:821:gst_audio_base_src_create:<alsasrc0> read 384 of 384
14:29:05.903888559 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2213:gst_base_src_do_sync:<alsasrc0> no sync needed
14:29:05.903897918 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2414:gst_base_src_get_range:<alsasrc0> buffer ok
14:29:05.903920407 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2351:gst_base_src_get_range:<alsasrc0> calling create offset 18446744073709551615 length 0, time 0
14:29:05.903931604 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:721:gst_audio_base_src_get_offset:<alsasrc0> at segment 5986896 and sample 2298968064
14:29:05.903939887 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:744:gst_audio_base_src_get_offset:<alsasrc0> reading from 5986896, we are at 5986896, sample 2298968064
14:29:05.903949599 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:799:gst_audio_base_src_create:<alsasrc0> reading from sample 2298968064 length 1536
----8<------------------------------------------
(endlessly)

Sorry : abnormal output WITH xrun (all loops doesn't shows xruns)

----8<------------------------------------------
14:28:47.624935220 26625      0x1610190 DEBUG             GST_MEMORY gstmemory.c:133:gst_memory_init: new memory 0x7f8b2c0126a0, maxsize:1543 offset:0 size:1536
14:28:47.624944861 26625      0x1610230 DEBUG               basesink gstbasesink.c:1803:gst_base_sink_get_sync_times:<alsasink0> got times start: 14:28:33.667482993, stop: 14:28:33.676190476, do_sy
nc 0
14:28:47.624964960 26625      0x1610230 DEBUG               basesink gstbasesink.c:3209:gst_base_sink_chain_unlocked:<alsasink0> rendering object 0x7f8b2c0111f0
14:28:47.624954399 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 5984930, sample 2298213120, read from 5984930-0, to_read 384, d
iff 0, segtotal 23, segsize 1536
14:28:47.624983579 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1281:wait_segment:<audiosrcringbuffer0> waiting..
14:28:47.624974209 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1664:gst_audio_base_sink_render:<alsasink0> time 14:28:33.667482993, offset 2298212736, start 0:00:00.0000000
00, samples 384
14:28:47.625000377 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1701:gst_audio_base_sink_render:<alsasink0> sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
14:28:47.625006900 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1751:gst_audio_base_sink_render:<alsasink0> no sync needed. Using render_start=2298267648
14:28:47.625012143 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1885:gst_audio_base_sink_render:<alsasink0> rendering at 2298267648 384/384
14:28:47.625018140 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1490:default_commit: pointer at 5985063, write to 5985072-0, diff 9, segtotal 23, segsize 1536, base 0
14:28:48.792376363 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1521:default_commit:<audiosinkringbuffer0> write @0x7f8b34007000 seg 12, sps 384, off 0, avail 1536
14:28:48.792392207 26625      0x1610230 DEBUG             ringbuffer gstaudioringbuffer.c:1547:default_commit: copy 1536 bytes
14:28:48.792398946 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1896:gst_audio_base_sink_render:<alsasink0> wrote 384 of 384
14:28:48.792409188 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1928:gst_audio_base_sink_render:<alsasink0> next sample expected at 2298268032
14:28:47.627456987 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written 384 frames out of 384
14:28:47.633507946 26625 0x7f8b2c003630 INFO              ringbuffer gstaudioringbuffer.c:1966:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer0> Storing timestamp 99:99:99.999999999 @ 8
14:28:48.792424760 26625      0x1610230 DEBUG               basesink gstbasesink.c:3248:gst_base_sink_chain_unlocked:<alsasink0> object unref after render 0x7f8b2c0111f0
14:28:48.792458775 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:28:48.792460366 26625 0x7f8b2c003630 DEBUG             ringbuffer gstaudioringbuffer.c:1851:gst_audio_ring_buffer_advance:<audiosrcringbuffer0> signal waiter

14:28:48.792473553 26625      0x1610230 DEBUG             GST_MEMORY gstmemory.c:86:_gst_memory_free: free memory 0x7f8b2c012000
14:28:48.792502141 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read: pointer at 5984931, sample 2298213120, read from 5984930-0, to_read 384, d
iff 1, segtotal 23, segsize 1536
14:28:48.792526636 26625      0x1610190 DEBUG             ringbuffer gstaudioringbuffer.c:1733:gst_audio_ring_buffer_read:<audiosrcringbuffer0> read @0x7f8b2c009d30 seg 8, off 0, sampleslen 384
14:28:48.792510714 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:28:48.792484197 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written -32 frames out of 384
14:28:48.792509073 26625      0x1610230 DEBUG         queue_dataflow gstqueue.c:1149:gst_queue_loop:<queue0> queue is empty
14:28:48.792537577 26625      0x1610190 INFO              ringbuffer gstaudioringbuffer.c:1761:gst_audio_ring_buffer_read:<audiosrcringbuffer0> Retrieved timestamp 99:99:99.999999999 @ 8
14:28:48.792572219 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:28:48.792582661 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:821:gst_audio_base_src_create:<alsasrc0> read 384 of 384
14:28:48.792593378 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:28:48.792605551 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2213:gst_base_src_do_sync:<alsasrc0> no sync needed
14:28:48.792620385 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2414:gst_base_src_get_range:<alsasrc0> buffer ok
14:28:48.792640258 26625      0x1610230 DEBUG         queue_dataflow gstqueue.c:1161:gst_queue_loop:<queue0> queue is not empty
14:28:48.792639198 26625      0x1610190 DEBUG                basesrc gstbasesrc.c:2351:gst_base_src_get_range:<alsasrc0> calling create offset 18446744073709551615 length 0, time 0
14:28:48.792653400 26625      0x1610230 DEBUG               basesink gstbasesink.c:3168:gst_base_sink_chain_unlocked:<alsasink0> got times start: 14:28:33.676190476, end: 14:28:33.684897959
14:28:48.792657128 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:721:gst_audio_base_src_get_offset:<alsasrc0> at segment 5984931 and sample 2298213504
14:28:48.792663600 26625      0x1610230 DEBUG               basesink gstbasesink.c:1803:gst_base_sink_get_sync_times:<alsasink0> got times start: 14:28:33.676190476, stop: 14:28:33.684897959, do_sy
nc 0
14:28:48.792672367 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:744:gst_audio_base_src_get_offset:<alsasrc0> reading from 5984931, we are at 5984931, sample 2298213504
14:28:48.792689095 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written 384 frames out of 384
14:28:48.792704192 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0> written 384 frames out of 384
14:28:48.792686326 26625      0x1610230 DEBUG               basesink gstbasesink.c:3209:gst_base_sink_chain_unlocked:<alsasink0> rendering object 0x7f8b2c011300
14:28:48.792705651 26625      0x1610190 DEBUG           audiobasesrc gstaudiobasesrc.c:799:gst_audio_base_src_create:<alsasrc0> reading from sample 2298213504 length 1536
14:28:48.792725450 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1664:gst_audio_base_sink_render:<alsasink0> time 14:28:33.676190476, offset 2298213120, start 0:00:00.0000000
00, samples 384
14:28:48.792740574 26625      0x1610230 DEBUG          audiobasesink gstaudiobasesink.c:1701:gst_audio_base_sink_render:<alsasink0> sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
----8<------------------------------------------

Very interesting line...

gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue
-32

Looks like an EPIPE (32) on the snd_pcm_wait() call in gst_alsasink_write()...which xrun_recovery() attempts to handle...

/*
 *   Underrun and suspend recovery
 */
static gint
xrun_recovery (GstAlsaSink * alsa, snd_pcm_t * handle, gint err)
{
  GST_DEBUG_OBJECT (alsa, "xrun recovery %d: %s", err, g_strerror (err));

  if (err == -EPIPE) {          /* under-run */
    err = snd_pcm_prepare (handle);
    if (err < 0)
      GST_WARNING_OBJECT (alsa,
          "Can't recovery from underrun, prepare failed: %s",
          snd_strerror (err));
    return 0;
  } else if (err == -ESTRPIPE) {
    while ((err = snd_pcm_resume (handle)) == -EAGAIN)
      g_usleep (100);           /* wait until the suspend flag is released */

    if (err < 0) {
      err = snd_pcm_prepare (handle);
      if (err < 0)
        GST_WARNING_OBJECT (alsa,
            "Can't recovery from suspend, prepare failed: %s",
            snd_strerror (err));
    }
    return 0;
  }
  return err;
}

From this discussion it sounds as though snd_pcm_recover() needs to be called in the xrun_recovery() function instead of snd_pcm_prepare().

http://stackoverflow.com/questions/12842395/how-to-gracefully-recover-from-epipe-errors-in-alsa

(Sorry for the french output in logs)

If I "grep -v" the lines that are normally printed when all is ok I got this :

[Before this line, some init (manually filtered)]
----8<------------------------------------------
0:00:01.010961951 26625      0x1487800 DEBUG                GST_BUS gstbus.c:977:poll_func: mainloop 0x1667c30 quit
0:00:01.010970276 26625      0x1487800 DEBUG                GST_BUS gstbus.c:776:gst_bus_source_dispatch:<bus1> source 0x1652d40 handler returns 1
0:00:01.010977012 26625      0x1487800 DEBUG                GST_BUS gstbus.c:1087:gst_bus_poll: mainloop stopped 0x1667c30
0:00:01.010982794 26625      0x1487800 DEBUG                GST_BUS gstbus.c:1332:gst_bus_remove_signal_watch:<bus1> removing signal watch 37
0:00:01.010989419 26625      0x1487800 DEBUG                GST_BUS gstbus.c:797:gst_bus_source_finalize:<bus1> finalize source 0x1652d40
0:00:01.010997014 26625      0x1487800 DEBUG                GST_BUS gstbus.c:1100:gst_bus_poll:<bus1> finished poll with message 0x7f8b24002bb0
0:00:01.011009960 26625      0x1487800 DEBUG                GST_BUS gstbus.c:874:gst_bus_add_watch_full_unlocked:<bus1> New source 0x1652d40 with id 38
0:00:01.011015432 26625      0x1487800 DEBUG                GST_BUS gstbus.c:1085:gst_bus_poll: running mainloop 0x1669b50
----8<------------------------------------------
[Here the normal output begin (filtered by grep)]
----8<------------------------------------------
1:39:18.548386467 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
1:39:18.548478614 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
1:39:18.548444919 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
1:39:18.548522986 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ first xrun, just a little silence, the sound comes back (computer overloaded ?)]
----8<------------------------------------------
5:11:46.754841692 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
5:11:46.754985448 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
5:11:46.755004859 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
5:11:46.755006648 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ second xrun, just a little silence, the sound comes back (computer overloaded ?)]
----8<------------------------------------------
8:49:45.691399650 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
8:49:45.691438249 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
8:49:45.691451177 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
8:49:45.691725109 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ third xrun, just a little silence, the sound comes back (computer overloaded ?)]
----8<------------------------------------------
10:10:09.780821374 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
10:10:09.780871631 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
10:10:09.780879167 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
10:10:09.780811676 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ fourth xrun, just a little silence, the sound comes back (computer overloaded ?)]
----8<------------------------------------------
11:34:43.663271577 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
11:34:43.663336178 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
11:34:43.663343045 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
11:34:43.663423626 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ fifth xrun, just a little silence, the sound comes back (computer overloaded ?)]
----8<------------------------------------------
14:28:48.792458775 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:28:48.792510714 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:28:48.792572219 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:28:48.792593378 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ sixth xrun, a little silence then the sound comes back for only one second]
----8<------------------------------------------
14:29:18.561641218 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:29:18.561620176 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:29:18.561691630 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:29:18.561746935 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ seventh xrun, a little silence then the sound comes back for only one second]
----8<------------------------------------------
14:37:02.081587565 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:37:02.081590217 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:37:02.081647110 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:37:02.081663490 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[↑↑↑↑↑ eight xrun, silence, the sound never comes back]
----8<------------------------------------------
14:37:09.653318664 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:37:09.653356667 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:37:09.653379130 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:37:09.653389271 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:37:39.391359336 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:37:39.391426380 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:37:39.391566483 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:37:39.391580180 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:37:51.609751820 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:37:51.609767869 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:37:51.609840609 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:37:51.609880816 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:38:07.080395430 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:38:07.080340839 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:38:07.080532913 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:38:07.080543652 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:38:14.702682538 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:38:14.702752311 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:38:14.702791369 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:38:14.702816161 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:38:26.766826905 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:38:26.766843180 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:38:26.766856321 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:38:26.773252846 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:38:49.100970619 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:38:49.101167862 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:38:49.101205932 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:38:49.101226340 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:39:06.039074866 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:39:06.039121976 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:39:06.039206224 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:39:06.039308589 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:39:13.460915390 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:39:13.460942043 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:39:13.460956710 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:39:13.461264641 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:39:28.997048359 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:39:28.997113305 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
14:39:28.997261885 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:39:28.997287389 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:39:44.134017322 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32
14:39:44.134077422 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:1023:gst_alsasink_write:<alsasink0> Write error: Relais brisé (pipe)
14:39:44.134094772 26625 0x7f8b2c003a30 DEBUG                   alsa gstalsasink.c:960:xrun_recovery:<alsasink0> xrun recovery -32: Erreur inconnue -32
14:39:44.134140042 26625 0x7f8b2c003630 DEBUG                   alsa gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue -32
----8<------------------------------------------
[endlessly]


This is my grep filter (exclusion) :
===========================================
GST_ELEMENT_PADS gstelement.c:
GST_INIT gst.c:
GST_INIT gstmessage.c:
GST_MEMORY gstmemory.c:
GST_MEMORY gstallocator.c
GST_PLUGIN_LOADING gstplugin.c:
GST_REFCOUNTING gstobject.c:
GST_REGISTRY gstregistry.c:
GST_REGISTRY gstregistrybinary.c
GST_REGISTRY gstregistrychunks.c:
structure gststructure.c:
alsa gstalsasink.c:1021:
audiobasesink gstaudiobasesink.c:1664:
audiobasesink gstaudiobasesink.c:1701:
audiobasesink gstaudiobasesink.c:1751:
audiobasesink gstaudiobasesink.c:1885:
audiobasesink gstaudiobasesink.c:1896:
audiobasesink gstaudiobasesink.c:1928:
audiobasesrc gstaudiobasesrc.c:721:
audiobasesrc gstaudiobasesrc.c:744:
audiobasesrc gstaudiobasesrc.c:799:
audiobasesrc gstaudiobasesrc.c:821:
basesink gstbasesink.c:1803:
basesink gstbasesink.c:3168:
basesink gstbasesink.c:3209:
basesink gstbasesink.c:3248:
basesrc gstbasesrc.c:2213:
basesrc gstbasesrc.c:2351:
basesrc gstbasesrc.c:2414:
queue_dataflow gstqueue.c:1149:
queue_dataflow gstqueue.c:1161:
ringbuffer gstaudioringbuffer.c:1281:
ringbuffer gstaudioringbuffer.c:1490:
ringbuffer gstaudioringbuffer.c:1521:
ringbuffer gstaudioringbuffer.c:1547:
ringbuffer gstaudioringbuffer.c:1708:
ringbuffer gstaudioringbuffer.c:1733:
ringbuffer gstaudioringbuffer.c:1761:
ringbuffer gstaudioringbuffer.c:1851:
ringbuffer gstaudioringbuffer.c:1966:
===========================================

The last lines are supposedly (but faster filtered) equivalent to:

===========================================
alsa gstalsasink.c:1021:gst_alsasink_write:<alsasink0>ESC\[00m written 384 frames out of 384
audiobasesink gstaudiobasesink.c:1664:gst_audio_base_sink_render:<alsasink0>ESC\[00m time
audiobasesink gstaudiobasesink.c:1701:gst_audio_base_sink_render:<alsasink0>ESC\[00m sync-offset
audiobasesink gstaudiobasesink.c:1751:gst_audio_base_sink_render:<alsasink0>ESC\[00m no sync needed. Using render_start=
audiobasesink gstaudiobasesink.c:1885:gst_audio_base_sink_render:<alsasink0>ESC\[00m rendering at
audiobasesink gstaudiobasesink.c:1896:gst_audio_base_sink_render:<alsasink0>ESC\[00m wrote 384 of 384
audiobasesink gstaudiobasesink.c:1928:gst_audio_base_sink_render:<alsasink0>ESC\[00m next sample expected at
audiobasesrc gstaudiobasesrc.c:721:gst_audio_base_src_get_offset:<alsasrc0>ESC\[00m at segment
audiobasesrc gstaudiobasesrc.c:744:gst_audio_base_src_get_offset:<alsasrc0>ESC\[00m reading from
audiobasesrc gstaudiobasesrc.c:799:gst_audio_base_src_create:<alsasrc0>ESC\[00m reading from sample
audiobasesrc gstaudiobasesrc.c:821:gst_audio_base_src_create:<alsasrc0>ESC\[00m read
basesink gstbasesink.c:1803:gst_base_sink_get_sync_times:<alsasink0>ESC\[00m got times start:
basesink gstbasesink.c:3168:gst_base_sink_chain_unlocked:<alsasink0>ESC\[00m got times start:
basesink gstbasesink.c:3209:gst_base_sink_chain_unlocked:<alsasink0>ESC\[00m rendering object
basesink gstbasesink.c:3248:gst_base_sink_chain_unlocked:<alsasink0>ESC\[00m object unref after render
basesrc gstbasesrc.c:2213:gst_base_src_do_sync:<alsasrc0>ESC\[00m no sync needed
basesrc gstbasesrc.c:2351:gst_base_src_get_range:<alsasrc0>ESC\[00m calling create offset
basesrc gstbasesrc.c:2414:gst_base_src_get_range:<alsasrc0>ESC\[00m buffer ok
queue_dataflow gstqueue.c:1149:gst_queue_loop:<queue0>ESC\[00m queue is empty
queue_dataflow gstqueue.c:1161:gst_queue_loop:<queue0>ESC\[00m queue is not empty
ringbuffer gstaudioringbuffer.c:1281:wait_segment:<audiosrcringbuffer0>ESC\[00m waiting..
ringbuffer gstaudioringbuffer.c:1490:default_commit:ESC\[00m pointer at
ringbuffer gstaudioringbuffer.c:1521:default_commit:<audiosinkringbuffer0>ESC\[00m write
ringbuffer gstaudioringbuffer.c:1547:default_commit:ESC\[00m copy 1536 bytes
ringbuffer gstaudioringbuffer.c:1708:gst_audio_ring_buffer_read:ESC\[00m pointer at
ringbuffer gstaudioringbuffer.c:1733:gst_audio_ring_buffer_read:<audiosrcringbuffer0>ESC\[00m read
ringbuffer gstaudioringbuffer.c:1761:gst_audio_ring_buffer_read:<audiosrcringbuffer0>ESC\[00m Retrieved timestamp
ringbuffer gstaudioringbuffer.c:1851:gst_audio_ring_buffer_advance:<audiosrcringbuffer0>ESC\[00m signal waiter
ringbuffer gstaudioringbuffer.c:1966:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer0>ESC\[00m Storing timestamp 99:99:99.999999999 @
===========================================

snd_pcm_recover() just calls snd_pcm_prepare() on an -EPIPE so I cannot see anything wrong with the way the alsasink plugin is handling the underrun.

I don't know if this is useful, but this is a gdb backtrace of the current failed pipeline:

0x00007f8b3f51d3cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) info threads
  Id   Target Id         Frame 
  5    Thread 0x7f8b3a9e7700 (LWP 26655) "queue0:src" 0x00007f8b3f803ca4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  4    Thread 0x7f8b3a1e6700 (LWP 26656) "alsasrc0:src" 0x00007f8b3f803ca4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  3    Thread 0x7f8b399e5700 (LWP 26661) "audiosrc-ringbu" 0x00007f8b3f521747 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
  2    Thread 0x7f8b391e4700 (LWP 26662) "audiosink-ringb" 0x00007f8b3f51d3cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
* 1    Thread 0x7f8b4045d740 (LWP 26625) "gst-launch-1.0" 0x00007f8b3f51d3cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread apply all backtrace

+ Trace 232411

Bad news, the computer that was running so many tests (provide-clock etc.) was halted. I relaunched the tests but I can't have results today.

However, for the current test, the silent pipeline with GST_DEBUG=5 is always running, I have more information on it. I have done some straces.

The pipeline is :
gst-launch-1.0 -v alsasrc device="$alsa_iface" ! queue ! alsasink device="$alsa_iface" sync=false

the alsa interface was used without plug nor dsnoop/dmix alsa module, the pipeline do not uses audioconvert nor audioresample Gstreamer module. The only unnecessary module is "queue".

** These are the threads to strace:

(gdb) info threads
  Id   Target Id         Frame 
  5    Thread 0x7f8b3a9e7700 (LWP 26655) "queue0:src" 0x00007f8b3f803ca4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  4    Thread 0x7f8b3a1e6700 (LWP 26656) "alsasrc0:src" 0x00007f8b3f803ca4 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
  3    Thread 0x7f8b399e5700 (LWP 26661) "audiosrc-ringbu" 0x00007f8b3f521747 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
  2    Thread 0x7f8b391e4700 (LWP 26662) "audiosink-ringb" 0x00007f8b3f51d3cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
* 1    Thread 0x7f8b4045d740 (LWP 26625) "gst-launch-1.0" 0x00007f8b3f51d3cd in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) quit

** "gst-launch-1.0" process

strace -p 26625

poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
poll([{fd=9, events=POLLIN}, {fd=7, events=POLLIN}], 2, 250) = 0 (Timeout)
(again and again, nothing relevant)

This kind of lines (log output) are filtered on other straces:
write(2, "24:00:07.956070566 \33[334m26625\33["..., 180) = 180

** "audiosink-ringb" process

strace -p 26662 2>&1 | grep -v 'write(2, "'

ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
ioctl(10, 0x40184150, 0x7f8b391e3d20)   = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
(again and again, very interesting!)

** "audiosrc-ringbu" process

strace -p 26661 2>&1 | grep -v 'write(2, "'

ioctl(11, 0x80184151, 0x7f8b399e4d10)   = 0
futex(0x1667d24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1667d20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(11, 0x80184151, 0x7f8b399e4d10)   = 0
futex(0x1667d24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1667d20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(11, 0x80184151, 0x7f8b399e4d10)   = 0
futex(0x1667d24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1667d20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(11, 0x80184151, 0x7f8b399e4d10)   = 0
futex(0x1667d24, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1667d20, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(11, 0x80184151, 0x7f8b399e4d10)   = 0
(again and again, nothing relevant)

** "alsasrc0:src" process

strace -p 26656 2>&1 | grep -v 'write(2, "'

futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844853, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844855, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844857, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844859, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844861, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1667d24, FUTEX_WAIT_PRIVATE, 13844863, NULL) = 0
futex(0x1667ae0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1634910, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
(again and again, very interesting!)

** "queue0:src" process

strace -p 26655 2>&1 | grep -v 'write(2, "'

futex(0x1634914, FUTEX_WAIT_PRIVATE, 13856123, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAIT_PRIVATE, 13856125, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAIT_PRIVATE, 13856127, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAIT_PRIVATE, 13856129, NULL) = 0
futex(0x7f8b3f7f39e0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f8b3f7f39e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634950, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x1634914, FUTEX_WAIT_PRIVATE, 13856131, NULL) = 0
(agian and again, very interesting!)



Why "FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)" ?

Check this out:

http://www.gossamer-threads.com/lists/mythtv/users/474457

Robert Krakora
> Check this out:
> http://www.gossamer-threads.com/lists/mythtv/users/474457

This is interesting, there is "prealloc proc file" for both playback and capture devices :

For example:
* /proc/asound/card0/pcm0p/sub0/prealloc (playback)
* /proc/asound/card0/pcm0c/sub0/prealloc (capture)

=======================================
#######################################
=======================================
==== computer A

user@a $ lsb_release -i -c -r
Distributor ID:	Ubuntu
Release:	13.04
Codename:	raring

user@a $ uname -s -r -v -m -o
Linux 3.8.0-29-generic #42-Ubuntu SMP Tue Aug 13 19:40:39 UTC 2013 x86_64 GNU/Linux

user@a $ alsacap -C 0 | grep 'Card\|Device'
Card 0, ID `Intel', name `HDA Intel'
  Device 0, ID `AD198x Analog', name `AD198x Analog', 1 subdevices (0 available)
  Device 1, ID `AD198x Digital', name `AD198x Digital', 1 subdevices (1 available)

user@a $ cat /proc/asound/card0/pcm0p/sub0/prealloc
64
user@a $ cat /proc/asound/card0/pcm1p/sub0/prealloc
64

user@a $ alsacap -R -C 0 | grep 'Card\|Device'
Card 0, ID `Intel', name `HDA Intel'
  Device 0, ID `AD198x Analog', name `AD198x Analog', 2 subdevices (2 available)

user@a $ cat /proc/asound/card0/pcm0c/sub0/prealloc
64

=======================================
==== computer B

user@b $ lsb_release -i -c -r
Distributor ID:	Debian
Release:	7.0
Codename:	wheezy

user@b $ uname -s -r -v -m -o
Linux 3.2.0-4-rt-686-pae #1 SMP PREEMPT RT Debian 3.2.35-2 i686 GNU/Linux

user@b $ alsacap -C 0 | grep 'Card\|Device'
Card 0, ID `XFi', name `Creative X-Fi'
  Device 0, ID `ctxfi', name `Front/WaveIn', 256 subdevices (255 available)
  Device 1, ID `ctxfi', name `Surround', 256 subdevices (256 available)
  Device 2, ID `ctxfi', name `Center/LFE', 256 subdevices (256 available)
  Device 3, ID `ctxfi', name `Side', 256 subdevices (256 available)
  Device 4, ID `ctxfi', name `IEC958 Non-audio', 1 subdevices (1 available)

user@b $ cat /proc/asound/card0/pcm0p/sub0/prealloc
128
user@b $ cat /proc/asound/card0/pcm1p/sub0/prealloc
128
user@b $ cat /proc/asound/card0/pcm2p/sub0/prealloc
128
user@b $ cat /proc/asound/card0/pcm3p/sub0/prealloc
128
user@b $ cat /proc/asound/card0/pcm4p/sub0/prealloc
128

user@b $ alsacap -R -C 0 | grep 'Card\|Device'
Card 0, ID `XFi', name `Creative X-Fi'
  Device 0, ID `ctxfi', name `Front/WaveIn', 1 subdevices (0 available)

user@b $ cat /proc/asound/card0/pcm0c/sub0/prealloc
128

user@b $ alsacap -C 1 | grep 'Card\|Device'
Card 1, ID `Intel', name `HDA Intel'
  Device 0, ID `AD198x Analog', name `AD198x Analog', 1 subdevices (0 available)
  Device 1, ID `AD198x Digital', name `AD198x Digital', 1 subdevices (1 available)

user@b $ cat /proc/asound/card1/pcm0p/sub0/prealloc
64
user@b $ cat /proc/asound/card1/pcm1p/sub0/prealloc
64

user@b $ alsacap -R -C 1 | grep 'Card\|Device'
Card 1, ID `Intel', name `HDA Intel'
  Device 0, ID `AD198x Analog', name `AD198x Analog', 3 subdevices (2 available)
  Device 1, ID `AD198x Digital', name `AD198x Digital', 1 subdevices (1 available)

user@b $ cat /proc/asound/card1/pcm0c/sub0/prealloc
64
user@b $ cat /proc/asound/card1/pcm1c/sub0/prealloc
64

user@b $ alsacap -C 2 | grep 'Card\|Device'
Card 2, ID `Juli', name `ESI Juli@'
  Device 0, ID `ICE1724', name `ICE1724', 1 subdevices (0 available)
  Device 1, ID `ICE1724 IEC958', name `ICE1724 IEC958', 1 subdevices (1 available)

user@b $ cat /proc/asound/card2/pcm0p/sub0/prealloc
256
user@b $ cat /proc/asound/card2/pcm1p/sub0/prealloc
256

user@b $ alsacap -R -C 2 | grep 'Card\|Device'
Card 2, ID `Juli', name `ESI Juli@'
  Device 0, ID `ICE1724', name `ICE1724', 1 subdevices (0 available)
  Device 1, ID `ICE1724 IEC958', name `ICE1724 IEC958', 1 subdevices (1 available)

user@b $ cat /proc/asound/card2/pcm0c/sub0/prealloc
256
user@b $ cat /proc/asound/card2/pcm1c/sub0/prealloc
256

user@b $ alsacap -C 3 | grep 'Card\|Device'
Card 3, ID `Live', name `SB PCI512 [CT4790]'
  Device 0, ID `emu10k1', name `ADC Capture/Standard PCM Playback', 32 subdevices (31 available)
  Device 2, ID `emu10k1 efx', name `Multichannel Capture/PT Playback', 8 subdevices (8 available)
  Device 3, ID `emu10k1', name `Multichannel Playback', 1 subdevices (1 available)

user@b $ cat /proc/asound/card3/pcm0p/sub0/prealloc
64
user@b $ cat /proc/asound/card3/pcm2p/sub0/prealloc
64
user@b $ cat /proc/asound/card3/pcm3p/sub0/prealloc
64

user@b $ alsacap -R -C 3 | grep 'Card\|Device'
Card 3, ID `Live', name `SB PCI512 [CT4790]'
  Device 0, ID `emu10k1', name `ADC Capture/Standard PCM Playback', 1 subdevices (0 available)
  Device 1, ID `emu10k1 mic', name `Mic Capture', 1 subdevices (1 available)
  Device 2, ID `emu10k1 efx', name `Multichannel Capture/PT Playback', 1 subdevices (1 available)

user@b $ cat /proc/asound/card3/pcm0c/sub0/prealloc
64
user@b $ cat /proc/asound/card3/pcm1c/sub0/prealloc
64
user@b $ cat /proc/asound/card3/pcm2c/sub0/prealloc
64

user@b $ alsacap -C 4 | grep 'Card\|Device'
Card 4, ID `Live1', name `SB Live! Value [CT4832]'
  Device 0, ID `emu10k1', name `ADC Capture/Standard PCM Playback', 32 subdevices (32 available)
  Device 2, ID `emu10k1 efx', name `Multichannel Capture/PT Playback', 8 subdevices (8 available)
  Device 3, ID `emu10k1', name `Multichannel Playback', 1 subdevices (1 available)

user@b $ cat /proc/asound/card4/pcm0p/sub0/prealloc
64
user@b $ cat /proc/asound/card4/pcm2p/sub0/prealloc
64
user@b $ cat /proc/asound/card4/pcm3p/sub0/prealloc
64

user@b $ alsacap -R -C 4 | grep 'Card\|Device'
Card 4, ID `Live1', name `SB Live! Value [CT4832]'
  Device 0, ID `emu10k1', name `ADC Capture/Standard PCM Playback', 1 subdevices (1 available)
  Device 1, ID `emu10k1 mic', name `Mic Capture', 1 subdevices (1 available)
  Device 2, ID `emu10k1 efx', name `Multichannel Capture/PT Playback', 1 subdevices (1 available)

user@b $ cat /proc/asound/card4/pcm0c/sub0/prealloc
64
user@b $ cat /proc/asound/card4/pcm1c/sub0/prealloc
64
user@b $ cat /proc/asound/card4/pcm2c/sub0/prealloc
64

user@b $ alsacap -C 5 | grep 'Card\|Device'
Card 5, ID `CODEC', name `USB Audio CODEC'
  Device 0, ID `USB Audio', name `USB Audio', 1 subdevices (0 available)

# there is no /proc/asound/card5/pcm0p/sub0/prealloc

user@b $ alsacap -R -C 5 | grep 'Card\|Device'
Card 5, ID `CODEC', name `USB Audio CODEC'
  Device 0, ID `USB Audio', name `USB Audio', 1 subdevices (0 available)

# there is no /proc/asound/card5/pcm0c/sub0/prealloc

=======================================
==== computer G

user@g $ lsb_release -i -c -r
Distributor ID:	Ubuntu
Release:	13.04
Codename:	raring

user@g $ uname -s -r -v -m -o
Linux 3.8.0-29-generic #42-Ubuntu SMP Tue Aug 13 19:40:39 UTC 2013 x86_64 GNU/Linux

user@g $ alsacap -C 0 | grep 'Card\|Device'
Card 0, ID `SB', name `HDA ATI SB'
  Device 0, ID `ALC892 Analog', name `ALC892 Analog', 1 subdevices (0 available)
  Device 1, ID `ALC892 Digital', name `ALC892 Digital', 1 subdevices (1 available)

user@g $ cat /proc/asound/card0/pcm0p/sub0/prealloc
64
user@g $ cat /proc/asound/card0/pcm1p/sub0/prealloc
64

user@g $ alsacap -R -C 0 | grep 'Card\|Device'
Card 0, ID `SB', name `HDA ATI SB'
  Device 0, ID `ALC892 Analog', name `ALC892 Analog', 1 subdevices (0 available)
  Device 2, ID `ALC892 Analog', name `ALC892 Analog', 1 subdevices (1 available)

user@g $ cat /proc/asound/card0/pcm0c/sub0/prealloc
64
user@g $ cat /proc/asound/card0/pcm2c/sub0/prealloc
64

user@g $ alsacap -C 2 | grep 'Card\|Device'
Card 2, ID `H2n', name `H2n'
  Device 0, ID `USB Audio', name `USB Audio', 1 subdevices (1 available)

# there is no /proc/asound/card2/pcm0p/sub0/prealloc

user@g $ alsacap -R -C 2 | grep 'Card\|Device'
Card 2, ID `H2n', name `H2n'
  Device 0, ID `USB Audio', name `USB Audio', 1 subdevices (1 available)

# there is no /proc/asound/card2/pcm0c/sub0/prealloc

=======================================
==== computer V

user@v $ lsb_release -i -c -r
Distributor ID:	Debian
Release:	7.0
Codename:	wheezy

user@v $ uname -s -r -v -m -o
Linux 3.2.0-0.bpo.4-rt-686-pae #1 SMP PREEMPT RT Debian 3.2.41-2+deb7u2~bpo60+1 i686 GNU/Linux

user@v $ cat /proc/asound/cards 
 0 [CA0106         ]: CA0106 - CA0106
                      Audigy SE [SB0570] at 0x1040 irq 16
 1 [I82801DBICH4   ]: ICH4 - Intel 82801DB-ICH4
                      Intel 82801DB-ICH4 with AD1981A at irq 17

user@v $ alsacap -C 0 | grep 'Card\|Device'
Card 0, ID `CA0106', name `CA0106'
  Device 0, ID `ca0106', name `CA0106', 1 subdevices (0 available)
  Device 1, ID `ca0106', name `CA0106', 1 subdevices (1 available)
  Device 2, ID `ca0106', name `CA0106', 1 subdevices (1 available)
  Device 3, ID `ca0106', name `CA0106', 1 subdevices (1 available)

user@v $ cat /proc/asound/card0/pcm0p/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm1p/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm2p/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm3p/sub0/prealloc
64

user@v $ alsacap -R -C 0 | grep 'Card\|Device'
Card 0, ID `CA0106', name `CA0106'
  Device 0, ID `ca0106', name `CA0106', 1 subdevices (0 available)
  Device 1, ID `ca0106', name `CA0106', 1 subdevices (1 available)
  Device 2, ID `ca0106', name `CA0106', 1 subdevices (1 available)
  Device 3, ID `ca0106', name `CA0106', 1 subdevices (1 available)

user@v $ cat /proc/asound/card0/pcm0c/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm1c/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm2c/sub0/prealloc
64
user@v $ cat /proc/asound/card0/pcm3c/sub0/prealloc
64

user@v $ alsacap -C 1 | grep 'Card\|Device'
Card 1, ID `I82801DBICH4', name `Intel 82801DB-ICH4'
  Device 0, ID `Intel ICH', name `Intel 82801DB-ICH4', 1 subdevices (1 available)
  Device 4, ID `Intel ICH - IEC958', name `Intel 82801DB-ICH4 - IEC958', 1 subdevices (1 available)

user@v $ cat /proc/asound/card1/pcm0p/sub0/prealloc
64
user@v $ cat /proc/asound/card1/pcm4p/sub0/prealloc
64

$ alsacap -R -C 1 | grep 'Card\|Device'
Card 1, ID `I82801DBICH4', name `Intel 82801DB-ICH4'
  Device 0, ID `Intel ICH', name `Intel 82801DB-ICH4', 1 subdevices (1 available)
  Device 1, ID `Intel ICH - MIC ADC', name `Intel 82801DB-ICH4 - MIC ADC', 1 subdevices (1 available)
  Device 2, ID `Intel ICH - MIC2 ADC', name `Intel 82801DB-ICH4 - MIC2 ADC', 1 subdevices (1 available)
  Device 3, ID `Intel ICH - ADC2', name `Intel 82801DB-ICH4 - ADC2', 1 subdevices (1 available)

user@v $ cat /proc/asound/card1/pcm0c/sub0/prealloc
64
user@v $ cat /proc/asound/card1/pcm1c/sub0/prealloc
0
user@v $ cat /proc/asound/card1/pcm2c/sub0/prealloc
0
user@v $ cat /proc/asound/card1/pcm3c/sub0/prealloc
0

=======================================
#######################################
=======================================

I don't show more than one Subdevice (sub0) because they are thousand (for example, the XFi card has 4 devices and 3 of them devices has 255 subdevice each)

I get different values according to the cards: 64 for a Creative Audigy or a Creative SB Live!, 128 for a Creative XFi and 256 fo a ESI Juli@.

USB devices don't have prealloc proc file (no playback nor capture) !!!

Attempting to change the value of a playing soundcard:

root@g # cat /proc/asound/card0/pcm0c/sub0/prealloc
64
root@g # echo 128 > /proc/asound/card0/pcm0c/sub0/prealloc
root@g # cat /proc/asound/card0/pcm0c/sub0/prealloc
64

I can't change it.

Attempting to change the value of a non-playing soundcard:

root@v # cat /proc/asound/card1/pcm0p/sub0/prealloc
64
root@v # echo 128 > /proc/asound/card1/pcm0p/sub0/prealloc
root@v # cat /proc/asound/card1/pcm0p/sub0/prealloc
128

Two conclusions:

~~ 1. I can change it. Good. I'll be able to test with my future pipelines.

~~ 2. I don't know if tweaking this can solve my problem with PCI or PCIe Soundcards, but because this file does not exists for USB soundcards, it can't solve the problem with USB soundcards.

For your information, I've launched yesterday two independent pipelines on the PCIe ESI Juli@ XTE soundcard :

one pipeline for alsasrc:
"alsasrc device=hw:Juli ! capsfilter caps="audio/x-raw, format=S32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink client-name=pipeline_src sync=false connect=none"

one pipeline for alsasink:
"jackaudiosrc client-name=pipeline_sink connect=none ! capsfilter caps=\"audio/x-raw, format=F32LE, rate=48000, channels=2\" ! audioconvert ! audioresample ! capsfilter caps=\"audio/x-raw, format=S32LE, rate=48000, channels=2\" ! alsasink device=hw:Juli sync=false"

They are independent. They are connected with jack. I can change one without changing the other.

The "alsasrc ! something" had output these warning BUT HAS NOT faild:
AVERTISSEMENT : de l'élément /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0 : Impossible d'enregistrer assez rapidement les données audio
Information de débogage supplémentaire :
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0:
Dropped 10240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
14:50:41.515700033  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<alsasrc0> create DISCONT of 10240 samples at sample 2565442560
14:50:41.515759371  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Impossible d'enregistrer assez rapidement les données audio
14:50:41.515785649  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Dropped 10240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

This pipeline is NOT silent.
It DOES NOT need:
pipeline_src.set_state(Gst.State.NEED)
pipeline_src.set_state(Gst.State.PLAYING)
to works, it works already (but perhaps can failed with more time).

The "something ! alsasink" pipeline had outputs these warnings AND HAS failed:
16:12:20.371744040  3687 0xb0102690 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<jackaudiosrc0> create DISCONT of 23552 samples at sample 2800318464
16:12:20.371898922  3687 0xb0102690 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning: Impossible d'enregistrer assez rapidement les données audio
16:12:20.371929869  3687 0xb0102690 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning: Dropped 23552 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

This pipeline IS SILENT.
It NEEDs:
pipeline_sink.set_state(Gst.State.NULL)
pipeline_sink.set_state(Gst.State.PLAYING)
to works again. Sound come back after that.

This pipeline use the ESI Juli@ XTE as record interface, the prealloc is 256:

user@b $ cat /proc/asound/card2/pcm0p/sub0/prealloc
256
user@b $ cat /proc/asound/card2/pcm0c/sub0/prealloc
256

This is software used:

user@b $ uname -s -r -v -m -o
Linux 3.2.0-4-rt-686-pae #1 SMP PREEMPT RT Debian 3.2.35-2 i686 GNU/Linux

user@b $ /usr/sbin/alsactl -v
alsactl version 1.0.25

user@b $ gst-inspect-1.0 alsasink | grep Version
  Version:		1.0.9
user@b $ gst-inspect-1.0 jackaudiosrc | grep Version
  Version:		1.0.9


Two conclusions:

~~ 1. I don't know if the "prealloc proc file" value is related, but if it's related, 256 is too short.

~~ 2. Warnings like "This is most likely because downstream can't keep up and is consuming samples too slowly." are unrelated.
Some pipeline failed without this kind of warning, some pipeline don't failed with this kind of warning.

NB: I have no "INFO" nor "DEBUG" output on this pipelines (uses GST_DEBUG=3).

(In reply to comment #48)
> For your information, I've launched yesterday two independent pipelines on the
> PCIe ESI Juli@ XTE soundcard :
> 
> one pipeline for alsasrc:
> "alsasrc device=hw:Juli ! capsfilter caps="audio/x-raw, format=S32LE,
> rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter
> caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink
> client-name=pipeline_src sync=false connect=none"
> 
> one pipeline for alsasink:
> "jackaudiosrc client-name=pipeline_sink connect=none ! capsfilter
> caps=\"audio/x-raw, format=F32LE, rate=48000, channels=2\" ! audioconvert !
> audioresample ! capsfilter caps=\"audio/x-raw, format=S32LE, rate=48000,
> channels=2\" ! alsasink device=hw:Juli sync=false"
> 
> They are independent. They are connected with jack. I can change one without
> changing the other.
> 
> The "alsasrc ! something" had output these warning BUT HAS NOT faild:
> AVERTISSEMENT : de l'élément /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0 :
> Impossible d'enregistrer assez rapidement les données audio
> Information de débogage supplémentaire :
> gstaudiobasesrc.c(848): gst_audio_base_src_create ():
> /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0:
> Dropped 10240 samples. This is most likely because downstream can't keep up and
> is consuming samples too slowly.
> 14:50:41.515700033  3711  0x97f84f0 WARN            audiobasesrc
> gstaudiobasesrc.c:843:gst_audio_base_src_create:<alsasrc0> create DISCONT of
> 10240 samples at sample 2565442560
> 14:50:41.515759371  3711  0x97f84f0 WARN            audiobasesrc
> gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Impossible
> d'enregistrer assez rapidement les données audio
> 14:50:41.515785649  3711  0x97f84f0 WARN            audiobasesrc
> gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Dropped
> 10240 samples. This is most likely because downstream can't keep up and is
> consuming samples too slowly.
> 
> This pipeline is NOT silent.
> It DOES NOT need:
> pipeline_src.set_state(Gst.State.NEED)
> pipeline_src.set_state(Gst.State.PLAYING)
> to works, it works already (but perhaps can failed with more time).
> 
> The "something ! alsasink" pipeline had outputs these warnings AND HAS failed:
> 16:12:20.371744040  3687 0xb0102690 WARN            audiobasesrc
> gstaudiobasesrc.c:843:gst_audio_base_src_create:<jackaudiosrc0> create DISCONT
> of 23552 samples at sample 2800318464
> 16:12:20.371898922  3687 0xb0102690 WARN            audiobasesrc
> gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning:
> Impossible d'enregistrer assez rapidement les données audio
> 16:12:20.371929869  3687 0xb0102690 WARN            audiobasesrc
> gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning:
> Dropped 23552 samples. This is most likely because downstream can't keep up and
> is consuming samples too slowly.
> 
> This pipeline IS SILENT.
> It NEEDs:
> pipeline_sink.set_state(Gst.State.NULL)
> pipeline_sink.set_state(Gst.State.PLAYING)
> to works again. Sound come back after that.
> 
> This pipeline use the ESI Juli@ XTE as record interface, the prealloc is 256:
> 
> user@b $ cat /proc/asound/card2/pcm0p/sub0/prealloc
> 256
> user@b $ cat /proc/asound/card2/pcm0c/sub0/prealloc
> 256
> 
> This is software used:
> 
> user@b $ uname -s -r -v -m -o
> Linux 3.2.0-4-rt-686-pae #1 SMP PREEMPT RT Debian 3.2.35-2 i686 GNU/Linux
> 
> user@b $ /usr/sbin/alsactl -v
> alsactl version 1.0.25
> 
> user@b $ gst-inspect-1.0 alsasink | grep Version
>   Version:        1.0.9
> user@b $ gst-inspect-1.0 jackaudiosrc | grep Version
>   Version:        1.0.9
> 
> 
> Two conclusions:
> 
> ~~ 1. I don't know if the "prealloc proc file" value is related, but if it's
> related, 256 is too short.
> 
> ~~ 2. Warnings like "This is most likely because downstream can't keep up and
> is consuming samples too slowly." are unrelated.
> Some pipeline failed without this kind of warning, some pipeline don't failed
> with this kind of warning.
> 
> NB: I have no "INFO" nor "DEBUG" output on this pipelines (uses GST_DEBUG=3).

Interesting.  So, it seems that pipelines with one or the other (but not both) alsasrc or alsasink work without failing?

Oops, you stated the one with alsasink has failed...maybe the problem is with alsasink then???

Yes, a pipeline with only one alsa module can failed. This is something I've noticed several times.

IRL, I rarely pipeline alsasrc to alsasink, and it failed every day (I use a cron to relaunch the pipeline before failure :D ). The "alsasrc ! alsasink" pipeline is just "one of pipeline known to fail", and the easiest to reproduce.

For your information, I have an "audiotestsrc ! alsasink" pipeline running since three days without problem.

The problem seems appear when connectig one live source to a live sink, if one of this live source or sink is an alsa module (audiotesrsrc is an exception since it has been conceived to handle every usecase).

does'not fail:
jackaudiosrc ! something ! jackaudiosink
jackaudiosrc ! something ! opusenc ! rtpopuspay ! udpsink
udpsrc ! rtpopusdepay ! rtpjitterbuffer ! opusdec ! something ! jackaudiosink

fails:
alsasrc ! something ! alsasink
jackaudiosrc ! something ! alsasink
udpsrc ! rtpopusdepay ! rtpjitterbuffer ! opusdec ! something ! alsasink

Today I don't know if the alsasrc module can't fail at all.
I knew it, but I do not know now. I think it can fail too.

This time, the "jackaudiosrc ! something ! alsasink" pipeline had failed in less than 14 hours, sometimes it fails in more than 20h.

Perhaps alsasrc can fails with more time.

It seems to me that if I wait long enough, I have to restart both "alsasrc ! something" and "something ! alsasink" pipelines.

This pipeline:
gst-launch-1.0 jackaudiosrc client-name=live1_sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:Live1 slave-method=2 provide-clock=true

fails in less than 10min (with stuttering before failure)

What is the largest you have made "buffer_size" for record and playback in your .asoundrc file?

> What is the largest you have made "buffer_size" for record and playback in
> your .asoundrc file?

There is currently no .asoundrc file



Also, I tried to change "prealloc" for my SB Lives, I can't, for both two SB Live I have.

I can't set more than 64 (the default), there is also a "prealloc_max" file that contains 64, I can't change both "prealloc" and "prealloc_max" for the two Sound Blaster Live I have.

Here new information accordingly to my tests.

These pipelines:

* alsasrc device=hw:XFi ! queue ! alsasink device=hw:XFi sync=false
* alsasrc device=hw:Intel ! alsasink device=hw:Intel sync=false
* audiotestsrc ! alsasink device=hw:Intel

has not failed in more than three days (PCI Creative SoundBlaster X-Fi, Integrated PCI Intel 82801H), Integrated PCI Intel 82801H)

These three pipelines:
* alsasrc device=alsa_iface ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink sync=false connect=none

using alsa_iface = Live, alsa_iface=Live1, alsa_iface=Juli (PCI Creative SoundBlaster Live! CT4790, PCI Creative SoundBlaster Live! CT4832, PCIe ESI Juli@ XTe)

with Warnings like that :
AVERTISSEMENT : de l'élément /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0 : Impossible d'enregistrer assez rapidement les données audio
Information de débogage supplémentaire :
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstAlsaSrc:alsasrc0:
Dropped 10240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
14:50:41.515700033  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<alsasrc0> create DISCONT of 10240 samples at sample 2565442560
14:50:41.515759371  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Impossible d'enregistrer assez rapidement les données audio
14:50:41.515785649  3711  0x97f84f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<alsasrc0> warning: Dropped 10240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

has not failed in more than three days

---> These six pipelines using alsasrc has not failed in more than three days

These three pipelines:
* "jackaudiosrc connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, chanels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, forma=S32LE, rate=48000, channels=2" ! alsasink device=alsa_iface sync=false

using alsa_iface = Live, alsa_iface=Live1, alsa_iface=Juli (PCI Creative SoundBlaster Live! CT4790, PCI Creative SoundBlaster Live! CT4832, PCIe ESI Juli@ XTe)

with warnings like that:
AVERTISSEMENT : de l'élément /GstPipeline:pipeline0/GstJackAudioSrc:jackaudiosrc0 : Ressource introuvable.
Information de débogage supplémentaire :
gstjackaudiosrc.c(479): gst_jack_ring_buffer_acquire (): /GstPipeline:pipeline0/GstJackAudioSrc:jackaudiosrc0:
No physical output ports found, leaving ports unconnected
0:00:02.961586728  6042  0x88204f0 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<jackaudiosrc0> create DISCONT of 134144 samples at sample 135168
0:00:02.961768645  6042  0x88204f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning: Impossible d'enregistrer assez rapidement les données audio
0:00:02.961796268  6042  0x88204f0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<jackaudiosrc0> warning: Dropped 134144 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

has failed.


_______________________________________________________

This day (2013-08-26), with Gstreamer 1.0.9.

Pipelines known to be faulty pipelines:
* alsasrc ! audioresample ! audioconvert ! alsasink sync=false
* jackaudiosrc ! audioresample ! audioconvert ! alsasink sync=false

Pipelines not kwnown to be faulty pipelines:
* alsasrc ! alsasink
* alsasrc ! queue ! alsasink
* audiotestsrc ! alsasink
* jackaudiosrc ! audioresample ! audioconvert ! opusenc ! rtpopuspay ! udpsink
* udpsrc ! rtpjitterbuffer ! rtpopusdepay ! opusdec ! audioresample ! audioconvert ! jackaudiosink

For your information, some soundcards have not same format as recording format and playing format, needing audioconvert when pipelining alsasrc with alsasink, and some soundcards has not functionnal 48000Hz playing sampling (functionnal 44100Hz sampling) but functionnal 48000Hz recording sampling, needing audioresample when pipelining alsasrc with alsasink. Pipelining audioconvert and audioresampling between alsasrc and alsasink is needed in some case.

Analysis:
---> alsasrc with audioconvert and audioresample does not fail
---> alsasrc without audioconvert and without audioresample does not fail
---> alsasink without audioconvert and without audioresample does not fail
---> alsasink with audioconvert and audioresample fails
---> audioconvert with audioresample without alsasink does not fail
---> audioresample with audioconvert without alsasink does not fail

The bug seems to appear in combination of alsasink with audioconvert, or in combination of alasink with audioresample, or in combination of alsasink with audioresample with audioconvert.
Both audioconvert and audioresample module are not faulty when used without alsasink module. The alsasink module is not faulty when used without on of the audioconvert or audioresample module or without both of them.

I will try theses four pipelines (never tested) :

* alsasrc device=hw:Live ! audioconvert ! alsasink device=hw:Live sync=false
* alsasrc device=hw:Live1 ! audioresample ! alsasink device=hw:Live1 sync=false
* audiotestsrc ! audioconvert ! alsasink device=hw:Intel
* audiotestsrc ! audioresample ! alsasink device=hw:XFi

(by the way, I confirm, a failed pipeline need state.NULL before state.PLAYING to become functionnal again, state.PAUSED before state.PLAYING does nothing)

So, from you testing, the pipeline below should eventually fail?

gst-launch audiotestsrc ! audioconvert ! audioresample ! alsasink

I have noticed that your pipelines that audioresample ! audioconvert.  In samples I have seen, audioconvert seems to always precede audioresample like this...

audioconvert ! audioresample

...maybe Sebastian can chime in...

I am wrong, you have tried about every combination known to man...;-)

Maybe audioconvert ! audioresample add too much latency?

What about trying...

gst-launch alsasrc latency-time=20000 buffer-time=800000 ! audioresample ! audioconvert ! alsasink sync=false

"Similarly, alsasrc' buffer-time and latency-time control the total capacity of the buffer and the size of each individual buffer (respectively), again up to best effort approximation by the device(driver)."

From: http://gentrans.sourceforge.net/docs/head/manual/html/howto.html

> So, from you testing, the pipeline below should eventually fail?
> gst-launch audiotestsrc ! audioconvert ! audioresample ! alsasink

I will try it. :)

But bad news, I forget that the pipeline failed in Comment #35 was:

gst-launch-1.0 -v alsasrc device="$alsa_iface" ! queue ! alsasink device="$alsa_iface" sync=false

WITHOUT audioconvert and without audioresample.

I have at least ONE CASE of failed pipeline that does not use audioresample nor audioconvert. This pipeline has failed in less than 15 hours.

This one was running on Gstreamer 1.0.6 with a non-realtime linux kernel (the 'g' computer)

The tests running in Comment #22, Comment #48 and Comment #55 are running on Gstreamer 1.0.9 with a realtime linux kernel (the 'b' computer).

It seems that realtime kernels give more time before the bug appears, but it's just a feeling (not proved).

> What about trying...
> gst-launch alsasrc latency-time=20000 buffer-time=800000 !
> audioresample ! audioconvert ! alsasink sync=false

I have already test this kind of options in the past, but I do not remember the results.
I will retry it. But it is not good For my usage to lengthen the recording and playback time. If it help to contain the bug, I do not consider this to be a good solution. The Gstreamer alsa latency-time and buffer-time default values (10ms of latency-time and 200ms of buffer-time) are already oversized.
In comparison, a typical jackd latency is 6ms, and works on USB soundcard (USB soundcards are known to have a lot of latency). Default values (10ms latency and 200ms buffer are listenable and are already unpleasant).

IRL I use 6000 microsecond of latency time (6ms), and it works for hours before the crash. In this talk all the tests was done with default values (10000 microsecond latency-time, 200000 microsecond buffer-time), and it works for hour before the crash. Why can it work more than 12 hours with 6ms, but not 13h (for example, or why 20h but not 21h, why one day but not two days)?

IRL, this command
arecord -D hw:CODEC -f dat | aplay -D hw:CODEC -f dat
is faster than this command
gst-launch-1.0 alsasrc ! capsfilter caps="audio/x-raw, format=S16LE,
rate=48000, channels=2" ! alsasink
By the word "faster" I mean the latency between recording and playing is smaller.

Thoses two commands are equivalent in terms of functionality, but the in the first, record and aplay both hide a software resampler and format converter (there is therefore two hidden resamplers and two hidden converters) that Gstreamer don't use without explicit call, and the first command use the unsuitable unix pipe. 10ms is already more than necessary, a legitimate prudent choice.

Perhaps latency-time can extend or reduce the time before a pipeline fails, like usage of rt-kernel or non-rt-kernel, but I do not think this solves the problem, perhaps it makes the problem more difficult to solve because it takes longer to identify the bug.

But above all, having a failed pipeline (in less than 20 hours) that did not use audioconvert not audioresample makes it all confused. All these options seem to change the time it starts to fail, but not really fix the problem.

Well this...

arecord -D hw:CODEC -f dat | aplay -D hw:CODEC -f dat

...might invoke a purely hardware path down in the ALSA code thereby negating the latency.

There is no hardware path in the unix pipe. :)

So, arecord and aplay appear to me to be overbloated softwares that do more than what they should do. They emulate so many things! When these programs are used to query the characteristics of a sound card as described in the documentation, they respond what alsa emulates over physical abilities instead of physical habilities. These two programs allow anything but reliable use of a sound card. Using arecord or aplay without cabalistic option on a "default" sound card is like running two resample and two converter

This kind of command:
arecord -D default-f dat | aplay -D default-f dat
hides 4 converters and 4 resamplers. More than necessary.

In this kind of command:
gst-launch-1.0 alsasrc ! capsfilter caps="audio/x-raw, format=S16LE,
rate=48000, channels=2" ! alsasink
there is 0 converter and 0 resampler, and it is slower than the arecord/aplay alternative due to the latency default value, and only slower because of these default values. I think it is not necessary to slower. These values ​​are already very good default values.

But do not feed more the troll, aplay and arecord are slow. It's just a fact.

My problem is not why GStreamer can be faster than a slow combination of arecord with aplayn when reducing the prudent Gstreamer options provided for all use cases in the world. Yes, Gstreamer can be faster than arecord/aplay with better values than defaults.

But my problem is why my pipelines become silent without saying anything, even with default values that are cautious and prudent. :)

And with so many and so various tests, I don't know why. :(

Yes...arecord and aplay are stand alone applications...however, IMHO ALSA is very well done.  If it was not, JACK and Pulse would not have built on top of it and it's drivers would not be integrated in to the kernel.  :-)

The GStreamer plugins alsasrc and alsasink make use of the ALSA API, but seem fairly light weight.

It's time to deliberate ! :)

* gst-launch-1.0 -v alsasrc device=hw:Live1 ! audioresample ! alsasink device=hw:Live1 sync=false
status: FAILED (silent, no log)

* gst-launch-1.0 -v alsasrc device=hw:Live ! audioconvert ! alsasink device=hw:Live sync=false
status: FAILED (silent, no log)

* gst-launch-1.0 -v audiotestsrc ! audioconvert ! alsasink device=hw:Intel
status: running

* gst-launch-1.0 -v audiotestsrc ! audioresample ! alsasink device=hw:XFi
status: running

Pipelines were aged of 19h (I don't know exactly when they have failed).

Tested with Gstreamer 1.0.9 with Linux-3.2.0-4-rt

I'm trying

* gst-launch-1.0 -v alsasrc device=hw:Live1 ! audioresample ! alsasink
device=hw:Live1 sync=true

* gst-launch-1.0 -v alsasrc device=hw:Live ! audioconvert ! alsasink
device=hw:Live sync=true

* gst-launch-1.0 alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 ! audioresample ! audioconvert ! alsasink device=hw:XFi sync=false

* gst-launch-1.0 -v audiotestsrc ! audioconvert ! audioresample ! alsasink device=hw:Intel

(with an rt kernel)

Both

* gst-launch-1.0 -v alsasrc device=hw:Live1 ! audioresample ! alsasink
device=hw:Live1 sync=true

* gst-launch-1.0 -v alsasrc device=hw:Live ! audioconvert ! alsasink
device=hw:Live sync=true

are stuttering.

Kind of expected those two pipelines to run in to problems.

Be interesting to see what the other pipelines running with an RT kernel do that you started...

> Kind of expected those two pipelines to run in to problems.

This is why i use sync=false, it was decided by trial and error. :)

But with sync=true the problem comes fast with plenty of logs, with sync false the problem comes slowly but without logs. ^^

The two stuttering pipelines with sync=true are displaying something like that:

3:48:11.818344119  7155  0x9215890 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20051588 > 20000000
3:48:13.211389013  7155  0x9215890 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 21128255 > 20000000
3:48:14.604455196  7155  0x9215890 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 21803332 > 20000000
3:48:15.904639475  7155  0x9215890 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20092214 > 20000000

Endlessly.

Skew will never be < 20000000.

20000000 (20 000 000) is default value for which variable ?

Well, that you get these errors with sync=true already gives a good direction where to look. There are clock problems between your source and sink hardware, e.g. the rates are not what they're supposed to be (e.g. claims 44100Hz but is 44105Hz) and source produces not in the rate the sink wants to consume, or the clock rates are not stable, or ...

Sebastian Dröge (slomo):
> Well, that you get these errors with sync=true already
> gives a good direction where to look.

Yes, perhaps it is a better idea to test with this option, because we have more information in this case and failure is more reproductible. In any case, resolve issues that arise with it can not hurt.

> There are clock problems between your source and
> sink hardware

In Comment #52 we saw that we also had a problem with "slave-method=2 provide-clock=true"

> e.g. the rates are not what they're supposed to be
> (e.g. claims 44100Hz but is 44105Hz) and source
> produces not in the rate the sink wants to consume,
> or the clock rates are not stable, or ...

Statistically we have more problem with alsasink than with alsasrc. We can change the kind of source (jackaudiosrc, alsasrc) maintaining the bug without changing the kind of sink (alsasink). It's more like "the sink is requesting something that the source can not provide".

(NB: Due to a power failure throughout the city all my pipelines have been discontinued.)

Yesterday I've launched this pipeline:

gst-launch-1.0 -v alsasrc device=hw:XFi ! alsasink device=hw:Juli sync=true

from one soundcard to another, the pipeline is running since more than 16 hours

the pipeline is silent and logs are full of:

16:33:01.613912724  4360  0x9cc6c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1068582227 > 20000000
16:33:01.623932573  4360  0x9cc6c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1068584724 > 20000000
16:33:01.633891653  4360  0x9cc6c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1068586434 > 20000000
16:33:01.643870490  4360  0x9cc6c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1068587382 > 20000000
16:33:01.653871297  4360  0x9cc6c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1068587592 > 20000000

Notice the excessive value greater than 1000 000 000 while alsasink complains from values ​​greater than only 20 000 000!

Does someone known which the 20000000 number means ?

I have relaunched the same pipeline, with other things around.

I have one pipeline running an audiotestsrc:

gst-launch-1.0 -v audiotestsrc ! audioconvert ! audioresample ! alsasink device=hw:DSX

(yes, the audioresample and audioconvert are superfluous, but this is a test suggested in Comment #56, this pipeline is running properly for the moment)

the sound is brought to this pipeline (with a physical audio cable):

gst-launch-1.0 -v alsasrc device=hw:XFi ! alsasink device=hw:Juli sync=true

then the sound is listened on a physical speaker and recorded with another soundcard in that way:

arecord -f dat -D hw:Live 20130830.gstreamer-problem.wav

The sound looks like that before become silent (in less than 15min):
[5.6Mo] http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem.wav
[92Ko] http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem.png

there is one (and only one):

0:08:33.250492914  4683  0x842ec90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20000054 > 20000000
0:08:33.250549670  4683  0x842ec90 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.010340136, resyncing

before silent, when sound is distorded

after that, some minutes later, we can read that:

0:14:33.267288156  4683  0x842ec90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20099300 > 20000000
0:14:34.047324993  4683  0x842ec90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20024971 > 20000000

become more and more recurrent (but without the "resyncing" line), until the pipeline becomes silent. When the pipeline becomes silent, the output log is very verbose.

I'm running the same pipeline (logging output and recording sound from begin to end to compare sound with timestamps).

Then, I got this again:

0:08:34.112215429  4737  0x87b0c90 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.010340136, resyncing

With a very similar timestamp, the previous test has given that:

0:08:33.250549670  4683  0x842ec90 WARN           audiobasesink
gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0>
Unexpected discontinuity in audio timestamps of +0:00:00.010340136, resyncing

It seems this line appears only once.

What about running:

gst-launch-1.0 alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 !
audioresample ! audioconvert ! alsasink device=hw:XFi sync=true

This is the full output log:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full.stdout.txt

This is the full audio record (mono, I discarded the right channel because left and right channels are identically) :

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-mono-logsync.flac

These are some screenshots:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-0.png

The first distortion appears at approximatively 4:20 (approximatively the half of 8:34).

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-4.20-0.png

We can see that the sound is distorded BEFORE the first log line.

The first "correct clock skew" log message appears at 8:34 (sound is already distorded):

0:08:34.112173174  4737  0x87b0c90 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correc
t clock skew 20001262 > 20000000

This first "correct clock skew" log message is followed by the only one "resyncing" log message.

0:08:34.112215429  4737  0x87b0c90 WARN           audiobasesink
gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0>
Unexpected discontinuity in audio timestamps of +0:00:00.010340136, resyncing

At this time, the sound IS REPAIRED (before returning noisy later):

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-1.png
http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-2.png
http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-3.png
http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-4.png

We can see at approximatively 13:07 the first silence appearing:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-5.png

And we can see at approximatively 16:55 the pipeline becoming definitively silent:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-6.png

This picture summarizes it all:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-0-comment.png





> What about running:
>
> gst-launch-1.0 alsasrc device=hw:XFi
> latency-time=20000 buffer-time=800000 !
> audioresample ! audioconvert !
> alsasink device=hw:XFi sync=true

I will try it.

This is not related to Gstreamer but related to alsa (perhaps there is a link).

While trying the Robert Krarora pipeline, I am recording sound produced by the pipeline in that way:

arecord -f dat -D hw:Live /mnt/20130830.gstreamer-drift-problem-full-xfi-latency.wav
Recording WAVE '/mnt/20130830.gstreamer-drift-problem-full-xfi-latency.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
overrun!!! (at least 54.448 ms long)
overrun!!! (at least 54.049 ms long)
overrun!!! (at least 35.927 ms long)

I am listening what I am recording in that way:

tail -f /mnt/20130830.gstreamer-drift-problem-full-xfi-latency.wav | aplay -t raw -f dat -D hw:CODEC
Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
underrun!!! (at least 34.445 ms long)
underrun!!! (at least 28.149 ms long)
underrun!!! (at least 14.824 ms long)

The aplay and the arecord are running on two different soundcards, one is used for recording (and only recording), the oser is used for playing (and only playing), but on the same computer. The two "aplay" and "arecord" experience an overrun (recording) or an underrun (playing) at the same time, exactly at the same time !

I don't know if it's related, but alsa is underruning or overruning regularly.
Maybe it has an impact on the functioning of GStreamer.

Note: it's a realtime kernel.

Note: the pipeline
gst-launch-1.0 alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 ! audioresample ! audioconvert ! alsasink device=hw:XFi sync=true
is running since more than 30min without distortion or silence.

I found this:

<ARG>
<NAME>GstEncodeBin::audio-jitter-tolerance</NAME>
<TYPE>guint64</TYPE>
<RANGE></RANGE>
<FLAGS>rw</FLAGS>
<NICK>Audio jitter tolerance</NICK>
<BLURB>Amount of timestamp jitter/imperfection to allow on audio streams before inserting/dropping samples (ns).</BLURB>
<DEFAULT>20000000</DEFAULT>
</ARG>

in:
gst-plugins-base/docs/plugins/gst-plugins-base-plugins.args

There is the only place where I found the "20000000" in gst-plugins-base, gst-plugins-good and gstreamer source code.



----------
With aplay and arecord, I got a 2second overrun and underrun:

overrun!!! (at least 96.298 ms long)
overrun!!! (at least 51.389 ms long)
overrun!!! (at least 61.523 ms long)
overrun!!! (at least 52.045 ms long)
overrun!!! (at least 26.525 ms long)
overrun!!! (at least 2030.409 ms long)

underrun!!! (at least 72.038 ms long)
underrun!!! (at least 27.677 ms long)
underrun!!! (at least 38.223 ms long)
underrun!!! (at least 30.258 ms long)
underrun!!! (at least 4.933 ms long)
underrun!!! (at least 2012.711 ms long)

Time between underrun or overrun is unpredictable (100s, 20s, 400s…)

The pipeline is running since 50min without failing , and without "clock skew" or "resyncing" log line.

Hmmm...

1 hour is too short to say "the pipeline will never fail", but without your "latency" and "buffer-time" options, the pipeline would already be faulty.

Let us see what happens.  :-)

I actually found the pipeline suggestion in some GStreamer documentation.

> I actually found the pipeline suggestion
> in some GStreamer documentation.

Do you have a link ?
Or explanation about this values ?

> Let us see what happens.  :-)

I'll let the pipeline run all the next weekend, hoping we do not have electric problem (thanks to Murphy's Law :p).

(In reply to comment #84)
> > I actually found the pipeline suggestion
> > in some GStreamer documentation.
> 
> Do you have a link ?
> Or explanation about this values ?
> 
> > Let us see what happens.  :-)
> 
> I'll let the pipeline run all the next weekend, hoping we do not have electric
> problem (thanks to Murphy's Law :p).

Here is the documentation...scroll down and read it all...

http://fossies.org/dox/gst-plugins-base-1.1.4/gstaudiobasesink_8c.html

The pipeline has failed. The pipeline is silent.

There is no log before silence, since silence there is:
2:20:09.528759662 24177  0x86fcd20 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 24711652 > 20000000
endlessly

This is log:
http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-xfi-latency.stdout.txt

OK, now run the same pipeline with the new "drift-tolerance" property added:

gst-launch-1.0 alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 drift-tolerance = 25000000!
audioresample ! audioconvert ! alsasink device=hw:XFi sync=true

From http://gstreamer-devel.966125.n4.nabble.com/problem-with-synchronization-between-multiple-audio-clients-td4656124.html:

"- Do not forget about the audio sink. It is what actually schedules audio buffers to be played based on the timestmap. This is one big difference between sinks in GStreamer and sinks in many other libraries and programs: most sinks are not just simple output devices that emit data as soon as you push it into them, they pay attention to buffer timestamps. With this in mind, I recommend to use GST_BASE_AUDIO_SINK_SLAVE_SKEW as slave-method for the sink (which is the default value anyway), and give the drift-tolerance property a close look. Its default value is 40 ms. Once the rtpbin corrects buffer timestamps based on the RTP timestamps and the RTCP SR packets, and the sink then detects a resulting drift between the internal audio clock and these timestamps that is greater than the drift-tolerance value, it will skew the playout pointer, compensating for the drift. The smaller the drift-tolerance value, the more likely the skewing. If for example you try to use 0.5 ms for the drift-tolerance, skewing will happen often, and playback will sound very bad. Pick a sensible middle ground between synchronized playback and stable playback."

> From
http://gstreamer-devel.966125.n4.nabble.com/problem-with-synchronization-between-multiple-audio-clients-td4656124.html:

Interesting…

> OK, now run the same pipeline with the new "drift-tolerance" property added:

gst-launch-1.0 -v alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 drift-tolerance=25000000 ! audioconvert ! audioresample ! alsasink device=hw:XFi sync=true
0:00:00.068520914 24723  0x852f1a0 ERROR           GST_PIPELINE ./grammar.y:432:gst_parse_element_set: no property "drift-tolerance" in element "alsasrc0"
WARNING: erroneous pipeline: no property "drift-tolerance" in element "alsasrc0"

There is no drift-tolerance option in alsasrc module, but there is one in alsasink module:

gst-launch-1.0 -v alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 ! audioconvert ! audioresample ! alsasink device=hw:XFi drift-tolerance=25000000 sync=true

Tthis last pipeline is running with sound.

Hi all, I coming back to you with the report of two tests. :)

This pipeline is running since three days, it's playing sound, there is no error or warning log :

gst-launch-1.0 -v audiotestsrc ! audioconvert ! audioresample ! alsasink
device=hw:DSX


This pipeline pipeline is running since three days and has failed, it's playing silence then at first it played sound. There is no log since the beginning:

gst-launch-1.0 -v alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 drift-tolerance=25000000 ! audioconvert ! audioresample ! alsasink device=hw:XFi sync=true


This is beginning log:
0:00:00.068520914 24723  0x852f1a0 ERROR           GST_PIPELINE ./grammar.y:432:gst_parse_element_set: no property "drift-tolerance" in element "alsasrc0"
WARNING: erroneous pipeline: no property "drift-tolerance" in element "alsasrc0"
jcodec@jcodec:~$ date; date +%s; gst-launch-1.0 -v alsasrc device=hw:XFi latency-time=20000 buffer-time=800000 ! audioconvert ! audioresample ! alsasink device=hw:XFi drift-tolerance=25000000 sync=true 2>&1 | tee /mnt/20130830.gstreamer-drift-problem-full-xfi-latency-drift-tolerance.stdout.txtFri Aug 30 18:26:47 CEST 2013
1377880007
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
0:00:00.033637924 24734  0x9556d20 FIXME                default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<alsasrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
Setting pipeline to PLAYING ...
0:00:00.034133960 24734  0x9608f40 WARN                     bin gstbin.c:2474:gst_bin_do_latency_func:<pipeline0> failed to query latency
New clock: GstAudioSrcClock
0:00:00.034936962 24734  0x9556d20 WARN                    alsa pcm_hw.c:1401:_snd_pcm_hw_open: alsalib error: Invalid value for card
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0: actual-buffer-time = 743038
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0: actual-latency-time = 23219
/GstPipeline:pipeline0/GstAlsaSrc:alsasrc0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioConvert:audioconvert0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioResample:audioresample0.GstPad:src: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAlsaSink:alsasink0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioResample:audioresample0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
/GstPipeline:pipeline0/GstAudioConvert:audioconvert0.GstPad:sink: caps = audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003

There is no more log since the beginning.

hmm, sorry, the second pipeline (the one that failed) is:

gst-launch-1.0 -v alsasrc device=hw:XFi
latency-time=20000 buffer-time=800000 ! audioconvert ! audioresample ! alsasink
device=hw:XFi drift-tolerance=25000000 sync=true

There are no xruns, no WARNINGS?

http://lists.freedesktop.org/archives/gstreamer-devel/2011-June/031775.html

http://gstreamer-devel.966125.n4.nabble.com/Sound-stopping-pipeline-sync-issue-td3568168.html

I wonder what the results of these tests would be using pulsesrc and pulsesink instead of alsasrc and alsasink.

How about running the tests with jackaudiosrc and jackaudiosink instead of alsasrc and alsasink?

> There are no xruns, no WARNINGS?

No warnings at all. The pipeline said nothing (with GST_DEBUG=3).

> http://gstreamer-devel.966125.n4.nabble.com/Sound-stopping-pipeline-sync-issue-td3568168.html

I do not know how you find all these things but this one is very interesting! :)

> I wonder what the results of these tests would be
> using pulsesrc and pulsesink instead of alsasrc and
> alsasink.

It will be complicated because pulseseaudio is not installed on any machine that I use for testing.

> How about running the tests with jackaudiosrc and
> jackaudiosink instead of alsasrc and alsasink?

It is easier to test because it is an IRL use case. :)

This pipeline fails (IRL use case, used every day) :

* jackaudiosrc ! something ! alsasink sync=false

I don't known if this pipeline fails (I was not patient enough, but latest information makes me think not):

* alsasrc ! something ! jackaudiosink sync=false

I know these pipelines don't fail (IRL use case, used every day):

* jackaudiosrc ! something ! udpsink
* udpsrc ! something ! jackaudiosink

Do you want me to try:

* jackaudiosrc ! jackaudiosink
* jackaudiosrc ! something ! alsasink drift-tolerance=25000000 sync=true

or above information is sufficient?

This pipeline would be very interesting...

jackaudiosrc ! jackaudiosink

For information, an strace on the elements of the failed pipeline shows nothing than things like:

ioctl(10, 0x400c4150, 0xb5bff1f4)       = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])
ioctl(10, 0x400c4150, 0xb5bff1f4)       = 0
poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10, revents=POLLOUT}])

endlessly.

I can't see xruns since xrun information appears with GST_DEBUG=4 and with this log level it's difficult to run test during lmany hours.
But we see in Comment #45 that when I have xruns, strace shows strange things like "-1 EAGAIN (Resource temporarily unavailable)" and there is nothing like that here.

There is a way to set loglevel for xruns but not for other things ?

(In reply to comment #99)
> For information, an strace on the elements of the failed pipeline shows nothing
> than things like:
> 
> ioctl(10, 0x400c4150, 0xb5bff1f4)       = 0
> poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10,
> revents=POLLOUT}])
> ioctl(10, 0x400c4150, 0xb5bff1f4)       = 0
> poll([{fd=10, events=POLLOUT|POLLERR|POLLNVAL}], 1, 40) = 1 ([{fd=10,
> revents=POLLOUT}])
> 
> endlessly.
> 
> I can't see xruns since xrun information appears with GST_DEBUG=4 and with this
> log level it's difficult to run test during lmany hours.
> But we see in Comment #45 that when I have xruns, strace shows strange things
> like "-1 EAGAIN (Resource temporarily unavailable)" and there is nothing like
> that here.
> 
> There is a way to set loglevel for xruns but not for other things ?
Unfortunately, there is no way to set a loglevel for xruns without modifying the alsasink source which is a distinct possibility if you feel so inclined.  ;-)

BTW, it would be interesting to see if a simple pipeline of jackaudiosrc ! jackaudiosink fails.

I'm running these pipelines:

these two pipelines are created to have audio source for testing purpose (audiotest-to-alsa and audiotest-to-jack):

* gst-launch-1.0 -v audiotestsrc freq=600 ! alsasink device=hw:DSX

* gst-launch-1.0 -v audiotestsrc freq=440 ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=src name=test connect=none

these three pipelines are alsa-to-jack and jack-to-alsa modules:

* gst-launch-1.0 -v jackaudiosrc client-name=julia name=sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S32LE, rate=48000, channels=2" ! alsasink device=hw:Juli sync=false

* gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink name=src client-name=xfi sync=false connect=none

* gst-launch-1.0 -v jackaudiosrc client-name=xfi name=sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1"Message from syslogd@jcodec at Sep  3 19:44:59 ..."audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:XFi sync=false

these three pipelines are jack-to-jack modules with several different options:

* gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue0 name=out connect=none sync=false

* gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue1 name=out connect=none sync=true

* gst-launch-1.0 -v jackaudiosrc client-name=queue2 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue2 name=out connect=none sync=true drift-tolerance=25000000

The capsfilters are here to force the "channels=1", there is no conversion and no resample at all in the jack-to-jack pipelines

I can test each of these pipelines independently.
The patchbay looks like that:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130903.gstreamer-jackd-patchbay-test.png

:)

Wow, how many different machines are running these pipelines?

hum, sorry, an unwanted syslog message has slipped into my message

The jack-to-alsasink-xfi is :

gst-launch-1.0 -v jackaudiosrc client-name=xfi name=sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:XFi sync=false

For information, the jack server is launched without any initial soundcard and is therefore not dependent on any hardware constraint. Only Gstreamer has access to hardware.

> Wow, how many different machines are running these pipelines?

One computer right now. This one has 6 PCI or PCIe soundcard, and this test uses only two of them: I can do worse than that! :p

Because the tests can last a day, I try to parallelize them, it saves me many days. Sometimes I add another computer when I want to test rdp modules or different kernel / gstreamer version but this is not needed here. With jack it's easy to add pipelines that does not use any soundcard. :)

Have you ever taken a look at what your CPU usage is on this PC with all the pipelines active with 'top -H'?

Also, I sure that you can replicate the problem on a PC with only a single soundcard, correct?  Otherwise, you would probably have not gone to the trouble of puttly six PCI/PCIe soundcards in one PC.  <:-)

You can also do a 'top -p <pid> -H' for a particular process (gst-launch) and get a breakdown of CPU/memory usage per thread...that would be useful.

> Also, I sure that you can replicate the problem on a PC with only a single
soundcard, correct?

Correct! I found the bug with a single sound card, and then I reproduced with one sound card, and then I reproduced with several different sound cards but only one at a time, then I reproduced with several sound cards simultaneously. :)

> Have you ever taken a look at what your CPU usage is on this PC with all the
pipelines active with 'top -H'?

htop said me about mem:
Mem:1008M used:98M buffers:0M cache:102M

about cpu:
Avg:  6.6% sy:  1.3% ni:  0.0% hi:  0.0% si:  0.0% wa:  0.0% st:  0.0%

> You can also do a 'top -p <pid> -H' for a particular process


PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5831  117M 86068 84628 S  1.0  8.3  1:07.53 gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps=audio/x-raw, format=S16LE

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5726   99M 85080 83904 S  2.0  8.2  2:45.00 gst-launch-1.0 -v audiotestsrc freq=440 ! capsfilter caps=audio/x-raw, format=F32LE

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5720 27124  3972  2868 S  1.0  0.4  2:33.68 gst-launch-1.0 -v audiotestsrc freq=600 ! alsasink device=hw:DSX

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5789  117M 86064 84576 S  1.0  8.3  0:57.71 gst-launch-1.0 -v jackaudiosrc client-name=julia name=sink connect=none ! capsfilter

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5758  109M 85040 83820 S  0.0  8.2  0:26.89 gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5766  109M 85048 83824 S  0.0  8.2  0:27.33 gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none ! capsfilter

PID   VIRT   RES   SHR S CPU% MEM%   TIME+  Command
5774  109M 85048 83824 S  0.0  8.2  0:26.94 gst-launch-1.0 -v jackaudiosrc client-name=queue2 name=in connect=none ! capsfilter

5839  117M 86020 84572 S  1.0  8.3  1:28.70 gst-launch-1.0 -v jackaudiosrc client-name=xfi name=sink connect=none ! capsfilter


The computer is underutilized. :)

detailed htop with all relevant process and threads:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130903.gstreamer-jackd-patchbay-test-htop.txt

You can also do a 'top -p <pid> -H' for a particular process (gst-launch) and get a breakdown of CPU/memory usage per thread...that would be useful.

Would you be able to do a test where JACK is actually connected to a sound card?

jackaudiosrc ! jackaudiosink

JACK sits on top of ALSA...would be nice to see if the GStreamer JACK plugins yield the same problem.

Info :

These two pipelines have failed (silence no warning) :

* gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw,
format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" !
jackaudiosink name=src client-name=xfi sync=false connect=none

* gst-launch-1.0 -v jackaudiosrc client-name=julia name=sink connect=none !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" !
audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S32LE,
rate=48000, channels=2" ! alsasink device=hw:Juli sync=false

But this pipeline has not failed, although it is known to fail:

* gst-launch-1.0 -v jackaudiosrc client-name=xfi name=sink connect=none !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" !
audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE,
rate=48000, channels=2" ! alsasink device=hw:XFi sync=false

This mean it's too early to draw a conclusion about other pipelines wich still have time to fail.

This interesting because we have one example of "alsasrc ! something" pipeline failure. It seems more difficult to observe.

____________

> Would you be able to do a test where JACK is actually connected to a sound
card?

Yes I can. :)

I have launched another jack daemon controlling an alsa interface (hw:Intel) with its internal alsa driver.

I have launched those pipelines:

* gst-launch-1.0 -v audiotestsrc freq=1000 ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=testsine name=sine connect=none

* gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue0 name=out connect=none sync=false

* gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue1 name=out connect=none sync=true

* gst-launch-1.0 -v jackaudiosrc client-name=queue2 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue2 name=out connect=none sync=true drift-tolerance=25000000

I reuse the previously launched "audiotestsrc ! alsasink device=DSX" pipeline to have an external audio source.

The patchbay looks like:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130904.gstreamer-jackd-bis-audio-patchbay-test.png

This patchbay is running alongside the other.

Mem:1008M used:143M buffers:0M cache:183M
Avg:  8.0% sy:  2.7% ni:  0.0% hi:  0.0% si:  0.0% wa:  0.0% st:  0.0%

And this is the current consumption of resources:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130904.gstreamer-jackd-patchbay-test-htop.txt

There is no need to worry. :)

How are tests running today?  Sorry I was quiet yesterday...had fumes in our building and had to evacuate...everything good today...

Hello, I'm back! :)

****** 1rst jack patchbay (jackd does not manage soundcard itself), running since 5 days

This pipeline has failed 3 times in 5 days: (1 time the 1rst day, 1 time the second day, I was not here for two days, perhaps it fails 1 time per day):

gst-launch-1.0 -v jackaudiosrc client-name=julia name=sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S32LE, rate=48000, channels=2" ! alsasink device=hw:Juli sync=false

This pipeline fails 3 times in 5 days (idem):

gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink name=src client-name=xfi sync=false connect=none

This pipeline has not fails in three days (ooooh, this is the first time I see such a pipeline last as long), but fails before 5 days:

gst-launch-1.0 -v jackaudiosrc client-name=xfi name=sink connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! alsasink device=hw:XFi sync=false

Before the three days, logs are plenty of that:

44:43:35.046368602  5839  0x986ccf0 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<sink> create DISCONT of 9216 samples at sample 7728715776
44:43:35.046429596  5839  0x986ccf0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<sink> warning: Can't record audio fast enough
44:43:35.046453839  5839  0x986ccf0 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<sink> warning: Dropped 9216 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
WARNING: from element /GstPipeline:pipeline0/GstJackAudioSrc:sink: Can't record audio fast enough
Additional debug info:
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstJackAudioSrc:sink:
Dropped 9216 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

But we see in Comment #48 that this warnings are unerelated. Some pipeline fail without this kind of warning, some pipeline don't fail with this kind of warning.

In five days, this pipeline has failed:

gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue0 name=out connect=none sync=false

with logs like that (extract):
101:46:20.206389522  5758  0x9031e30 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<in> create DISCONT of 162816 samples at sample 17586240512
101:46:20.206444705  5758  0x9031e30 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Can't record audio fast enough
101:46:20.206468491  5758  0x9031e30 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Dropped 162816 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

These pipeline has not failed in 5 days:

gst-launch-1.0 -v audiotestsrc freq=440 ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=src name=test connect=none

gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue1 name=out connect=none sync=true

gst-launch-1.0 -v jackaudiosrc client-name=queue2 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue2 name=out connect=none sync=true drift-tolerance=25000000

****** 2nd jack patchbay, running since 4 days

These pipelines has not failed in 4 days:

gst-launch-1.0 -v audiotestsrc freq=1000 ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=testsine name=sine connect=none

gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue0 name=out connect=none sync=false

gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue1 name=out connect=none sync=true

with this complete log:
0:01:24.401569345  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20055490 < -20000000
0:01:25.510915961  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 20244932 > 20000000
0:01:26.513655131  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<out> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
0:04:19.276611138  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20028081 < -20000000
0:06:14.800396151  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20055713 < -20000000
0:06:21.904643431  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 21088586 > 20000000
0:06:29.136902870  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20056509 < -20000000
0:07:20.445217286  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 21088498 > 20000000
0:07:32.029689158  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20055715 < -20000000
0:07:54.814458738  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 21088498 > 20000000
0:17:51.377957979  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20055715 < -20000000
118:25:35.542284376  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 21088498 > 20000000
118:25:41.729188668  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20059482 < -20000000

gst-launch-1.0 -v jackaudiosrc client-name=queue2 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue2 name=out connect=none sync=true drift-tolerance=25000000

****** No jack patchbay:

This pipeline has not failed in 5 days:

gst-launch-1.0 -v audiotestsrc freq=600 ! alsasink device=hw:DSX

I lanched two more pipelines 3 days ago.

This one has failed:

gst-launch-1.0 -v alsasrc device=hw:Live ! capsfilter caps='audio/x-raw, format=S16LE, rate=48000, channels=2' ! audioconvert ! audioresample ! capsfilter caps='audio/x-raw, format=S16LE, rate=48000, channels=2' ! opusenc cbr=true bitrate=128000 dtx=false inband-fec=false packet-loss-percentage=0 ! rtpopuspay ! udpsink host=127.0.0.1 port=5004

I don't knwo if this one have failed (accidentally killed it before listening it):

gst-launch-1.0 -v udpsrc uri=udp://127.0.0.1:5004 ! capsfilter caps='application/x-rtp, media=(string)audio, clock-rate=(int)48000, payload=(int)96, caps=(string)"audio/x-opus"' ! rtpjitterbuffer latency=60 drop-on-latency=true ! rtpopusdepay ! opusdec ! audioconvert ! audioresample ! capsfilter caps='audio/x-raw, format=S16LE, rate=48000, channels=2' ! alsasink device=hw:Live sync=false

It outputs this log:

74:50:18.186647380 10273 0x964b890 WARN   rtpjitterbuffer rtpjitterbuffer.c:458:calculate_skew: delta - skew: 0:00:03.481668225 too big, reset skew

Only one time, which is not related to alsa.

___________________________________

1rst conclusion: for the first time in history we have a failed pipeline that does not use any alsamodule:

gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! jackaudiosink client-name=queue0 name=out connect=none sync=false

And we have the same pipeline running in another jack patchbay without problem.

2nd conclusion: alsasink does not failed in 5 days when only used with audiotestsrc.

3rd conclusion: a pipeline can run more than 2 days without failing.

4th Conclusion: everything else that we had already observed has not changed.

Interesting...but the problem with this pipeline seems different from the problem(s) with the other pipelines.  Also, when I went to the Texas Instruments GStreamer Wiki, they suggested using alsasink with the sync property set to 'false' for audio only pipelines and this does not seem right as Sebastian indicated.  Makes me think that this alsasink problem has been around for a while in some for or another.  Anyway, the problem with the pipeline below looks definitely like a time stamp problem.  I am thinking that the sync property should be set to 'true' and not 'false'.  Would you be able to change it to 'true' and rerun the pipeline?  :-)

In five days, this pipeline has failed:

gst-launch-1.0 -v jackaudiosrc client-name=queue0 name=in connect=none !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" !
jackaudiosink client-name=queue0 name=out connect=none sync=false

with logs like that (extract):
101:46:20.206389522  5758  0x9031e30 WARN            audiobasesrc
gstaudiobasesrc.c:843:gst_audio_base_src_create:<in> create DISCONT of 162816
samples at sample 17586240512
101:46:20.206444705  5758  0x9031e30 WARN            audiobasesrc
gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Can't record
audio fast enough
101:46:20.206468491  5758  0x9031e30 WARN            audiobasesrc
gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Dropped 162816
samples. This is most likely because downstream can't keep up and is consuming
samples too slowly.

Two instance of this pipeline:

gst-launch-1.0 -v jackaudiosrc client-name=queue1 name=in connect=none !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" !
jackaudiosink client-name=queue1 name=out connect=none sync=true

are already running.

The 1rst is running since 5 days in a jack patchbay (with dummy interface) and the 2nd is running since 4 days in a jackd (with alsa interface).

Both are ok. There is some log output, but pipelines are running fine, no noise, no silence.

log from gstreamer connected to jackd with dummy interface:

101:46:14.700129470  5766  0x943fe30 WARN            audiobasesrc gstaudiobasesrc.c:843:gst_audio_base_src_create:<in> create DISCONT of 164864 samples at sample 17585976320
101:46:14.700178271  5766  0x943fe30 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Can't record audio fast enough
101:46:14.700199527  5766  0x943fe30 WARN            audiobasesrc gstaudiobasesrc.c:848:gst_audio_base_src_create:<in> warning: Dropped 164864 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
WARNING: from element /GstPipeline:pipeline0/GstJackAudioSrc:in: Can't record audio fast enough
Additional debug info:
gstaudiobasesrc.c(848): gst_audio_base_src_create (): /GstPipeline:pipeline0/GstJackAudioSrc:in:
Dropped 164864 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

log for gstreamer connected to jackd with alsa interface:
118:25:35.542284376  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<out> correct clock skew 21088498 > 20000000
118:25:41.729188668  8527  0x8062e30 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<out> correct clock skew -20059482 < -20000000

In both two usecases, the sound is fine.

These are good tests.  The JACK sinks are connected to actual audio hardware then?
What does the CPU usage look like now (after a few days)?

JACK sink with sync=false is behaving like I would expect.  No samples are being thrown away if they are late, every sample is being played regardless and the pipeline has backing up at JACK source because it is not being consumed at a satisfactory rate by JACK sink.  Now, with JACK sink with sync=true behavior is also correct in that it is dropping samples that arrive last and continuing on without backing up the pipeline at JACK source.  alsasink is behaving rather odd though with sync=true relative to JACK sink which is behaving correctly with sync=true.

Additionally, JACK sits on top of ALSA as does Pulse.  Is possibly the usage of the ALSA API in alsasink at fault?  Is it employed correctly under JACK and Pulse but not under the GStreamer alsasink plugin?

> What does the CPU usage look like now (after a few days)?

htop said me:

Mem:1008M used:169M buffers:0M cache:186M
Avg:  6.9% sy:  3.8% ni:  0.0% hi:  0.0% si:  0.0% wa:  0.0% st:  0.0%


remember Comment #111:

Mem:1008M used:143M buffers:0M cache:183M
Avg:  8.0% sy:  2.7% ni:  0.0% hi:  0.0% si:  0.0% wa:  0.0% st:  0.0%

There is three new pipelines since Comment #111 ("alsasrc ! rtpsink", "rtpsrc ! alsasink"; and another "audiotestsrc ! jackaudiosink")

All of this seems ok.

> These are good tests.  The JACK sinks are connected to actual audio hardware
then?

The "jack dummy" is not connected itself to any audio interface, I connect this patchbay to sound card with "alsasrc ! jackaudiosink" or "jackaudiosrc ! alsasink".

The "jack alsa" is connected to an audio interface and manage it alone.

In both case, the pipeline "jackaudiosrc ! jackaudiosink sync=true" is fine, the only difference are in warnings, perhaps due to internal jack clock.

> Makes me think that this alsasink problem has been around for a while in some for or another.

Is it possible that the magic trick of "sync=false" has prevented us from seeing the problem, because it hides the bug at first sight?

> Additionally, JACK sits on top of ALSA as does Pulse.  Is possibly the usage of the ALSA API in alsasink at fault?  Is it employed correctly under JACK and Pulse but not under the GStreamer alsasink plugin?

Indeed we find that "alsa → gstreamer" does'nt work but "alsa → jackaudio → gstreamer" works. This would mean that:

1. alsa works
2. jack works
3. gstreamer works for other than alsa

I never use "alsasink sync=true" because distortions comes in minutes (see Comment #75 ).

The fact that ALSA by itself works fine, JACK by itself works fine, GStreamer JACK sink works fine (with JACK sitting on top of ALSA) leads me to believe that the GStreamer alsasink plugin has issues.  Is it possibly an ALSA API usage issue by the alsasink plugin?

This seems logical for alsasink. But what should we think about alsasrc?

Failure comes from "sync=false" or from alsasrc itself ?

In Comment # 114 we have already 4 case of alsasrc failure but the pipelines use "sync=false".

Maybe I'm wrong but it seems to me that we have not tested the "alsasrc ! jackaudiosink sync=true" pipeline.

(I'm impressed that there is a combination that I have not tested :p )

(In reply to comment #122)
> This seems logical for alsasink. But what should we think about alsasrc?
> 
> Failure comes from "sync=false" or from alsasrc itself ?
> 
> In Comment # 114 we have already 4 case of alsasrc failure but the pipelines
> use "sync=false".
> 
> Maybe I'm wrong but it seems to me that we have not tested the "alsasrc !
> jackaudiosink sync=true" pipeline.

That would certainly be an interesting test case...

I'm testing that:

gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink name=src client-name=xfi connect=none sync=true




For your information, that:

gst-launch-1.0 -v jackaudiosrc name=sink client-name=julia connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S32LE, rate=48000, channels=2" ! alsasink device=hw:Juli sync=true

can produce noise or silence in less than 1 minute (sometime it needs more time).

Interesting...

This pipeline:

gst-launch-1.0 -v jackaudiosrc name=sink client-name=julia connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=1" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S32LE, rate=48000, channels=2" ! alsasink device=hw:Juli sync=true

Prints logs like that:

16:11:48.480893109  6273  0x833ecf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2550623562 > 20000000
16:11:48.502229196  6273  0x833ecf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2550624909 > 20000000
16:11:48.523561613  6273  0x833ecf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2550626213 > 20000000
16:11:48.544898602  6273  0x833ecf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2550627477 > 20000000

It occurs dozens of times per second.

The pipeline is silent.

--------------

This pipeline:

gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw,
format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" !
jackaudiosink name=src client-name=xfi connect=none sync=true

Prints logs like that:

16:10:31.350295130  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<src> correct clock skew 20190099 > 20000000
16:10:31.370219568  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<src> correct clock skew -20159812 < -20000000
16:10:31.500289722  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<src> correct clock skew 20008864 > 20000000
16:10:31.510157289  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<src> correct clock skew -20022663 < -20000000

It seems not predictable, it happens from time to time.

The pipeline is running nicely, recording sound without distortion.
This pipeline is running since more than 22 hours.

I think our hunch about alsasink is looking more and more plausible.  This is a really good test as both are printing similar WARN messages, yet one is no longer playing and one is playing nicely.

I think our hunch about alsasink is looking more and more plausible.

Yes !

I have another information. You said in Comment # 115:

> Also, when I went to the Texas Instruments GStreamer Wiki,
> they suggested using alsasink with the sync property set to
> 'false'

In fact, when I encounter the bug more than two year ago (with Gstreamer 0.10), I found the "sync=false" trick in the Texas Instruments GStreamer Wiki and other similar documents that mimicked it.

Maybe the bug was never found because everyone cheats with "sync=false" instead of report it. If you play less than a day, you can never have a problem using "sync=false".

I never use "sync=false" because I understand why, but because without it it would not work. So I thought it was the right thing to do because it is simply the only way to get something that looks like a normal operation.

It happened to me to teach "sync=false" as a solution to others believing that it was normal and the right way to do it.

There is so many example (too much ?) of code like that:

self.devicesink = gst.element_factory_make("alsasink", "alsasink")
self.devicesink.set_property("sync", False)

or like that:

GstElement *testsink = gst_element_factory_make("alsasink", "alsasink");
g_object_set(G_OBJECT(testsink), "sync", FALSE, NULL);

in this code search:
http://code.ohloh.net/search?s=alsasink%20sync%20false&p=2&pp=0&mp=1&ml=1&me=1&md=1&ff=1&filterChecked=true

^^

Yes, I noticed that too.

Remember Comment #42, we have logged this:

1:39:18.548386467 26625 0x7f8b2c003a30 DEBUG                   alsa
gstalsasink.c:1014:gst_alsasink_write:<alsasink0> wait error, -32

##############################################################################

I found that in gst-plugins-base/ext/alsa/gstalsasink.c:

---8<-------------------------------------------------------------------------
static gint
> gst_alsasink_write (GstAudioSink * asink, gpointer data, guint length)
> {
>   GstAlsaSink *alsa;
>   gint err;
>   gint cptr;
>   gint16 *ptr = data;
> 
>   alsa = GST_ALSA_SINK (asink);
> 
>   if (alsa->iec958 && alsa->need_swap) {
>     guint i;
> 
>     GST_DEBUG_OBJECT (asink, "swapping bytes");
>     for (i = 0; i < length / 2; i++) {
>       ptr[i] = GUINT16_SWAP_LE_BE (ptr[i]);
>     }
>   }
> 
>   GST_LOG_OBJECT (asink, "received audio samples buffer of %u bytes", length);
> 
>   cptr = length / alsa->bpf;
> 
>   GST_ALSA_SINK_LOCK (asink);
>   while (cptr > 0) {
>     /* start by doing a blocking wait for free space. Set the timeout
>      * to 4 times the period time */
>     err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
>     if (err < 0) {
>       GST_DEBUG_OBJECT (asink, "wait error, %d", err);
>     } else {
>       GST_DELAY_SINK_LOCK (asink);
>       err = snd_pcm_writei (alsa->handle, ptr, cptr);
>       GST_DELAY_SINK_UNLOCK (asink);
>     }
> 
>     GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
>     if (err < 0) {
>       GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
>       if (err == -EAGAIN) {
>         continue;
>       } else if (err == -ENODEV) {
>         goto device_disappeared;
>       } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
>         goto write_error;
>       }
>       continue;
>     }
> 
>     ptr += snd_pcm_frames_to_bytes (alsa->handle, err);
>     cptr -= err;
>   }
>   GST_ALSA_SINK_UNLOCK (asink);
> 
>   return length - (cptr * alsa->bpf);
> 
> write_error:
>   {
>     GST_ALSA_SINK_UNLOCK (asink);
>     return length;              /* skip one period */
>   }
> device_disappeared:
>   {
>     GST_ELEMENT_ERROR (asink, RESOURCE, WRITE,
>         (_("Error outputting to audio device. "
>                 "The device has been disconnected.")), (NULL));
>     goto write_error;
>   }
> }
---8<-------------------------------------------------------------------------

Perhaps the bug is somewhere here ?

In comparison we have that in gst-plugins-base/ext/alsa/gstalsasrc.c:

---8<-------------------------------------------------------------------------
> static guint
> gst_alsasrc_read (GstAudioSrc * asrc, gpointer data, guint length,
>     GstClockTime * timestamp)
> {
>   GstAlsaSrc *alsa;
>   gint err;
>   gint cptr;
>   gint16 *ptr;
> 
>   alsa = GST_ALSA_SRC (asrc);
> 
>   cptr = length / alsa->bpf;
>   ptr = data;
> 
>   GST_ALSA_SRC_LOCK (asrc);
>   while (cptr > 0) {
>     if ((err = snd_pcm_readi (alsa->handle, ptr, cptr)) < 0) {
>       if (err == -EAGAIN) {
>         GST_DEBUG_OBJECT (asrc, "Read error: %s", snd_strerror (err));
>         continue;
>       } else if (err == -ENODEV) {
>         goto device_disappeared;
>       } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
>         goto read_error;
>       }
>       continue;
>     }
> 
>     ptr += err * alsa->channels;
>     cptr -= err;
>   }
>   GST_ALSA_SRC_UNLOCK (asrc);
> 
>   /* if driver timestamps are enabled we need to return this here */
>   if (alsa->driver_timestamps && timestamp)
>     *timestamp = gst_alsasrc_get_timestamp (alsa);
> 
>   return length - (cptr * alsa->bpf);
> 
> read_error:
>   {
>     GST_ALSA_SRC_UNLOCK (asrc);
>     return length;              /* skip one period */
>   }
> device_disappeared:
>   {
>     GST_ELEMENT_ERROR (asrc, RESOURCE, READ,
>         (_("Error recording from audio device. "
>                 "The device has been disconnected.")), (NULL));
>     GST_ALSA_SRC_UNLOCK (asrc);
>     return (guint) - 1;
>   }
> }
---8<-------------------------------------------------------------------------

##############################################################################

There is two notable difference between them.

The first notable difference is:

in gstalsasrc.c:

> while (cptr > 0) {
>   /* some code */
>   ptr += err * alsa->channels;
>   cptr -= err;
> }

in gstalsasink.c:

> while (cptr > 0) {
>   /* some code */
>   ptr += snd_pcm_frames_to_bytes (alsa->handle, err);
>   cptr -= err;
> }

I do not know if this is normal and if this is the expected operation.

The second notable difference is:

in gstalsasrc.c, err is always assigned like that:

> err = snd_pcm_readi (alsa->handle, ptr, cptr)

in gstalsasink.c, err can be assigned in two ways:

> err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));

or, if err >= 0:

> err = snd_pcm_writei (alsa->handle, ptr, cptr);

##############################################################################

There is another noticeable thing !

We read in gstalsasink.c:

> err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));

And this the snd_pcm_wait code in alsa-lib/src/pcm/pcm.c:

> int snd_pcm_wait(snd_pcm_t *pcm, int timeout)
> {
> 	if (!snd_pcm_may_wait_for_avail_min(pcm, snd_pcm_mmap_avail(pcm))) {
> 		/* check more precisely */
> 		switch (snd_pcm_state(pcm)) {
> 		case SND_PCM_STATE_XRUN:
> 			return -EPIPE;
> 		case SND_PCM_STATE_SUSPENDED:
> 			return -ESTRPIPE;
> 		case SND_PCM_STATE_DISCONNECTED:
> 			return -ENODEV;
> 		default:
> 			return 1;
> 		}
> 	}
> 	return snd_pcm_wait_nocheck(pcm, timeout);
> }

snd_pcm_wait can return -EPIPE in case of SND_PCM_STATE_XRUN
We can remember that EPIPE is 32.

In gst-plugins-base/ext/alsa/gstalsasink.c we can see that -EPIPE is not handled:

>     if (err < 0) {
>       GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
>       if (err == -EAGAIN) {
>         continue;
>       } else if (err == -ENODEV) {
>         goto device_disappeared;
>       } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
>         goto write_error;
>       }
>       continue;
>     }

There is no "if (err == -EPIPE)" at all.

In case of "alsasrc ! alsasink" pipeline, when the alsasink get -EPIPE, this is the alsasrc module that catch this error and complains:

1:39:18.548478614 26625 0x7f8b2c003630 DEBUG                   alsa
gstalsasrc.c:808:xrun_recovery:<alsasrc0> xrun recovery -32: Erreur inconnue
-32

Does anyone have an idea?

-EPIPE is handled by XRUN recovery function.

Maybe the XRUN recovery function needs to be re-worked?

> -EPIPE is handled by XRUN recovery function.

But why it is alsasrc that handle xrun instead of alsasink ?

> Maybe the XRUN recovery function needs to be re-worked?

Is the difference between pulsesink, jackaudiosink and alsasink is that pulse and jack integrate their own xrun manager outside of gstreamer so that gstreamer undergoes very rarely xruns ?

That is kind of what it is looking like...

Seems like ALSA gets in a constant underrun state from which it never recovers IRT alsasink.

It is impressive to see that everyone recommends this option without justification (other than to say that it works), and that it must be like that.

For example, the olpc wiki give pipeline examples, the only one pipeline example that used sync=false is the alsasink one, without justification (no comment, this is how to do).

http://wiki.laptop.org/go/GStreamer

Another example, a french ubuntu forum:

A guy says:

> J'avais eu un problème similaire et l'avais résolu en mettant la propriété sync de l'élément alsasink à false.

I translate:

> I had a similar problem and had solved by setting the alsasink sync property to false.

http://forum.ubuntu-fr.org/viewtopic.php?id=254332

"sync=false" is used by evreyone, at best as workaround, and at worst as solution and the normal way to do.

And another guy respond:

> merci, ça marche comme ça

I translate:

> thank you, it works like that

This conversation took place in September 2008, we are in September 2013. This is at least five years that the bug exists and alsasink can not be used in normal operation.

However, as stated by Sebastian Dröge in Comment #32:

> You should use sync=true, and if that doesn't work this has to be fixed :)

This would mean that hundreds of people have encountered the bug but nobody reported it since they could be satisfied with a workaround. This is awesome! :o

I found a bug report dating from 2006:
https://bugs.launchpad.net/ubuntu/+source/gst-plugins-base0.10/+bug/42998

> Berti wrote on 2006-05-04:
> When I'm trying to access the "line in" sound from my soundcard with alsasrc :
> gst-launch -v alsasrc ! alsasink
> I can only hear the first second of the sound.

> Sebastian Dröge wrote on 2006-05-08:
> Ok, could you please try
> gst-launch-0.10 alsasrc ! audioconvert ! alsasink sync=false

> Berti wrote on 2006-05-08:
> With the sync=false, it works. The sound is OK until I kill the process.

This bug has been marked as fixed for the first time in version 0.10.12.2 in 2007:

> Kjell Braden wrote on 2007-11-25:
> It looks like this if fixed since at least 0.10.12.2-0ubuntu1,
> which is in gutsy.

Another example:

http://delog.wordpress.com/2011/06/01/stream-raw-vorbis-audio-over-udp-or-tcp-with-gstreamer/

> Note the use of sync property in the alsasink element. If you set it to true, the audio stops playing after a while or does not begin playing.

Again, this is not presented as a bug but as information to know. It is taught as normal operation, and everyone (including me) imitates. :/

I believe one of the GStreamer developers/maintainers indicated in a previous comment to this bug report that the default behavior if 'sync' is not explicitly set to something is 'sync=true'.  We know at least with JACK (which sits on top of ALSA) that it is possible to survive an underrun.

Yes, true is the default sync value for alsasink module:

user@machine $ gst-inspect-1.0 alsasink  | grep ' sync' -A 2
  sync                : Sync on the clock
                        flags: readable, writable
                        Boolean. Default: true

Should we rename the bug in that way:
« alsasink does not work at all with default value "sync=true" »
?

Seems like a more appropriate title.

This pipeline:

gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw,
format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample !
capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" !
jackaudiosink name=src client-name=xfi connect=none sync=true

has printed many of this lines (many per second):

47:09:14.402878930  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<src> correct clock skew -20211458 < -20000000
47:09:14.512842741  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<src> correct clock skew 20142346 > 20000000
47:09:14.532885517  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<src> correct clock skew -20240434 < -20000000

unless it prints this line:

47:09:15.532780831  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<src> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing

then has printed nothing (perhaps it will certainly happen again while waiting a little).

The pipeline is running fine, sound is played and not distorted, even when there is a lot of WARN logs.

This pipeline is running since 47 hours.

The problem does not seem to affect alsasrc, only alsasink.

I am thinking that gst_alsasink_write() should look something like this:

static gint
gst_alsasink_write (GstAudioSink * asink, gpointer data, guint length)
{
  GstAlsaSink *alsa;
  gint err;
  gint cptr;
  gint16 *ptr = data;

  cptr = length / alsa->bpf;

  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    /* start by doing a blocking wait for free space. Set the timeout
     * to 4 times the period time */
    err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "wait error, %d", err);
      if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
    ]
    
    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
      if (err == -EAGAIN) {
    }
  }

  GST_LOG_OBJECT (asink, "received audio samples buffer of %u bytes", length);

  cptr = length / alsa->bpf;

  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    /* start by doing a blocking wait for free space. Set the timeout
     * to 4 times the period time */
    err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
    if (err == -EPIPE) {
      GST_DEBUG_OBJECT (asink, "wait error, %d", err);
      if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
    } 

    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));

  cptr = length / alsa->bpf;

  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    /* start by doing a blocking wait for free space. Set the timeout
     * to 4 times the period time */
    err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
    if (err == -EPIPE) {
      GST_DEBUG_OBJECT (asink, "wait error, %d", err);
      if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
    }

    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
      if (err == -EAGAIN) {
        continue;
      } else if (err == -ENODEV) {
        goto device_disappeared;
      } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
      continue;
    }

    ptr += snd_pcm_frames_to_bytes (alsa->handle, err);
    cptr -= err;
  }
  GST_ALSA_SINK_UNLOCK (asink);

  return length - (cptr * alsa->bpf);

write_error:
  {
    GST_ALSA_SINK_UNLOCK (asink);
    return length;              /* skip one period */
  }
device_disappeared:
  {
    GST_ELEMENT_ERROR (asink, RESOURCE, WRITE,
        (_("Error outputting to audio device. "
                "The device has been disconnected.")), (NULL));
    goto write_error;
  }
}

Oops...cut and paste error on the last comment...I meant to paste this:

static gint
gst_alsasink_write (GstAudioSink * asink, gpointer data, guint length)
{
  GstAlsaSink *alsa;
  gint err;
  gint cptr;
  gint16 *ptr = data;

  alsa = GST_ALSA_SINK (asink);

  if (alsa->iec958 && alsa->need_swap) {
    guint i;

    GST_DEBUG_OBJECT (asink, "swapping bytes");
    for (i = 0; i < length / 2; i++) {
      ptr[i] = GUINT16_SWAP_LE_BE (ptr[i]);
    }
  }

  GST_LOG_OBJECT (asink, "received audio samples buffer of %u bytes", length);

  cptr = length / alsa->bpf;

  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    /* start by doing a blocking wait for free space. Set the timeout
     * to 4 times the period time */
    err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
    if (err == -EPIPE) {
      GST_DEBUG_OBJECT (asink, "wait error, %d", err);
      if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
    }

    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
      if (err == -EAGAIN) {
        continue;
      } else if (err == -ENODEV) {
        goto device_disappeared;
      } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
      continue;
    }

    ptr += snd_pcm_frames_to_bytes (alsa->handle, err);
    cptr -= err;
  }
  GST_ALSA_SINK_UNLOCK (asink);

  return length - (cptr * alsa->bpf);

write_error:
  {
    GST_ALSA_SINK_UNLOCK (asink);
    return length;              /* skip one period */
  }
device_disappeared:
  {
    GST_ELEMENT_ERROR (asink, RESOURCE, WRITE,
        (_("Error outputting to audio device. "
                "The device has been disconnected.")), (NULL));
    goto write_error;
  }
}

Effectively, without this modification, 

the "err" variable in this code:

> if (err < 0) {
>  GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));

is not this err:

> err = snd_pcm_writei (alsa->handle, ptr, cptr);

but this err:

> err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));

which does not make sense. Your modification seems more logical.

And the other modification (xrun recovery; goto write_error) is a good idea, as long as we are certain that the only one thing which may be returned in case of error is -EPIPE (someone to confirm ?)

I'll try this code tomorrow. :)

I have compiled the 1.0.10 gstreamer alsaink module with your modification, it change nothing.

I gradually get noise with log like that:
0:05:34.719307833  7707  0x8339cf0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20002484 > 20000000

until 5min, then we have that:
0:05:34.719353943  7707  0x8339cf0 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.021312500, resyncing

then the sound is ok.

Its like Comment #75 and Comment #78:

We get many "correct clock skew" with noise, then one "resyncing", then the sound is ok, then many "correct clock skew", we never have other resyncing, then the noise become silence with many "correct clock skew", definitively.

For your information, alsasrc have similar behavior: no log printed, then many "correct clock skew", then one "resyncing" wich stops "correct clock skew" printg, then new "correct clock skew", then new "resyncing", then new "correct clock skew", then new "resyncing", endlessly, but the sound is always ok !

alsasink have only one "resyncing" then the sound become silent.

You can listen a recording from Comment #78 (only one channel, both are identical):

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-mono-logsync.flac

You can see this picture from comment #78 (waveform):
http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-0-comment.png

Time can differ.


I'm running this pipeline:

http://dl.illwieckz.net/u/thomas-debesse/bug-report/gstreamer/bug-692953/20130830.gstreamer-drift-problem-full-8.34-0-comment.png

with the modification to gstalsasink.c from Comment #147:

---8<-------------------------------------------------------
  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    /* start by doing a blocking wait for free space. Set the timeout
     * to 4 times the period time */
    err = snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
    if (err == -EPIPE) {
      GST_DEBUG_OBJECT (asink, "wait error, %d", err);
      if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
    }

    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
      if (err == -EAGAIN) {
        continue;
      } else if (err == -ENODEV) {
        goto device_disappeared;
      } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
      continue;
    }
---8<-------------------------------------------------------

Interesting...does it take longer with my change to start exhibiting bad behavior, or is it about the same.  Seems like a gradual starvation (underrun) scenario where eventually recovery is not possible.

In Comment #78 the first and last "recovery" came at 8min, in Comment #149, it came at 5min. But the first use alsasrc and the second use jackaudiosrc.

Basically, time depends on the context, but nothing seems to have changed. The scenario is identical.

Hmmm...what about this mod...


static gint
gst_alsasink_write (GstAudioSink * asink, gpointer data, guint length)
{
  GstAlsaSink *alsa;
  gint err;
  gint cptr;
  gint16 *ptr = data;

  alsa = GST_ALSA_SINK (asink);

  if (alsa->iec958 && alsa->need_swap) {
    guint i;

    GST_DEBUG_OBJECT (asink, "swapping bytes");
    for (i = 0; i < length / 2; i++) {
      ptr[i] = GUINT16_SWAP_LE_BE (ptr[i]);
    }
  }

  GST_LOG_OBJECT (asink, "received audio samples buffer of %u bytes", length);

  cptr = length / alsa->bpf;

  GST_ALSA_SINK_LOCK (asink);
  while (cptr > 0) {
    GST_DELAY_SINK_LOCK (asink);
    err = snd_pcm_writei (alsa->handle, ptr, cptr);
    GST_DELAY_SINK_UNLOCK (asink);

    GST_DEBUG_OBJECT (asink, "written %d frames out of %d", err, cptr);
    if (err < 0) {
      GST_DEBUG_OBJECT (asink, "Write error: %s", snd_strerror (err));
      if (err == -EAGAIN) {
        /* start by doing a blocking wait for free space. Set the timeout
         * to 4 times the period time */
        snd_pcm_wait (alsa->handle, (4 * alsa->period_time / 1000));
        continue;
      } else if (err == -ENODEV) {
        goto device_disappeared;
      } else if (xrun_recovery (alsa, alsa->handle, err) < 0) {
        goto write_error;
      }
      continue;
    }

    ptr += snd_pcm_frames_to_bytes (alsa->handle, err);
    cptr -= err;
  }
  GST_ALSA_SINK_UNLOCK (asink);

  return length - (cptr * alsa->bpf);

write_error:
  {
    GST_ALSA_SINK_UNLOCK (asink);
    return length;              /* skip one period */
  }
device_disappeared:
  {
    GST_ELEMENT_ERROR (asink, RESOURCE, WRITE,
        (_("Error outputting to audio device. "
                "The device has been disconnected.")), (NULL));
    goto write_error;
  }
}

I'll try this code tomorrow.² :)

OK

The bug description now states that alsasink doesn't work by default at all, which is surely not true. Maybe you could qualify that a little..

Hi!

> The bug description now states that alsasink doesn't 
> work by default at all, which is surely not true.
> Maybe you could qualify that a little..

Um, yes, it works with sync default value when alsasink is used with audiotestsrc and with filesrc, when synchronization is not needed.

I corrected the description:

< alsasink does not work at all with default value "sync=true"
> alsasink does not work at all with default value "sync=true" when used with live source that needs synchronization

To summarize the previous 155 comments:

When using alsasink with alsasrc or jackaudiosrc or udpsrc, in a system where jack and alsa and network are functional, alsasink become noisy then silent in less than 30 min when used with default sync value "true", and become silent suddenly in some hours (or days) when used with sync value "false".

The sum of the execution time of all my test pipelines can be counted in months.

Outside my test environment, I encounter this problem every day, even several times a day depending on the configuration.

Were tested 2.6 and 3.2 kernel, realtime and no realtime kernel, various gstreamer version (0.10.30, 0.10.36, 1.0.1, 1.0.4, 1.0.6, 1.0.9, 1.0.10), i386 and x86_64 architectures, various sound card (DSX, Live CT4822, Live CT4790, XFi, I82801, Audigy, H2n, nVidia, UCA202, Muse LT3, Juli@), various bus (USB, PCI, PCIe) and various computer, with or without alsa plugin (dmix, plug), with or without virtual alsa interface on top of physical interface.

I personally checked this problem for over two years (a sound file recorded at the output of alsasink with default value is provided in the thread, see Comment #78 ). We can find a previous bug report aged from seven years (see Comment #139 ).

When someone find an open source code that uses alsasink for live transmission, the code never use the default (see Comment #130 for examples), or the code does not work. If the code does not use the default value, you must be very patient to experience the problem, but with patience the bug always happen. We have level 3 log with default value, not with the other value. In all cases, regardless of the value used, alsasink does not work with a live source. It is only a matter of time to experience the problem.

Public documentations that are not those of the gstreamer project itself indicate that we should not use the default setting (see Comment #129 or Comment #138 for examples).

All the other tested modules (jackaudio/alsasrc, udpsrc/sink, rtpopuspay/depay opusenc/dec, audioresample/convert, etc.) used in tested pipelines that use alsasink were tested without alsasrc and works fine in all test case.

I think we can say that alsasink does not work at all with (and without) the default value for synchronization when alsasink must be synchronized. :)

It has also been discovered by the submitter that replacing alsasink with jackaudiosink one of the pipelines where alsasink has failed (started studdering and eventually gone silent with 'sync=true'), the problem does not occur with 'sync=true'.  JACK sits on top of ALSA and presumably uses the same ALSA API that is being called by the alsasink plugin.

Yes, when other module than alsasink are used with alsasink, I have tested other modules in many combinations.

pipeline example:

jackaudiosrc ! audioresample ! alsasink

* testing the absence of each other module (removing or replacing one module at a time):

jackaudiosrc ! alsasink
(testing audioresample absence)

alsasrc ! audioresample ! alsasink
(testing jackaudiosrc absence)

* testing the presence of each other module without alsasink (one module at a time):

jackaudiosrc ! jackaudiosink
(testing jackaudiosrc without alsasink)

alsasrc ! audioresample ! jackaudiosink
(testing audioresample witrout alsasink)

* testing the presence of each other modules used together without alsasink:

jackaudiosrc ! audioresample ! jackaudiosink
(testing the whole pipeline without alsasink)

It appears than no module or any combination of modules does not cause or prevent the problem by its absence or presence.

> Robert Krakora 2013-09-12 18:31:00 UTC Comment #152
> Hmmm...what about this mod...

I get the same behavior :/

Hmmm...interesting...

Maybe comparing the JACK sink with the ALSA sink will yield some clues.

> Maybe comparing the JACK sink with the ALSA sink will yield some clues.

They seem too different to be compared…

OK

Maybe alsasink needs an overhaul?

Check this out:

http://comments.gmane.org/gmane.comp.video.gstreamer.bugs/98458

And this:

https://community.freescale.com/thread/238671

Seems like src/sink plugins written for JACK and Pulse work fine for live streams.  They are servers that reside on top of ALSA.  No offense, but alsasink seems like it needs some attention.

Interesting...

gst_base_sink_query_latency ()

gboolean            gst_base_sink_query_latency         (GstBaseSink *sink,
                                                         gboolean *live,
                                                         gboolean *upstream_live,
                                                         GstClockTime *min_latency,
                                                         GstClockTime *max_latency);
Query the sink for the latency parameters. The latency will be queried from the upstream elements. live will be TRUE if sink is configured to synchronize against the clock. upstream_live will be TRUE if an upstream element is live.

If both live and upstream_live are TRUE, the sink will want to compensate for the latency introduced by the upstream elements by setting the min_latency to a strictly possitive value.

This function is mostly used by subclasses.

sink :

the sink
live :

if the sink is live. [out][allow-none]
upstream_live :

if an upstream element is live. [out][allow-none]
min_latency :

the min latency of the upstream elements. [out][allow-none]
max_latency :

the max latency of the upstream elements. [out][allow-none]
Returns :

TRUE if the query succeeded.

Would you test this pipeline?

gst-launch alsasrc ! queue ! alsasink

Robert Krakora 2013-09-13 13:42:23 UTC 
> Would you test this pipeline?
> gst-launch alsasrc ! queue ! alsasink


You have already suggested that in Comment #10 and and I answered in Comment #11 ;) unless you ask this time to compare the original alsasink with queue to your modified alsasink with queue ?

This would mean alsasrc and alsasink with 'sync=true' implicitly with queue in between them.  Don't know if you had tested with queue in between with alsasink 'sync=true'...I know you have with alsasink 'sync=false'.

(In reply to comment #169)
> Robert Krakora 2013-09-13 13:42:23 UTC 
> > Would you test this pipeline?
> > gst-launch alsasrc ! queue ! alsasink
> 
> 
> You have already suggested that in Comment #10 and and I answered in Comment
> #11 ;) unless you ask this time to compare the original alsasink with queue to
> your modified alsasink with queue ?

Yes, with modified alsasink with queue...sorry...

I have tested these 4 pipelines:

gst-launch-1.0 alsasrc device=hw:Juli ! alsasink device=hw:Juli sync=true
gst-launch-1.0 alsasrc device=hw:Juli ! alsasink device=hw:Juli sync=false
gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true
gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=false

* with original gstalsasink.c code:

The sound is nice at the beginning

* with code from Comment #147 :

The sound is nice at the beginning

* with code from Comment #152 :

The sound is noisy from the beginning.

I have not yet taken the time to test through time. ^^

I will try the third pipeline (queue and sync=true) with code from Comment #147 giving it more time.

I have launched two similar pipelines:

gst-launch-1.0 alsasrc device=hw:Live1 ! queue ! alsasink device=hw:Live1 sync=true
gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true

The first is recording and playing on a PCI SB Live!, the seconde is recording and playing on a PCIe Juli@ XTE.

The two pipelines are running since more than 1 hour and 30 minutes.

The first has run a very long time without a problem, then stuttered for several tens of minutes before correcting himself.

This is the full log with GST_DEBUG=3:

> user@comp:~$ gst-launch-1.0 alsasrc device=hw:Live1 ! queue ! alsasink device=hw:Live1 sync=true
> Setting pipeline to PAUSED ...
> Pipeline is live and does not need PREROLL ...
> 0:00:00.029252700  9064  0x8bd6e00 FIXME                default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<alsasrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
> Setting pipeline to PLAYING ...
> 0:00:00.029781567  9064 0xb5c01320 WARN                     bin gstbin.c:2474:gst_bin_do_latency_func:<pipeline0> failed to query latency
> New clock: GstAudioSrcClock
> 0:00:00.030852776  9064  0x8bd6e00 WARN                    alsa pcm_hw.c:1401:_snd_pcm_hw_open: alsalib error: Invalid value for card
> 0:25:33.446544487  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20000934 > 20000000
> 0:25:33.446607898  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
> 1:15:43.907689145  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 20000311 > 20000000
> 1:15:43.907738170  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing

The second one has never experienced problem in more than 1 hour and 30 minutes !

this is the full log with GST_DEBUG=3:

> user@comp:~$ gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true
> Setting pipeline to PAUSED ...
> Pipeline is live and does not need PREROLL ...
> 0:00:00.028395941  9034  0x8c9ee00 FIXME                default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<alsasrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
> Setting pipeline to PLAYING ...
> 0:00:00.028785708  9034 0xb5c01320 WARN                     bin gstbin.c:2474:gst_bin_do_latency_func:<pipeline0> failed to query latency
> New clock: GstAudioSrcClock
> 0:00:00.029872384  9034  0x8c9ee00 WARN                    alsa pcm_hw.c:1401:_snd_pcm_hw_open: alsalib error: Invalid value for card

This two pipeline are running code from Comment #147 with sync=true. It's the first time I see pipelines using alsasink with sync=true running fine or auto correcting during more than one hour. With the original code that fails in about ten minutes.

I think we can say we are on the right path. :)

I hope so.  You have, unfortunately, been dealing with it for about two years you say.  You are a gluten for punishment.  :-)  I have been using Pulse Audio and the GStreamer pulsesrc and pulsesink plugins (with no problem like this by the way) for the past year and forgot all about the alsasink problems I had experienced in the past.

What we are doing by adding a queue:

http://gstreamer.freedesktop.org/data/doc/gstreamer/head/manual/html/section-threads-uses.html

Better explanation:  :-)

http://docs.gstreamer.com/display/GstSDK/Basic+tutorial+7%3A+Multithreading+and+Pad+Availability

> You are a glutton for punishment.  :-)

It's more that I **really** need it to be working! :D

In fact, apart from this very annoying bug, I am very happy with GStreamer. It offers hundreds of possibilities, and usually, it does well. You may have noticed as I have been able to launch more than 12 pipelines simultaneously on two different jack patchbay and 6 sound card, all on one 6 years old computer, and without consuming more than 8% of cpu and not much memory. Except this bug, I am very pleased with gstreamer! :)

> What we are doing by adding a queue:
> http://gstreamer.freedesktop.org/data/doc/gstreamer/head/manual/html/section-threads-uses.html

> Better explanation:  :-)
> http://docs.gstreamer.com/display/GstSDK/Basic+tutorial+7%3A+Multithreading+and+Pad+Availability

Thanks for the useful information!

By the way, this pipeline from Comment #125 is running nicely since 4 days, there is some 'WARN' sometimes (see Comment #127 ) but sound is not affected:

> gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink name=src client-name=xfi connect=none sync=true

This pipeline does not use any "queue" element.

I am trying an additional pipeline (jackaudiosrc ! queue ! alsasink sync=true):

> gst-launch-1.0 -v jackaudiosrc name=sink client-name=live connect=none ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! queue ! alsasink device=hw:Live sync=true

Acually, JACK is an audio client/server application and the JACK API that is called by the GStreamer JACK plugin actually marshalls the audio data to the JACK server which runs in a different process and utilizes the ALSA API.

Check this out:

http://lac.linuxaudio.org/2003/zkm/slides/paul_davis-jack/jackd.html

GStreamer JACK source/sink plugins are external clients to the JACK server...

http://lac.linuxaudio.org/2003/zkm/slides/paul_davis-jack/client.html

Three days later Comment #173 and comment #177,

This pipeline has printed nothing and sound is ok:
> gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true

This pipeline is printing many logs and is silent:
> gst-launch-1.0 alsasrc device=hw:Live1 ! queue ! alsasink device=hw:Live1 sync=true

logs:
> 67:49:44.857404382  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1911213314 > 20000000
> 67:49:44.950268629  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1911214371 > 20000000
> 67:49:45.043129356  9064  0x8bd6db0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 1911215395 > 20000000
> [… many per second, endlessly]

This pipeline is printing many logs and is silent:
> gst-launch-1.0 -v jackaudiosrc name=sink client-name=live connect=none ! capsfilter caps=audio/x-raw, format=F32LE, rate=48000, channels=2 ! audioconvert ! audioresample ! capsfilter caps=audio/x-raw, format=S16LE, rate=48000, channels=2 ! queue ! alsasink device=hw:Live sync=true

logs:
> 66:04:13.143236571  9120  0x8c47d80 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 31062342927 > 20000000
> 66:04:13.164612731  9120  0x8c47d80 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 31062347184 > 20000000
> 66:04:13.185890110  9120  0x8c47d80 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 31062349355 > 20000000
> [… many per second, endlessly]

This three pipelines are running "alsasink" code from Comment #147 with "sync=true" and using a "queue" element.

This other pipeline:
> gst-launch-1.0 -v alsasrc device=hw:XFi ! capsfilter caps=audio/x-raw, format=S16LE, rate=48000, channels=2 ! audioconvert ! audioresample ! capsfilter caps=audio/x-raw, format=F32LE, rate=48000, channels=2 ! jackaudiosink name=src client-name=xfi sync=true connect=none

is running since nearly 7 days, with *sometime* logs like that:
> 160:24:17.805550209  6266  0x821acf0 WARN           audiobasesink gstaudiobasesink.c:1295:gst_audio_base_sink_skew_slaving:<src> correct clock skew -20244981 < -20000000
but sound is ok.

This pipeline is running original Gstreamer code, with "sync=true", without "queue" element. Now we must be able to say that alsasrc is functional and the doubt is removed?

Now it would be interesting to know why the code of alsasink from Comment# 147 used alongside a "queue" element has *no* problem with the PCIe card ESI Juli@ XTE when pipelining alsasrc and alsasink with "sync = true".

This is this PCI express card: ESI Juli@ XTE
http://www.esi-audio.com/products/juliaxte/

> user@comp:~$ cat /proc/asound/cards | grep Juli -A0
>  3 [Juli           ]: ICE1724 - ESI Juli@
>                       ESI Juli@ at 0x9c00, irq 18

> user@comp:~$ grep ' 3 ' /proc/asound/modules 
>  3 snd_ice1724

> user@comp:~# lspci -kvm -s 05:00.0
> Device:    05:00.0
> Class:    Multimedia audio controller
> Vendor:    VIA Technologies Inc.
> Device:    VT1720/24 [Envy24PT/HT] PCI Multi-Channel Audio Controller
> SVendor:    Unknown vendor 3031
> SDevice:    Device 4553
> Rev:    01
> Driver:    snd_ice1724

> user@comp:~$ lspci -s 05:00.0 -vvv
> 05:00.0 Multimedia audio controller: VIA Technologies Inc. VT1720/24 [Envy24PT/HT] PCI Multi-Channel Audio Controller (rev 01)
> 	Subsystem: Device 3031:4553
> 	Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
> 	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> 	Latency: 64
> 	Interrupt: pin A routed to IRQ 18
> 	Region 0: I/O ports at 9c00 [size=32]
> 	Region 1: I/O ports at 9880 [size=128]
> 	Capabilities: <access denied>
> 	Kernel driver in use: snd_ice1724

> user@comp:~# alsacap -C 3
> *** Scanning for playback devices on card 4 ***
> Card 4, ID `Juli', name `ESI Juli@'
>   Device 0, ID `ICE1724', name `ICE1724', 1 subdevices (1 available)
>     2 channels, sampling rate 16000..192000 Hz
>     Sample formats: S32_LE
>       Subdevice 0, name `subdevice #0'
>   Device 1, ID `ICE1724 IEC958', name `ICE1724 IEC958', 1 subdevices (1 available)
>     2 channels, sampling rate 32000..192000 Hz
>     Sample formats: S32_LE
>       Subdevice 0, name `subdevice #0'

> user@comp:~# alsacap -R -C 3
> *** Scanning for recording devices on card 4 ***
> Card 4, ID `Juli', name `ESI Juli@'
>   Device 0, ID `ICE1724', name `ICE1724', 1 subdevices (1 available)
>     2 channels, sampling rate 16000..192000 Hz
>     Sample formats: S32_LE
>       Subdevice 0, name `subdevice #0'
>   Device 1, ID `ICE1724 IEC958', name `ICE1724 IEC958', 1 subdevices (1 available)
>     2 channels, sampling rate 32000..192000 Hz
>     Sample formats: S32_LE
>       Subdevice 0, name `subdevice #0'

Hmmm...that is interesting...I would expect these two to behave the same...

This pipeline has printed nothing and sound is ok:
> gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true

This pipeline is printing many logs and is silent:
> gst-launch-1.0 alsasrc device=hw:Live1 ! queue ! alsasink device=hw:Live1 sync=true

I agree, alsasrc seems to be OK...alsasink is the issue...

Would be interesting to know if device=hw:Live will run well in this pipeline:

gst-launch-1.0 -v alsasrc device=hw:Live ! capsfilter caps=audio/x-raw, format=S16LE, rate=48000, channels=2 ! audioconvert ! audioresample ! capsfilter caps=audio/x-raw, format=F32LE, rate=48000, channels=2 ! jackaudiosink name=src client-name=live sync=true connect=none

> Hmmm...that is interesting...I would expect these two to behave the same...

Yes, this means that the sound card can also have influence, but I do not know why…

Your change is not perfect but it is encouraging. With a small change in the code, with a special equipment, and with the queue element, sometimes it works. It's better than ever. :D

* with original code : It never works, It fails in less than 10min.

* with your code : The problem need hours to appear, It may work without problem in some very specific and particular cases (if the druid gives you the magic spell, if the moon is blue, and if you have the right cauldron).

Did you have a chance to run this pipeline?

gst-launch-1.0 -v alsasrc device=hw:Live ! capsfilter caps=audio/x-raw,
format=S16LE, rate=48000, channels=2 ! audioconvert ! audioresample !
capsfilter caps=audio/x-raw, format=F32LE, rate=48000, channels=2 !
jackaudiosink name=src client-name=live sync=true connect=none

yes I will do that when I have a little time. :)

Hey, this pipeline which has run which ran for three days without error and without sound degradation:

> gst-launch-1.0 alsasrc device=hw:Juli ! queue ! alsasink device=hw:Juli sync=true

has failed (silent) and is printing lot of things like that:

> 96:02:10.954697732  9034  0x8c9edb0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2161525628 > 20000000
> 96:02:10.964680002  9034  0x8c9edb0 WARN           audiobasesink gstaudiobasesink.c:1273:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew 2161526138 > 20000000

It needs 4 days to fail, but it fails !

This pipelines use code from Comment #147 .

also, I've launched that pipeline (with code from comment #147 ):

> gst-launch-1.0 -v alsasrc device=hw:Live ! capsfilter caps="audio/x-raw, format=S16LE, rate=48000, channels=2" ! audioconvert ! audioresample ! capsfilter caps="audio/x-raw, format=F32LE, rate=48000, channels=2" ! jackaudiosink name=src client-name=live sync=true connect=none

The "alsasrc ! jackaudio" pipeline from comment #186 is running fine (sound is good) since two days, but with some warning like that:

47:20:23.992553466 10303  0x8ed4cf0 WARN           audiobasesink gstaudiobasesink.c:1579:gst_audio_base_sink_get_alignment:<src> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing

Well, I think that you have pretty much narrowed the problem to the GStreamer alsasink plugin.  Seems like a starvation or dataflow interruption causing a timing skew.  alsasink enters this condition and there is seemingly no way for it to recover.  A queue helps some to decouple the source from the sink thus freeing up the source to go out and get more data immediately instead of getting blocked until the alsasink writes data out to the audio device.  What to do now?  Obviously the JACK and Pulse Audio servers which utilize ALSA have dealt with this problem successfully as the GStreamer JACK and Pulse Audio plugins work fine.  You use the JACK plugins and I use the Pulse Audio plugins.

Yes I think it is a good analysis!

And since we can find very old messages about the need for a functional alsasink under live condition, and this not as the repair of a regression, but as an improvement, we can say that it never worked!

For example, the bug #340842 was created in 2006, only five month after the first Gstreamer 0.10 release, and was labelled as wishlist… Seven years ago it was already a wish, only a wish. :p

Firstly it does not work at all for this use case (synchronized live streaming), and secondly it never worked.

This is still something to do! :D

Can someone provide a summary of the current understanding of the situation? Maybe we should also just start a new bug with that then, nobody is going to read 200 comments first :)

I think what Thomas has discovered is that alsasink sync=true fails almost immediately and alsasink sync=false fails after some ours.  The submitter can provide more details.  All documentation that we have found recommends setting sync=false for alsasink and this is wrong.  It seems as though alsasink underflows and never recovers.  The submitter tested the jacksinkaudiosink with sync=true and it runs indefinitely with no underflow and I have tested pulsesink with sync=true and it too runs indefinitely with no underflow.  The question is has alsasink ever functioned properly?  The submitter has proven that alsasink sync=false does fail similar to alsasink sync=true but after an extended period of time.  JACK and Pulse Audio both make use of ALSA, albiet in a separate process than running GStreamer pipelines including their respective plugins, and they seem to not experience unrecoverable underflow situations.

I think what the submitter has discovered is that alsasink sync=true fails almost
immediately and alsasink sync=false fails after some hours.  The submitter can
provide more details.  All documentation that we have found recommends setting
sync=false for alsasink and this is wrong.  It seems as though alsasink
underflows and never recovers.  The submitter tested the jacksinkaudiosink with
sync=true and it runs indefinitely with no underflow and I have tested
pulsesink with sync=true and it too runs indefinitely with no underflow.  The
question is has alsasink ever functioned properly?  The submitter has proven
that alsasink sync=false does fail similar to alsasink sync=true but after an
extended period of time.  JACK and Pulse Audio both make use of ALSA, albiet in
a separate process than running GStreamer pipelines including their respective
plugins, and they seem to not experience unrecoverable underflow situations.

(In reply to comment #192)
> Can someone provide a summary of the current understanding of the situation?
> Maybe we should also just start a new bug with that then, nobody is going to
> read 200 comments first :)

I think this is the best summary it is possible to write. :)

Hi,

I am confronting to the exact same issue with our dear friend alsasink.
I just read the complete discussion, the tests you did are really complete, nice job.

I wanted to know if you know of any progress on that bug, is it resolved? Planned for resolution in next release?
Unfortunatly on my target jack and pulse are not available.

Regards,
Julien.

I am not a developer on GStreamer, just a user.  Maybe Sebastian or one of the other developers could comment.  I have moved to GStreamer 1.0 and I use the Pulse Audio plugin which does not exhibit this problem.

Hi all, I am also observing this issue.

By looking at the debug output and code I have some questions:

I wonder if something is missing which connects ringbuffer underrun from the audiosrc to the audiosink?
Is this supposed to work via skew slaving?
Won't the ringbuffer on the sink deplete?

Thanks,

Tom

Update:

I looked at this further and I think this is what happens:
* The audio source provides the pipeline clock, but it does not take into account buffer underruns (gst_audio_base_src_get_time).
* The audio sink relates it's time with the pipeline time but only allows that the time of the sink is later than that of the pipeline.(gst_audio_base_sink_skew_slaving). However after enough buffer underruns from the source, the pipeline time will be less than the sink time...

When setting provide-clock to false on the alsasrc, I did not encounter the issue.

To debug this I have been using:
GST_DEBUG=audiosrc:6,audiosink:6,alsa:5,ringbuffer:5,audiobasesrc:6,audiobasesink:5
I added a sleep in the gst_alsasrc_read to occasionally generate buffer underruns.

After a while the audiobasesink DEBUG logging looks like this:
   0x80cc0 DEBUG          audiobasesink gstaudiobasesink.c:1256:gst_audio_base_sink_skew_slaving:<alsasink0> internal 0:00:01.085532879 external 0:00:00.605102040 cinternal 0:00:00.000000000 cexternal 0:00:00.000000000
0:00:01.262867407  9974    0x80cc0 DEBUG          audiobasesink gstaudiobasesink.c:1276:gst_audio_base_sink_skew_slaving:<alsasink0> internal 0:00:01.085532879 external 0:00:00.605102040 skew 480430839 avg 577713
0:00:01.263301518  9974    0x80cc0 DEBUG          audiobasesink gstaudiobasesink.c:1819:gst_audio_base_sink_render:<alsasink0> final timestamps: start 0:00:00.801088434 - stop 0:00:00.812698411

That is a great observation.  Searching the Internet on "provide-clock", in regards to alsasrc, yields a lot of interesting posts.  Wonder why then, pulsesrc and jackaudiosrc (Pulse Audio and JACK utilize ALSA under-the-hood in separate processes), do not exhibit this same behaviour.  Maybe because they manage ALSA differently within a separate process?

pulsesrc has it's own time implementationi and jackaudiosrc it's own buffer implementation. These are different from the one used by alsasrc.
The jack alsadriver contains code for determining the buffer underrun time in alsa_driver_xrun_recovery. Pulse probably also determines the delay.

Looks like alsasrc needs some attention in regards to under run handling.

Interesting findings.

I have the issue using udpsrc instead of alsasrc.
Then I would say that the problem can be in udpsrc and alsasrc or only in alsasink.

jup

What does your pipeline look like?
Can you post a snippit of DEBUG output from the audiobasesink when the audio is no longer audible similar to the one I posted in comment 199?

Created attachment 276579 [details]
jup-gstreamer-pipeline-udpsrc-alsasink

Tom,

The pipeline I use is doing the following:

-> input : udp packets with RTP MP3 audio data
-> process : decode the MP3 audio data
-> output : audio data sent to alsa

See attachment.

About the debug info, I first need to recompile gstreamer and then reproduce the problem.
As soon as I will have them I will post.

Can someone with more indepth knowledge of the audiobasesrc and audiobasesink comment on the observations I made in comment 199? More specifically:

* Shouldn't the clock provided by audiobasesrc (or gstalsasrc) take into account the time spent in buffer overruns?
* Why is the skew limited in one direction in audiobasesink?

Thanks

jup, does your pipeline also stop working when you add an rtpjitterbuffer?
You may set the latency property of the jitterbuffer to zero.

I am interested in knowing if anyone is suffering from the this issue when:
- setting alsasrc provide-clock=false
- using an rtpjitterbuffer between udpsrc and alsasink

(In reply to comment #208)
> jup, does your pipeline also stop working when you add an rtpjitterbuffer?
> You may set the latency property of the jitterbuffer to zero.
> 
> I am interested in knowing if anyone is suffering from the this issue when:
> - setting alsasrc provide-clock=false
> - using an rtpjitterbuffer between udpsrc and alsasink

Tom,

I can try that, but first I want to understand why do you suggest to set the latency property to zero?
It means that the packets will not be kept in the buffer => no buffering.
If there is no buffering, then the element cannot do what he has to do, control the network jitter, reorder or dump packets?

Hi, 

I think I encouter a related issue with alsasink that could have the same root cause. My pipeline play broadcasted TV in real time (so a live source and video + audio sinks with sync=true). 

The problem occurs sometimes as soon as the pipeline is started, but always after an xrun recovery. When this happens, I get no sound at all or incorrect sound (partial sample buffers). Also when the issue occurs, I then get xrun repeatedly. Audio may come back after a while (several minutes).

I can very easily reproduce the issue, so investigation is facilitated.
Also the problem never occurs with sync=false on the alsasink, but of course audio is then unsynchronized.

I have narrowed the issue to alsasink as input buffers are filled with data but output buffers are filled with zero when the problem leads to silence.

I think the problem may come from GstAudioSinkRingBuffer and the following debug logs seem to illustrate an issue:

When no problem occurs, we can see that a segment prepare read (there are two audio segments, 0 and 1) is always followed by a write then a segment clear:

D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:acquired device
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:activate device
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: buffer time: 42666 usec
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: latency time: 21333 usec
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: total segments: 2
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: latency segments: 3
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: segment size: 8192 bytes = 1024 samples
D ringbuffer  (kraken/audio_queue:src)         : acquire ringbuffer: buffer size: 16384 bytes = 2048 samples
...
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 4) @0x72953618
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:80c32308...18b35a07
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 4, write to 5-0, diff 1, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x72955618 seg 1, sps 1024, off 0, avail 4024
D ringbuffer  (kraken/audio_queue:src)         : copy 4024 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write 1536 : 1536
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 4, write to 5-4024, diff 1, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x72955618 seg 1, sps 1024, off 4024, avail 4168
D ringbuffer  (kraken/audio_queue:src)         : copy 4168 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 4, write to 6-0, diff 2, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:waiting..
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 0 @0x72953618
D ringbuffer  (kraken/audiosink-ringb)         : GstAudioSinkRingBuffer:signal waiter
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 1 (real 5) @0x72955618
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:408dee07...500c35fc
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 5, write to 6-0, diff 1, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x72953618 seg 0, sps 1024, off 0, avail 8120
D ringbuffer  (kraken/audio_queue:src)         : copy 8120 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write 1536 : 1536
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 5, write to 6-8120, diff 1, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x72953618 seg 0, sps 1024, off 8120, avail 72
D ringbuffer  (kraken/audio_queue:src)         : copy 72 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 5, write to 7-0, diff 2, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:waiting..
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 1 @0x72955618
D ringbuffer  (kraken/audiosink-ringb)         : GstAudioSinkRingBuffer:signal waiter
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 6) @0x72953618
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:f4f6dbfc...22130cff


The logs GstAlsaSink:408dee07...500c35fc are custom logs that display the first and last 4 bytes of the data written by gst_alsasink_write().


When the problem occurs, we see several consecutive segments prepare reads followed by clear before any write occur, then consecutive write occur with null data, as the segments have been cleared just before:

D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 11358) @0x745ce898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 0 @0x745ce898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 1 (real 11359) @0x745d0898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 1 @0x745d0898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 11360) @0x745ce898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 0 @0x745ce898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 1 (real 11361) @0x745d0898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 1 @0x745d0898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 11362) @0x745ce898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 0 @0x745ce898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 1 (real 11363) @0x745d0898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 1 @0x745d0898
D ringbuffer  (kraken/audiosink-ringb)         : prepare read from segment 0 (real 11364) @0x745ce898
W alsa        (kraken/audiosink-ringb)         : GstAlsaSink:00000000...00000000
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write 1536 : 1536
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 11364, write to 11348-1088, diff -16, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x745ce898 seg 0, sps 1024, off 1088, avail 7104
D ringbuffer  (kraken/audio_queue:src)         : copy 7104 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 11364, write to 11349-0, diff -15, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x745d0898 seg 1, sps 1024, off 0, avail 5184
D ringbuffer  (kraken/audio_queue:src)         : copy 5184 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write 1536 : 1536
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 11364, write to 11349-5184, diff -15, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x745d0898 seg 1, sps 1024, off 5184, avail 3008
D ringbuffer  (kraken/audio_queue:src)         : copy 3008 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 11364, write to 11350-0, diff -14, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x745ce898 seg 0, sps 1024, off 0, avail 8192
D ringbuffer  (kraken/audio_queue:src)         : copy 8192 bytes
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:pointer at 11364, write to 11351-0, diff -13, segtotal 2, segsize 8192, base 0
D ringbuffer  (kraken/audio_queue:src)         : GstAudioSinkRingBuffer:write @0x745d0898 seg 1, sps 1024, off 0, avail 1088
D ringbuffer  (kraken/audio_queue:src)         : copy 1088 bytes
D ringbuffer  (kraken/audiosink-ringb)         : clear segment 0 @0x745ce898


You can notice that from GstAlsaSink:00000000...00000000 logs that gst_alsasink_write() is called with null data.


Do you think this could be the same issue and what I could do to investigate further the problem ?

Regards,
Rémi

Note: I run the pipeline with "--gst-debug=ringbuffer:9" to get the debug logs, in case someone wants to check for the previous problems reports if the issue is similar.

I made a patch that makes gstreamer more aware of buffer underruns in the audiosink.

Without the patch, the buffer underrun time isn't reported to the audiosink which causes the audiosink to handle this as wrong clock skew calibration (which it isn't).

This patch will clear the ringbuffer on buffer underrun and reset the clock skew calibration when the underrun has finished.

Can anyone try this and let me know if this helps fixing the issues you have.

In case your pipeline also contains an alsasrc set provide-clock to false, as mentioned in comment 199.

Created attachment 277219 [details] [review]
Handle buffer underrun

See comment 212

Created attachment 277257 [details] [review]
Handle buffer underrun

Previous patch + reset average skew and discont time

Review of attachment 277257 [details] [review]:

::: ext/alsa/gstalsasink.c
@@ +1039,3 @@
         goto device_disappeared;
+      } else {
+        xrun_recovery (alsa, alsa->handle, err);

That would mean that on underrun we throw away even more data, no? That doesn't seem right

The patch is throwing away the data that should have been playing during the underrun time.

For the same reason, data in the ringbuffer is thrown away because it would also be played at the wrong time.

You are handling the case where data is late in arriving to the sink and time to play it has already passed, correct?  That is why you are throwing it away.  Prevents the case where data is always behind the clock and never catches up.

The gstreamer code is written so data is continuously fed to the device. When no data is available, for example when it arrives late, silence is sent to the audio device.
The bufferrun occurs because the thread that needs to provide the data was not able to (scheduling).
This thread is running audioringbuffer_thread_func from gstaudiosink.

The scheduling of the data into the ringbuffer in gst_audio_base_sink_render is based on clock slaving. When a buffer underrun occurs, the scheduling of this data is incorrect because it would be played 'buffer underrun time' later.

Adding to my previous comment, to clarify the audio dataflow:

audio arrives in audiobasesink in gst_audio_base_sink_render, where it is written into gstringbuffer (software ringbuffer). This write blocks when no more room is available.

In a thread running audioringbuffer_thread_func, the gstaudioringbuffer is written to the audio device (hardware ringbuffer). This thread does not block when no data is arriving, but it continues to read the gstringbuffer, which is cleared (silence) when no data was written to it.

Thanks for the clarification.  Also explains why the failure still eventually occurs even when the "sync" property on alsasink is set to "false".  Almost every example I have seen on the Internet shows the "sync" property set to "false" for alsasink.

Created attachment 277718 [details] [review]
Handle buffer underrun

Handle buffer underrun in the ringbuffer

Robert, Rémi, jup, can you see what the patch I added does for your pipelines?

If you are using alsasrc, set provide-clock to false.
If you are using udpsrc with rtp, use an rtpjitterbuffer.

Thanks.

Created attachment 277719 [details] [review]
Handle buffer underrun

Minor code improvements, update commit date

Hi Tom, 

I had two issues:

1. No audio or choppy audio from the start of the pipeline
2. Audio lost after a while

With your patch, I reproduce the first problem but not the second one yet. However after more tests, I reproduce the first issue even without having xruns, so I'm not sure this problem is directly related to the one you are fixing.


I use the following pipeline to test my issues:

gst-launch-1.0 mpgtssrc ! queue max-size-buffers=0 max-size-time=0 ! tsdemux ! audio/x-eac3 ! ac3parse ! avdec_eac3 ! audioconvert
 ! audio/x-raw,rate=48000,channels=2 ! alsasink latency-time=21334 buffer-time=42667

mpegtssrc is a custom tuner plugin comparable to a simple v4l2src.


On a side note, I get the following warning with your patch:
gst-libs/gst/audio/gstaudioringbuffer.c:1544:10: warning: suggest explicit braces to avoid ambiguous 'else' [-Wparentheses]

that seems justified for the following code:
      if (!wait_segment (buf))
        if (buf->underrun)
          break;
        else
          goto not_started;

What's sure is that I have none of the issues in sync=false on the sink.

Also, when I have issues, I never get the following logs in debug mode (--gst-debug=audiosink:7,ringbuffer:7):

gst-plugins-base/gst-libs/gst/audio/gstaudioringbuffer.c:1300:wait_segment:<audiosinkringbuffer0> waiting..
gst-plugins-base/gst-libs/gst/audio/gstaudioringbuffer.c:1871:gst_audio_ring_buffer_advance:<audiosinkringbuffer0> signal waiter

But I always get them (repeatedly) when this works correctly (most of the time).

So I think I might have a thread synchronization issue in the ringbuffer in sync=true.

After more investigations, when I get no audio or choppy audio from the beginning, it's because I enter this condition in gstaudioringbuffer.c default_commit() function:

      /* segment too far ahead, writer too slow, we need to drop, hopefully UNLIKELY */
      if (G_UNLIKELY (diff < 0)) {
        /* we need to drop one segment at a time, pretend we wrote a segment. */
        GST_ERROR("skip because diff < 0");
        skip = TRUE;
        break;
      }

This condition is always TRUE when I get no audio, and most often TRUE when I get choppy audio. This condition seems to be reached in sync=true and is never recovered correctly.

Not sure it helps with the initial issue in this bug through...

Rémi,

So this issue 'Audio lost after a while' hasn't occurred anymore with the patch?

If your choppy audio occurs in the diff < 0 condition, this means that the audio is arriving too late at the audiosink.

Maybe this is caused by mpgtssrc due to either not properly reporting it's latency or incorrect timestamps?
If the problem is in alsasink, probably something caused an incorrect clock skew?

Perhaps the audiorate plugin and the basesink ts-offset can be of help to debug the problem.

Thank you very much for your input Tom, configuring latency of the src seems to fix my issue at pipeline startup and this problem is most likely not related to the one discussed in this bug. 

I will now test again that audio is stable with and without your patches as this issue seems to be related to this bug.

*** Bug 743087 has been marked as a duplicate of this bug. ***

Review of attachment 277719 [details] [review]:

I think there may still be an issue in xrun_recovery().  If the call to snd_pcm_prepare() fails in response to an EPIPE, shouldn't xrun_recovery() return that error rather than 0?  Wouldn't it otherwise keep running into the same condition and never actually recover from it, essentially getting stuck in an infinite loop writing out that segment?

Review of attachment 277719 [details] [review]:

I think there may still be an issue in xrun_recovery().  If the call to snd_pcm_prepare() fails in response to an EPIPE, shouldn't xrun_recovery() return that error rather than 0?  Wouldn't it otherwise keep running into the same condition and never actually recover from it, essentially getting stuck in an infinite loop writing out that segment?

I think there is also a race condition when taking down the ringbuffer thread.  I've seen it deadlock because the ringbuffer thread was in sitting in gst_audio_ringbuffer_handle_underrun() on the g_cond_wait() (cond_underrun) while the other thread was sitting in gst_audio_sink_ring_buffer_activate() in the g_thread_join() call waiting for it to shut down.

Review of attachment 277719 [details] [review]:

The deadlock is due to a race condition in gst_audio_ringbuffer_handle_underrun().  Basically, once the ring buffer thread gets signalled, it can potentially recover from the xrun and signal cond_underrun before gst_audio_ringbuffer_handle_underrun() continues to execute, leading to a deadlock in g_cond_wait().  The solution is to check if the underrun has been handled already, and only waiting on cond_underrun if it has not. The function should look like this:

void
gst_audio_ringbuffer_handle_underrun (GstAudioRingBuffer * buf)
{
  GST_OBJECT_LOCK (buf);
  buf->underrun = TRUE;
  GST_AUDIO_RING_BUFFER_SIGNAL (buf);
  if (buf->underrun)
    g_cond_wait (&buf->cond_underrun, GST_OBJECT_GET_LOCK (buf));
  GST_OBJECT_UNLOCK (buf);
}

Review of attachment 277719 [details] [review]:

The deadlock is due to a race condition in gst_audio_ringbuffer_handle_underrun().  Basically, once the ring buffer thread gets signalled, it can potentially recover from the xrun and signal cond_underrun before gst_audio_ringbuffer_handle_underrun() continues to execute, leading to a deadlock in g_cond_wait().  The solution is to check if the underrun has been handled already, and only waiting on cond_underrun if it has not. The function should look like this:

void
gst_audio_ringbuffer_handle_underrun (GstAudioRingBuffer * buf)
{
  GST_OBJECT_LOCK (buf);
  buf->underrun = TRUE;
  GST_AUDIO_RING_BUFFER_SIGNAL (buf);
  if (buf->underrun)
    g_cond_wait (&buf->cond_underrun, GST_OBJECT_GET_LOCK (buf));
  GST_OBJECT_UNLOCK (buf);
}

-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/issues/80.