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

Wed Jun 7 15:02:12 UTC 2017

Hello experts,
Kindly suggest what could be the possible scenario in which
gst_system_clock_id_wait_jitter_unlocked gets blocked in basesink.
Thanks
Nitin

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

> 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_jitte
>> r_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/i38
>>> 6/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/i38
>>> 6/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/20170607/17d614c2/attachment.html>