GNOME Bugzilla – Bug 597550
basesrc: sometimes no buffers produced after PLAYING - PAUSED - PLAYING
Last modified: 2009-10-15 14:35:30 UTC
Created attachment 144887 [details] basesrc-state-test.c test app I have test app that runs "videotestsrc is-live=true ! fakesink async=false" pipeline and occasionally sets it to PAUSED and back to PLAYING. The problem is sometimes videotestsrc fails to produce buffers after state change to PLAYING. The steps leading to this problem seem to be: 1. videotestsrc loop task is waiting for clock 2. state change to PAUSED happens and clock is unscheduled 3. state change to PLAYING happens (loop task thread has not been executed, it is still waiting for clock!) 4. gst_basesrc_do_sync returns with gst_clock_unscheduled return value and loop task returns wrong-state error, videotestsrc task is paused and no buffers are produced Snippet from log with GST_DEBUG=*:2,GST_STATES:3,basesrc:5 ./basesrc-state-test 0:00:03.052952337 10802 0x90087d8 LOG basesrc gstbasesrc.c:1832:gst_base_src_do_sync:<videotestsrc0> waiting for clock, base time 150:29:02.746874029, stream _start 0:00:03.034358924 0:00:03.056341978 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<fakesink0> completed state change to PAUSED 0:00:03.056367508 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<fakesink0> posting state-changed PLAYING to PAUSED 0:00:03.056403187 10802 0x8f19008 INFO GST_STATES gstbin.c:2343:gst_bin_change_state_func:<pipe> child 'fakesink0' changed state to 3(PAUSED) successfully 0:00:03.056429202 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2883:gst_base_src_change_state:<videotestsrc0> PLAYING->PAUSED 0:00:03.056449043 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2679:gst_base_src_set_playing:<videotestsrc0> unlock 0:00:03.056467205 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2688:gst_base_src_set_playing:<videotestsrc0> unschedule clock 0:00:03.056505042 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2695:gst_base_src_set_playing:<videotestsrc0> live running 0 0:00:03.056525391 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<videotestsrc0> completed state change to PAUSED 0:00:03.056545301 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<videotestsrc0> posting state-changed PLAYING to PAUSED 0:00:03.056573966 10802 0x8f19008 INFO GST_STATES gstbin.c:2364:gst_bin_change_state_func:<pipe> child 'videotestsrc0' changed state to 3(PAUSED) successfully wi thout preroll 0:00:03.056604961 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<pipe> completed state change to PAUSED 0:00:03.056618581 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<pipe> posting state-changed PLAYING to PAUSED 0:00:03.056658231 10802 0x8f19008 LOG basesrc gstbasesrc.c:604:gst_base_src_query_latency:<videotestsrc0> latency: live 1, min 0:00:00.000000000, max 99:99:9 9.999999999 0:00:03.056674294 10802 0x8f19008 LOG basesrc gstbasesrc.c:924:gst_base_src_default_query:<videotestsrc0> report latency: live 1, min 0:00:00.000000000, max 99:99:99.999999999 0:00:03.056690237 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:976:gst_base_src_default_query:<videotestsrc0> query latency returns 1 0:00:03.056732534 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<fakesink0> completed state change to PLAYING 0:00:03.056747548 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<fakesink0> posting state-changed PAUSED to PLAYING 0:00:03.056766845 10802 0x8f19008 INFO GST_STATES gstbin.c:2343:gst_bin_change_state_func:<pipe> child 'fakesink0' changed state to 4(PLAYING) successfully 0:00:03.056783529 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2866:gst_base_src_change_state:<videotestsrc0> PAUSED->PLAYING 0:00:03.056805585 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2688:gst_base_src_set_playing:<videotestsrc0> unschedule clock 0:00:03.056818438 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2695:gst_base_src_set_playing:<videotestsrc0> live running 1 0:00:03.056830351 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2702:gst_base_src_set_playing:<videotestsrc0> unlock stop 0:00:03.056843618 10802 0x8f19008 DEBUG basesrc gstbasesrc.c:2716:gst_base_src_set_playing:<videotestsrc0> signal 0:00:03.056856144 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<videotestsrc0> completed state change to PLAYING 0:00:03.056869260 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<videotestsrc0> posting state-changed PAUSED to PLAYING 0:00:03.056888064 10802 0x8f19008 INFO GST_STATES gstbin.c:2343:gst_bin_change_state_func:<pipe> child 'videotestsrc0' changed state to 4(PLAYING) successfully 0:00:03.056904879 10802 0x8f19008 INFO GST_STATES gstelement.c:2237:gst_element_continue_state:<pipe> completed state change to PLAYING 0:00:03.056918018 10802 0x8f19008 INFO GST_STATES gstelement.c:2250:gst_element_continue_state:<pipe> posting state-changed PAUSED to PLAYING 0:00:03.056970724 10802 0x90087d8 LOG basesrc gstbasesrc.c:1837:gst_base_src_do_sync:<videotestsrc0> clock entry done: 2 0:00:03.056985178 10802 0x90087d8 DEBUG basesrc gstbasesrc.c:2018:gst_base_src_get_range:<videotestsrc0> clock was unscheduled (2), returning WRONG_STATE 0:00:03.057000212 10802 0x90087d8 INFO basesrc gstbasesrc.c:2218:gst_base_src_loop:<videotestsrc0> pausing after gst_base_src_get_range() = wrong-state 0:00:03.057013377 10802 0x90087d8 DEBUG basesrc gstbasesrc.c:2352:gst_base_src_loop:<videotestsrc0> pausing task, reason wrong-state
Yes, maybe basesrc should ignore in the task function, if the clock was unscheduled.
commit e9f2714ff946b3260439d981747b2159dcc4e00a Author: Wim Taymans <wim.taymans@collabora.co.uk> Date: Thu Oct 15 16:30:36 2009 +0200 basesrc: fix race in PLAYING->PAUSED->PLAYING When we quickly switch from PLAYING to PAUSED and back to PLAYING it's possible in some cases that the task refuses to start, This is because when we go to PAUSED, we unschedule the clock timeout, which could return UNSCHEDULED when we're back to PLAYING, causing the task to PAUSE again with a wrong-state. This patch checks if we are running when we return with an UNSCHEDULED return value and if we are, try to create a new buffer. Fixes #597550