[gst-devel] Sequence of play->pause->play->pause blocks pipeline after a while

Thu May 14 15:26:40 CEST 2009

Replying  on my own question,

(my posted first "good" trance log came actually from doing a
pause->play, sorry)

My trouble seems to come from xv-sink doing an async play->pause state.
It wants to preroll with some data first before going into pause.
Now I wonder, as the other elements (decoder/demux) are in the pause state,
how will that give the xv-sink its data for prerolling?
Does that helps somebody to give me a clue?

(I will put the producer of data for the appsrc to sleep after
putting gstreamer pipeline to pause.)

Thanks,
francis

On Thu, May 14, 2009 at 1:28 PM, franchan <francis.meyvis at gmail.com> wrote:
> Hello,
>
> I use the playbin2 based pipeline with a appsrc as its source.
> I see that after a number of sequence of a setting the state from play to pause
> (to play again ...), my pipeline gets blocked.
> After investigating, I noticed that I never receive the final 'PAUSED' event,
> neither on the async. bus nor on the sync.bus.
> If I enable less GST debugging it occurs almost after the second or
> third set_state(pause).
> If I enable more GST debugging
> (trying to understand from the traces why there's no PAUSED event)
> I notice that I can repeat the sequence around 7 or more times.
> Anyone having an idea what might cause this trouble?
>
> There is some difference in the traces between a sequence that does
> not block in the wait,
> These are the last elements that put their state change messages:
> typefind, decodebin20, source, uridecodebin0, playbin
> -> in a case of blocking, I never receive this state change message
> from the playbin element.
>
> In the trances below "0x9148228" is the name of this playbin2.
>
> In a failed case I see this traces:
> 0:00:24.670419368 24786  0x8e64038 DEBUG           GST_STATES
> gstbin.c:2452:gst_bin_change_state_func:<0x9148228> done changing
> bin's state from PLAYING to PAUSED, now in PLAYING, ret ASYNC
> ...
> 0:00:24.670503674 24786  0x8e64038 DEBUG           GST_STATES
> gstelement.c:2443:gst_element_change_state:<0x9148228> element will
> change state ASYNC
> 0:00:24.670517082 24786  0x8e64038 DEBUG           GST_STATES
> gstelement.c:2382:gst_element_set_state_func:<0x9148228> returned
> ASYNC
> And nothing is traced about a post on the bus that the transition is complete.
> Why would it log that the transition is completed from PLAYING to
> PAUSED but "now in PLAYING return ASYNC" ?
>
> This are traces from a successful transition:
> 0:00:23.454835541 24786 0xa7941018 DEBUG           GST_STATES
> gstelement.c:2382:gst_element_set_state_func:<uridecodebin0> returned
> SUCCESS
> 0:00:23.454849781 24786 0xa7941018 INFO            GST_STATES
> gstbin.c:2355:gst_bin_change_state_func:<0x9148228> child
> 'uridecodebin0' changed state to 4(PLAYING) successfully
> 0:00:23.454864708 24786 0xa7941018 DEBUG                  bin
> gstbin.c:1888:gst_bin_sort_iterator_next:<0x9148228> queue empty,
> elements exhausted
> 0:00:23.454877579 24786 0xa7941018 DEBUG           GST_STATES
> gstbin.c:2392:gst_bin_change_state_func: iterator done
> 0:00:23.454890545 24786 0xa7941018 DEBUG                  bin
> gstbin.c:1927:gst_bin_sort_iterator_free:<0x9148228> free
> 0:00:23.454905389 24786 0xa7941018 DEBUG                  bin
> gstbin.c:2419:gst_bin_change_state_func:<0x9148228> no async elements
> 0:00:23.454918967 24786 0xa7941018 DEBUG           GST_STATES
> gstbin.c:2452:gst_bin_change_state_func:<0x9148228> done changing
> bin's state from PAUSED to PLAYING, now in PAUSED, ret SUCCESS
> 0:00:23.454933812 24786 0xa7941018 DEBUG           GST_STATES
> gstelement.c:2461:gst_element_change_state:<0x9148228> element changed
> state SUCCESS
> 0:00:23.454947262 24786 0xa7941018 INFO            GST_STATES
> gstelement.c:2150:gst_element_continue_state:<0x9148228> completed
> state change to PLAYING
> 0:00:23.454960743 24786 0xa7941018 INFO            GST_STATES
> gstelement.c:2163:gst_element_continue_state:<0x9148228> posting
> state-changed PAUSED to PLAYING
> 0:00:23.454979452 24786 0xa7941018 DEBUG              GST_BUS
> gstbus.c:378:gst_bus_post:<bus1> [msg 0x918bca0] posting on bus, type
> state-changed, GstMessageState, old-state=(GstState)GST_STATE_PAUSED,
> new-state=(Gs
> tState)GST_STATE_PLAYING,
> pending-state=(GstState)GST_STATE_VOID_PENDING; from source
> <0x9148228>
> 0:00:23.455030482 24786 0xa7941018 DEBUG              GST_BUS
> gstbus.c:408:gst_bus_post:<bus1> [msg 0x918bca0] pushing on async
> queue
> 0:00:23.455049002 24786 0xa7941018 DEBUG              GST_BUS
> gstbus.c:413:gst_bus_post:<bus1> [msg 0x918bca0] pushed on async queue
> 0:00:23.455074283 24786  0x8f96350 DEBUG              GST_BUS
> gstbus.c:569:gst_bus_timed_pop_filtered:<bus1> got message 0x918bca0,
> state-changed, type mask is 4294967295
> 0:00:23.455089285 24786  0x8f96350 DEBUG              GST_BUS
> gstbus.c:829:gst_bus_source_dispatch:<bus1> source 0x9167d80 calling
> dispatch with 0x918bca0
> 0:00:23.455156310 24786  0x8f96350 DEBUG              GST_BUS
> gstbus.c:834:gst_bus_source_dispatch:<bus1> source 0x9167d80 handler
> returns 1
> 0:00:23.455292654 24786 0xa7941018 DEBUG           GST_STATES
> gstelement.c:2382:gst_element_set_state_func:<0x9148228> returned
> SUCCESS
>
> And these are traces from an unsuccessful transition:
> 0:00:24.670311575 24786  0x8e64038 DEBUG           GST_STATES
> gstelement.c:2382:gst_element_set_state_func:<uridecodebin0> returned
> SUCCESS
> 0:00:24.670325593 24786  0x8e64038 INFO            GST_STATES
> gstbin.c:2355:gst_bin_change_state_func:<0x9148228> child
> 'uridecodebin0' changed state to 3(PAUSED) successfully
> 0:00:24.670340189 24786  0x8e64038 DEBUG                  bin
> gstbin.c:1888:gst_bin_sort_iterator_next:<0x9148228> queue empty,
> elements exhausted
> 0:00:24.670362613 24786  0x8e64038 DEBUG           GST_STATES
> gstbin.c:2392:gst_bin_change_state_func: iterator done
> 0:00:24.670375634 24786  0x8e64038 DEBUG                  bin
> gstbin.c:1927:gst_bin_sort_iterator_free:<0x9148228> free
> 0:00:24.670389603 24786  0x8e64038 DEBUG                  bin
> gstbin.c:2430:gst_bin_change_state_func:<0x9148228> check async
> elements
> 0:00:24.670404929 24786  0x8e64038 DEBUG                  bin
> gstbin.c:825:find_message:<0x9148228> we found a message 0x919d6c0
> from playsink0 matching types 00100000
> 0:00:24.670419368 24786  0x8e64038 DEBUG           GST_STATES
> gstbin.c:2452:gst_bin_change_state_func:<0x9148228> done changing
> bin's state from PLAYING to PAUSED, now in PLAYING, ret ASYNC
> 0:00:24.670442062 24786  0x8e64038 DEBUG        baseaudiosink
> gstbaseaudiosink.c:459:gst_base_audio_sink_get_time:<alsa-sink>
> processed samples: raw 344064, delay 0, real 344064, time
> 0:00:07.168000000
> 0:00:24.670458605 24786  0x8e64038 DEBUG            GST_CLOCK
> gstclock.c:851:gst_clock_get_internal_time:<GstAudioSinkClock>
> internal time 0:00:07.168000000
> 0:00:24.670473593 24786  0x8e64038 DEBUG            GST_CLOCK
> gstclock.c:892:gst_clock_get_time:<GstAudioSinkClock> adjusted time
> 0:00:07.168000000
> 0:00:24.670487727 24786  0x8e64038 DEBUG             pipeline
> gstpipeline.c:503:gst_pipeline_change_state:<0x9148228>
> stream_time=0:00:07.168000000, now=0:00:07.168000000, base_time
> 0:00:00.000000000
> 0:00:24.670503674 24786  0x8e64038 DEBUG           GST_STATES
> gstelement.c:2443:gst_element_change_state:<0x9148228> element will
> change state ASYNC
> 0:00:24.670517082 24786  0x8e64038 DEBUG           GST_STATES
> gstelement.c:2382:gst_element_set_state_func:<0x9148228> returned
> ASYNC
>
>
> Thanks,
> francis
>