a/v freeze while flushing audio chain of pipeline in running state (clock and renderer sync related)

Thu Jun 1 17:10:36 UTC 2017

Please note that flush stop is passed with False so that the clock timing
is not reset purposely as thereafter buffer with valid timestamp of
different language is pushed. What could trigger queue thread to block /
wait inside video renderer basesink from audio sink pulse audio. The test
is running on x86 with gstreamer 1.4.5. Suggestion/pointer will be very
helpful as there is not much clue from traces to establish design
relationship between audio and video sinks and blocking wait.
Thanks for ur help
Best Regards

On Jun 1, 2017 10:14 AM, "Nitin Mahajan" <rise.era at gmail.com> wrote:

> some updates,
> the hang is blocking wait inside gst_system_clock_id_wait_
> jitter_unlocked().
> the blocking calls is on gst_poll_wait ().
> it seems that the audio sink thread (pulse audio) is related to this wait.
> the gstreamer pipeline is full of buffers. Video rendering is in blocking
> wait.
> The buffer carries a valid PTS value.
> what could have gone wrong by flushing the audio chain which causes video
> chain to block on waiting ?
> thanks to share your opinion and ideas to help further debugging.
> BR
> Nitin
>
> On Wed, May 31, 2017 at 5:28 PM, Nitin Mahajan <nitin.mahajan78 at gmail.com>
> wrote:
>
>> Hello folks,
>>
>> I'm observing a/v freeze (gstreamer 1.4.5).
>> sequence of operations:
>> - a/v playback ongoing (pipeline state is in PLAYING)
>>
>> On audio src pad of demux:
>> - push gst_event_new_flush_start()
>> - push gst_event_new_flush_stop(FALSE)
>> - push new segment event
>> - push buffers
>>
>> A/V freeze (random)
>> the idea is to flush gstreamer pipeline for the audio chain before
>> pushing buffers of different language of same codec.
>>
>> It seems that the pipeline is blocked on basesink for video chain.
>> The clock ID object for video renderer suggests,
>> gst_system_clock_id_wait_jitter_unlocked() named GstPulseSinkClock
>> (gdb) p *clock
>> $72 =
>>
>> {
>>  object =
>>  {
>>      object = {g_type_instance = {g_class = 0xac707c58}, ref_count = 46,
>> qdata = 0x0}, lock = {p = 0xac709f70, i = {2893062000, 0}},
>>      name = 0xac705520 "GstPulseSinkClock",
>>      parent = 0x0,
>>      flags = 752,
>>      control_bindings = 0x0,
>>      control_rate = 100000000,
>>      last_sync = 18446744073709551615,
>>      _gst_reserved = 0x0
>>  },
>>  priv = 0xad167828,
>>  _gst_reserved = {0x0, 0x0, 0x0, 0x0}
>>  }
>>
>> So far not able to make out how clock management and sync with renderer
>> is taking place.
>> But below two threads seem related as it semms that video renderer is
>> polling for some event from audio renderer ?
>> ANy suggestion will be more that helpful
>>
>> Thread
>> #0  0xb7fdd428 in __kernel_vsyscall ()
>> #1  0xb7ab5108 in __GI_ppoll (fds=0x9fe12c48, nfds=1, timeout=0xa07fe1d8,
>> sigmask=sigmask at entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:56
>> #2  0xb7d76f29 in ppoll (__ss=0x0, __timeout=<optimized out>,
>> __nfds=<optimized out>, __fds=<optimized out>) at
>> /usr/include/i386-linux-gnu/bits/poll2.h:77
>> #3  gst_poll_wait (set=0xac703c58, timeout=23516000) at gstpoll.c:1248
>> #4  0xb7d8d76d in gst_system_clock_id_wait_jitter_unlocked
>> (clock=0xad167890, entry=0xac731948, jitter=0xa07fe650, restart=1) at
>> gstsystemclock.c:684
>> #5  0xb7d3c1aa in gst_clock_id_wait (id=0xac731948, jitter=jitter at entry
>> =0xa07fe650) at gstclock.c:539
>> #6  0xb77f1930 in gst_base_sink_wait_clock (sink=sink at entry=0xadc0cfd8,
>> time=<optimized out>, jitter=jitter at entry=0xa07fe650) at
>> gstbasesink.c:2104
>> #7  0xb77f3317 in gst_base_sink_do_sync (basesink=basesink at entry=0xadc0cfd8,
>> obj=obj at entry=0x9fe18360, late=late at entry=0xa07fe7d8,
>> step_end=step_end at entry=0xa07fe7dc) at gstbasesink.c:2491
>> #8  0xb77f484e in gst_base_sink_chain_unlocked (basesink=basesink at entry
>> =0xadc0cfd8, obj=obj at entry=0x9fe18360, is_list=is_list at entry=0,
>> pad=<optimized out>) at gstbasesink.c:3390
>> #9  0xb77f69a8 in gst_base_sink_chain_main (basesink=0xadc0cfd8,
>> pad=<optimized out>, obj=0x9fe18360, is_list=0) at gstbasesink.c:3538
>> #10 0xb7fb8a05 in gst_validate_pad_monitor_chain_func (pad=0xad166500,
>> parent=0xadc0cfd8, buffer=0x9fe18360) at gst-validate-pad-monitor.c:1509
>> #11 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9fe18360,
>> type=<optimized out>, pad=0xad166500) at gstpad.c:3830
>> #12 gst_pad_push_data (pad=0xac727578, type=type at entry=4112,
>> data=0x9fe18360) at gstpad.c:4063
>> #13 0xb7d6a45e in gst_pad_push (pad=0x9fe18360, pad at entry=0xac727578,
>> buffer=buffer at entry=0x9fe18360) at gstpad.c:4174
>> #14 0xb7d520c2 in gst_proxy_pad_chain_default (pad=0xac730090,
>> parent=0xac727578, buffer=0x9fe18360) at gstghostpad.c:126
>> #15 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9fe18360,
>> type=<optimized out>, pad=0xac730090) at gstpad.c:3830
>> #16 gst_pad_push_data (pad=0xac70ac50, type=type at entry=4112,
>> data=0x9fe18360) at gstpad.c:4063
>> #17 0xb7d6a45e in gst_pad_push (pad=0x9fe18360, buffer=0x9fe18360) at
>> gstpad.c:4174
>> #18 0xb7807127 in gst_base_transform_chain (pad=0xac70ad88,
>> parent=0xac75c788, buffer=0x9e9a7d48) at gstbasetransform.c:2260
>> #19 0xb7fb8a05 in gst_validate_pad_monitor_chain_func (pad=0xac70ad88,
>> parent=0xac75c788, buffer=0x9e9a7d48) at gst-validate-pad-monitor.c:1509
>> #20 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9e9a7d48,
>> type=<optimized out>, pad=0xac70ad88) at gstpad.c:3830
>> #21 gst_pad_push_data (pad=0xac70a8a8, type=type at entry=4112,
>> data=0x9e9a7d48) at gstpad.c:4063
>> #22 0xb7d6a45e in gst_pad_push (pad=0x9e9a7d48, buffer=0x9e9a7d48) at
>> gstpad.c:4174
>> #23 0xb7807127 in gst_base_transform_chain (pad=0xac70a770,
>> parent=0xac735588, buffer=0x9e9a7d48) at gstbasetransform.c:2260
>> #24 0xb7fb8a05 in gst_validate_pad_monitor_chain_func (pad=0xac70a770,
>> parent=0xac735588, buffer=0x9e9a7d48) at gst-validate-pad-monitor.c:1509
>> #25 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9e9a7d48,
>> type=<optimized out>, pad=0xac70a770) at gstpad.c:3830
>> #26 gst_pad_push_data (pad=0xac75f290, type=type at entry=4112,
>> data=0x9e9a7d48) at gstpad.c:4063
>> #27 0xb7d6a45e in gst_pad_push (pad=0x9e9a7d48, buffer=0x9e9a7d48) at
>> gstpad.c:4174
>> #28 0xb7807127 in gst_base_transform_chain (pad=0xac75f158,
>> parent=0x818d058, buffer=0x9e9a7d48) at gstbasetransform.c:2260
>> #29 0xb7fb8a05 in gst_validate_pad_monitor_chain_func (pad=0xac75f158,
>> parent=0x818d058, buffer=0x9e9a7d48) at gst-validate-pad-monitor.c:1509
>> #30 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9e9a7d48,
>> type=<optimized out>, pad=0xac75f158) at gstpad.c:3830
>> #31 gst_pad_push_data (pad=0xac75f020, type=type at entry=4112,
>> data=0x9e9a7d48) at gstpad.c:4063
>> #32 0xb7d6a45e in gst_pad_push (pad=0x9e9a7d48, buffer=0x9e9a7d48) at
>> gstpad.c:4174
>> #33 0xb7807127 in gst_base_transform_chain (pad=0xac70aec0,
>> parent=0xac75c490, buffer=0x9e9a7d48) at gstbasetransform.c:2260
>> #34 0xb7fb8a05 in gst_validate_pad_monitor_chain_func (pad=0xac70aec0,
>> parent=0xac75c490, buffer=0x9e9a7d48) at gst-validate-pad-monitor.c:1509
>> #35 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9e9a7d48,
>> type=<optimized out>, pad=0xac70aec0) at gstpad.c:3830
>> #36 gst_pad_push_data (pad=0xadc32e78, type=type at entry=4112,
>> data=0x9e9a7d48) at gstpad.c:4063
>> #37 0xb7d6a45e in gst_pad_push (pad=0x9e9a7d48, pad at entry=0xadc32e78,
>> buffer=buffer at entry=0x9e9a7d48) at gstpad.c:4174
>> #38 0xb7d520c2 in gst_proxy_pad_chain_default (pad=0xac727428,
>> parent=0x8191d10, buffer=0x9e9a7d48) at gstghostpad.c:126
>> #39 0xb7d62c3a in gst_pad_chain_data_unchecked (data=0x9e9a7d48,
>> type=<optimized out>, pad=0xac727428) at gstpad.c:3830
>> ---Type <return> to continue, or q <return> to quit---
>> #40 gst_pad_push_data (pad=0xac70a3c8, type=type at entry=4112,
>> data=0x9e9a7d48) at gstpad.c:4063
>> #41 0xb7d6a45e in gst_pad_push (pad=0x9e9a7d48, buffer=buffer at entry
>> =0x9e9a7d48) at gstpad.c:4174
>> #42 0xb60dfb67 in gst_queue_push_one (queue=0xac72c090) at gstqueue.c:1169
>> #43 gst_queue_loop (pad=0xac70a3c8) at gstqueue.c:1298
>> #44 0xb7d947c9 in gst_task_func (task=task at entry=0xad19f588) at
>> gsttask.c:316
>> #45 0xb7d957ef in default_func (tdata=0xac75e980, pool=0x8057470) at
>> gsttaskpool.c:68
>> #46 0xb7c11405 in ?? () from /lib/i386-linux-gnu/libglib-2.0.so.0
>> #47 0xb7c109aa in ?? () from /lib/i386-linux-gnu/libglib-2.0.so.0
>> #48 0xb7b8df72 in start_thread (arg=0xa07ffb40) at pthread_create.c:312
>> #49 0xb7ac3f8e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
>>
>> Thread
>> #0  0xb7fdd428 in __kernel_vsyscall ()
>> #1  0xb7ab501b in poll () at ../sysdeps/unix/syscall-template.S:81
>> #2  0xac6e5bbd in poll (__timeout=1500, __nfds=2, __fds=0xa6c02d68) at
>> /usr/include/i386-linux-gnu/bits/poll2.h:46
>> #3  poll_func (ufds=0xa6c02d68, nfds=2, timeout=1500,
>> userdata=0xac70b508) at pulse/thread-mainloop.c:69
>> #4  0xac6d44ee in pa_mainloop_poll (m=m at entry=0xac70b460) at
>> pulse/mainloop.c:850
>> #5  0xac6d4d1d in pa_mainloop_iterate (m=m at entry=0xac70b460,
>> block=block at entry=1, retval=retval at entry=0x0) at pulse/mainloop.c:932
>> #6  0xac6d4df4 in pa_mainloop_run (m=0xac70b460, retval=retval at entry=0x0)
>> at pulse/mainloop.c:950
>> #7  0xac6e5b5c in thread (userdata=0xac705660) at
>> pulse/thread-mainloop.c:88
>> #8  0xac68e4dd in internal_thread_func (userdata=0xac70b598) at
>> pulsecore/thread-posix.c:83
>> #9  0xb7b8df72 in start_thread (arg=0xa753eb40) at pthread_create.c:312
>> #10 0xb7ac3f8e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
>>
>> _______________________________________________
>> gstreamer-devel mailing list
>> gstreamer-devel at lists.freedesktop.org
>> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20170601/b3e5bcf6/attachment-0001.html>