GStreamer-devel

Sequence of play->pause->play->pause blocks pipeline after a while

classic Classic list List threaded Threaded
♦
♦
 3 messages Options
franchan
Reply | Threaded
Open this post in threaded view
♦
♦
|

Sequence of play->pause->play->pause blocks pipeline after a while

franchan
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

------------------------------------------------------------------------------
The NEW KODAK i700 Series Scanners deliver under ANY circumstances! Your
production scanning environment may not be a perfect world - but thanks to
Kodak, there's a perfect scanner to get the job done! With the NEW KODAK i700
Series Scanner you'll get full speed at 300 dpi even with all image
processing features enabled. http://p.sf.net/sfu/kodak-com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gstreamer-devel
franchan
Reply | Threaded
Open this post in threaded view
♦
♦
|

Re: Sequence of play->pause->play->pause blocks pipeline after a while

franchan
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 <[hidden email]> 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
>

------------------------------------------------------------------------------
The NEW KODAK i700 Series Scanners deliver under ANY circumstances! Your
production scanning environment may not be a perfect world - but thanks to
Kodak, there's a perfect scanner to get the job done! With the NEW KODAK i700
Series Scanner you'll get full speed at 300 dpi even with all image
processing features enabled. http://p.sf.net/sfu/kodak-com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gstreamer-devel
sledge hammer
Reply | Threaded
Open this post in threaded view
♦
♦
|

Re: Sequence of play->pause->play->pause blocks pipeline after a while

sledge hammer
I think the pause state is the same state as play. But in play the clock doesn't run. I think data can be requested/given but not make the clock run.

> Date: Thu, 14 May 2009 15:26:40 +0200
> From: [hidden email]
> To: [hidden email]
> Subject: Re: [gst-devel] Sequence of play->pause->play->pause blocks pipeline after a while
>
> 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

Σύρετε φωτογραφίες στο παράθυρο του Messenger. Δείτε πώς. Κάντε κλικ εδώ!
------------------------------------------------------------------------------
The NEW KODAK i700 Series Scanners deliver under ANY circumstances! Your
production scanning environment may not be a perfect world - but thanks to
Kodak, there's a perfect scanner to get the job done! With the NEW KODAK i700
Series Scanner you'll get full speed at 300 dpi even with all image
processing features enabled. http://p.sf.net/sfu/kodak-com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/gstreamer-devel
Free forum by Nabble Edit this page