Audio delay issue

Fri Jul 11 01:32:42 PDT 2014

Hi,

I've developed an audio component that records data from the microphone and streams the audio of the network. The following is my pipeline :

autoaudiosrc ! volume ! audioconvert ! opusenc ! oggmux ! tcpserversink

I start my pipeline by setting it to PLAYING and stop it by setting it to NULL. I connect to my component using gst-launch-1.0 ie

gst-launch-1.0 tcpclientsrc host=10.1.10.67 port=7821 ! oggdemux ! opusdec ! audioconvert ! autoaudiosink

When I run my component's pipeline the first time, everything is ok.

On running it again, it seems to be stuck in the prerolling state for about 15 seconds. Once it starts I get a lot of delay.

In the log, I'm getting messages like :

create DISCONT of 146240 samples at sample 147200
W/GStreamer+audiobasesrc( 1840): 0:00:36.311438892 0x7791ea60 gstaudiobasesrc.c:863:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
W/GStreamer+audiobasesrc( 1840): 0:00:36.311560246 0x7791ea60 gstaudiobasesrc.c:863:gst_audio_base_src_create:<source> warning: Dropped 146240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.

I've tried sending EOS, flush-start and flush-stop events to the pipeline, but this doesn't seem to change anything.

Can anyone help?

Thanks
Lee

Partial Log: 

D/GStreamer+multihandlesink( 1840): 0:00:36.270628527 0x7655b1b0 gstmultihandlesink.c:1423:gst_multi_handle_sink_new_client_position:<tcpsink> queue is currently 1 buffers long
D/GStreamer+multihandlesink( 1840): 0:00:36.271873788 0x7655b1b0 gstmultihandlesink.c:1429:gst_multi_handle_sink_new_client_position:<tcpsink> [socket 0x7791f7b8] SYNC_METHOD_LATEST, position 0
D/GStreamer+GST_CAPS( 1840): 0:00:36.275288736 0x7655b1b0 gstpad.c:2523:gst_pad_get_current_caps:<tcpsink:sink> get current pad caps application/ogg, streamheader=(buffer)< 4f676753000200000000000000002201a858000000000190f24701134f7075734865616401010000803e0000000000, 4f676753000000000000000000002201a85801000000f1c39717012f4f707573546167731e000000456e636f6465642077697468204753747265616d6572204f707573656e630000000001 >
D/GStreamer+multihandlesink( 1840): 0:00:36.277023788 0x7655b1b0 gstmultihandlesink.c:1039:gst_multi_handle_sink_client_queue_buffer:<tcpsink> [socket 0x7791f7b8] no previous caps for this client, send streamheader
D/GStreamer+multihandlesink( 1840): 0:00:36.278799153 0x7655b1b0 gstmultihandlesink.c:1108:gst_multi_handle_sink_client_queue_buffer:<tcpsink> 2 streamheader buffers
D/GStreamer+multihandlesink( 1840): 0:00:36.280507954 0x7655b1b0 gstmultihandlesink.c:1118:gst_multi_handle_sink_client_queue_buffer:<tcpsink> [socket 0x7791f7b8] queueing streamheader buffer of length 47
D/GStreamer+multihandlesink( 1840): 0:00:36.282299465 0x7655b1b0 gstmultihandlesink.c:1118:gst_multi_handle_sink_client_queue_buffer:<tcpsink> [socket 0x7791f7b8] queueing streamheader buffer of length 75
D/GStreamer+basesink( 1840): 0:00:36.285330715 0x7791ea60 gstbasesink.c:3449:gst_base_sink_chain_unlocked:<tcpsink> object unref after render 0x76599550
D/GStreamer+GST_MEMORY( 1840): 0:00:36.289586027 0x7791ea60 gstmemory.c:86:_gst_memory_free free memory 0x7791a008
D/GStreamer+collectpads( 1840): 0:00:36.291344986 0x7791ea60 gstcollectpads.c:1333:gst_collect_pads_check_collected:<collectpads0> All active pads (1 + 0 >= 1) have data, calling gst_ogg_mux_collected
D/GStreamer+collectpads( 1840): 0:00:36.293158111 0x7791ea60 gstcollectpads.c:982:gst_collect_pads_pop:<collectpads0> Pop buffer on pad mux:audio_1487405346: buffer=0x76599370
D/GStreamer+GST_PERFORMANCE( 1840): 0:00:36.297800976 0x7791ea60 gstminiobject.c:324:gst_mini_object_make_writable copy GstBuffer miniobject 0x76599370 -> 0x76599230
D/GStreamer+GST_MEMORY( 1840): 0:00:36.298055871 0x7791ea60 gstmemory.c:86:_gst_memory_free free memory 0x7659a548
D/GStreamer+basesrc( 1840): 0:00:36.298224830 0x7791ea60 gstbasesrc.c:2441:gst_base_src_get_range:<source> calling create offset -1 length 0, time 0
D/GStreamer+audiobasesrc( 1840): 0:00:36.298498528 0x7791ea60 gstaudiobasesrc.c:730:gst_audio_base_src_get_offset:<source> at segment 460 and sample 960
D/GStreamer+audiobasesrc( 1840): 0:00:36.298613215 0x7791ea60 gstaudiobasesrc.c:740:gst_audio_base_src_get_offset:<source> dropped, align to segment 460
D/GStreamer+audiobasesrc( 1840): 0:00:36.298967955 0x7791ea60 gstaudiobasesrc.c:753:gst_audio_base_src_get_offset:<source> reading from 3, we are at 460, sample 147200
D/GStreamer+audiobasesrc( 1840): 0:00:36.299204569 0x7791ea60 gstaudiobasesrc.c:809:gst_audio_base_src_create:<source> reading from sample 147200 length 640
D/GStreamer+GST_MEMORY( 1840): 0:00:36.299337590 0x7791ea60 gstmemory.c:136:gst_memory_init new memory 0x7658c908, maxsize:643 offset:0 size:640
D/GStreamer+ringbuffer( 1840): 0:00:36.299584048 0x7791ea60 gstaudioringbuffer.c:1732:gst_audio_ring_buffer_read pointer at 460, sample 147200, read from 460-0, to_read 320, diff 0, segtotal 20, segsize 640
D/GStreamer+ringbuffer( 1840): 0:00:36.299703527 0x7791ea60 gstaudioringbuffer.c:1304:wait_segment:<openslesringbuffer1> waiting..
D/GStreamer+ringbuffer( 1840): 0:00:36.310383840 0x7786b2c0 gstaudioringbuffer.c:1875:gst_audio_ring_buffer_advance:<openslesringbuffer1> signal waiter
D/GStreamer+ringbuffer( 1840): 0:00:36.310497538 0x7791ea60 gstaudioringbuffer.c:1732:gst_audio_ring_buffer_read pointer at 461, sample 147200, read from 460-0, to_read 320, diff 1, segtotal 20, segsize 640
D/GStreamer+ringbuffer( 1840): 0:00:36.310679569 0x7791ea60 gstaudioringbuffer.c:1757:gst_audio_ring_buffer_read:<openslesringbuffer1> read @0x76587008 seg 0, off 0, sampleslen 320
I/GStreamer+ringbuffer( 1840): 0:00:36.310813163 0x7791ea60 gstaudioringbuffer.c:1785:gst_audio_ring_buffer_read:<openslesringbuffer1> Retrieved timestamp 99:99:99.999999999 @ 0
D/GStreamer+audiobasesrc( 1840): 0:00:36.311055194 0x7791ea60 gstaudiobasesrc.c:831:gst_audio_base_src_create:<source> read 320 of 320
W/GStreamer+audiobasesrc( 1840): 0:00:36.311183996 0x7791ea60 gstaudiobasesrc.c:858:gst_audio_base_src_create:<source> create DISCONT of 146240 samples at sample 147200
W/GStreamer+audiobasesrc( 1840): 0:00:36.311438892 0x7791ea60 gstaudiobasesrc.c:863:gst_audio_base_src_create:<source> warning: Can't record audio fast enough
W/GStreamer+audiobasesrc( 1840): 0:00:36.311560246 0x7791ea60 gstaudiobasesrc.c:863:gst_audio_base_src_create:<source> warning: Dropped 146240 samples. This is most likely because downstream can't keep up and is consuming samples too slowly.
D/GStreamer+GST_MESSAGE( 1840): 0:00:36.311800663 0x7791ea60 gstelement.c:1801:gst_element_message_full:<source> start
I/GStreamer+GST_ERROR_SYSTEM( 1840): 0:00:36.311968267 0x7791ea60 gstelement.c:1832:gst_element_message_full:<source> posting message: Can't record audio fast enough
D/GStreamer+GST_BUS( 1840): 0:00:36.312300506 0x7791ea60 gstbus.c:310:gst_bus_post:<bus0> [msg 0x77969378] posting on bus warning message: 0x77969378, time 99:99:99.999999999, seq-num 170, element 'source', GstMessageWarning, gerror=(GError)NULL, debug=(string)"gstaudiobasesrc.c\(863\):\ gst_audio_base_src_create\ \(\):\ /GstPipeline:audio-stream/GstOpenSLESSrc:source:\012Dropped\ 146240\ samples.\ This\ is\ most\ likely\ because\ downstream\ can\'t\ keep\ up\ and\ is\ consuming\ samples\ too\ slowly.";
D/GStreamer+bin( 1840): 0:00:36.312582902 0x7791ea60 gstbin.c:3404:gst_bin_handle_message_func:<audio-stream> [msg 0x77969378] handling child source message of type warning
D/GStreamer+bin( 1840): 0:00:36.313259673 0x7791ea60 gstbin.c:3739:gst_bin_handle_message_func:<audio-stream> posting message upward
D/GStreamer+GST_BUS( 1840): 0:00:36.313520610 0x7791ea60 gstbus.c:310:gst_bus_post:<bus1> [msg 0x77969378] posting on bus warning message: 0x77969378, time 99:99:99.999999999, seq-num 170, element 'source', GstMessageWarning, gerror=(GError)NULL, debug=(string)"gstaudiobasesrc.c\(863\):\ gst_audio_base_src_create\ \(\):\ /GstPipeline:audio-stream/GstOpenSLESSrc:source:\012Dropped\ 146240\ samples.\ This\ is\ most\ likely\ because\ downstream\ can\'t\ keep\ up\ and\ is\ consuming\ samples\ too\ slowly.";
D/GStreamer+GST_BUS( 1840): 0:00:36.313639360 0x7791ea60 gstbus.c:345:gst_bus_post:<bus1> [msg 0x77969378] pushing on async queue
D/GStreamer+GST_BUS( 1840): 0:00:36.314059360 0x75a72380 gstbus.c:504:gst_bus_timed_pop_filtered:<bus1> got message 0x77969378, warning from source, type mask is 4294967295
D/GStreamer+GST_BUS( 1840): 0:00:36.314367590 0x75a72380 gstbus.c:771:gst_bus_source_dispatch:<bus1> source 0x778d1af8 calling dispatch with warning message: 0x77969378, time 99:99:99.999999999, seq-num 170, element 'source', GstMessageWarning, gerror=(GError)NULL, debug=(string)"gstaudiobasesrc.c\(863\):\ gst_audio_base_src_create\ \(\):\ /GstPipeline:audio-stream/GstOpenSLESSrc:source:\012Dropped\ 146240\ samples.\ This\ is\ most\ likely\ because\ downstream\ can\'t\ keep\ up\ and\ is\ consuming\ samples\ too\ slowly.";
I/GLib+stdout( 1840): network : gstreamer : DEFAULT : Element source : warning message