So I tried to figure out why exactly one of the sinks didn't preroll, here are my findings:
sample:
https://dl.dropboxus...38760017/bb.avi
picture of pipeline:
https://dl.dropboxus...17/pipeline.png
debug output:
https://dl.dropboxus...bug_nocolor.log
unsuccessfull unpause - lines 58106-58146
gdb output when going successfully to paused state:
http://pastebin.com/vV45iYL5
6.thread - pulling from aqueue pushing to dvbaudiosink
5.thread - pulling from vqueue pushing to dvbvideosink
4.thread - pulling from multiqueue ..pushing to aqueue
3.thread - pulling from multiqueue ..pushing to vqueue
2.thread - ..pushing from avidemux to multiqueue
(6,5) sinks have prerolled buffer, and are waiting for change state to playing, which will unlock both chains
(3,4) vqueue and aqueue are filled and threads are waiting for space in these queues to push next buffers to them
2 multiqueue is filled(probably video part), 2.thread is waiting for space in multiqueue to push buffers from avidemux
gdb output when going un-successfully to paused state:
http://pastebin.com/PXuq78Q4
6. audiosink is not prerolled and is waiting for buffer from empty aqueue
5. videosink is prerolled and is blocking video chain
4. aqueue is empty and is waiting for buffer from multiqueue which is also empty(audio part)
3. vqueue is filled as is multiqueue(videopart)
2. avidemux wants to push video buffer to multiqueue(video part) which is filled(avidemux pushes audio/video buffers sequentially at least that's how it looks like from log)
So avidemux wants to push video buffer to multiqueue(video part) which is filled and cannot be freed, since video chain is blocked by videosink -> we cannot refill empty multiqueue(audio part), so audiosink will wait indefinitely for preroll buffer
Why is it happening?
We have unbalanced flow of audio/video buffers, because of async setting and different size of video/audio buffers.
So video buffers will fill much faster video hw buffer then audio buffers will fill hw audio buffer (hw buffers have same size)?
For example on unsuccessfull unpause, we just pushed to dvbaudiosink buffer with 1:28 and videosink has time only 1:08:
0:04:48.608164902 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:2539:gst_base_sink_do_sync:<dvbaudiosink0> possibly waiting for clock to reach 0:01:28.440000000, adjusted 0:01:28.440000000
0:04:48.608731680 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:2167:gst_base_sink_wait_clock:<dvbaudiosink0> sync disabled
0:04:48.609026346 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:2546:gst_base_sink_do_sync:<dvbaudiosink0> clock returned 4, jitter 0:00:00.000000000
0:04:48.609512383 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:3501:gst_base_sink_chain_unlocked:<dvbaudiosink0> rendering object 0x76bc5a88
0:04:48.610206865 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:946:gst_base_sink_set_last_buffer_unlocked:<dvbaudiosink0> setting last buffer to 0x76bc5a88
0:04:48.611024420 ^[[334m 2283 0x5118c0 DEBUG basesink gstbasesink.c:3547:gst_base_sink_chain_unlocked:<dvbaudiosink0> object unref after render 0x76bc5a88
0:04:48.775547457 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:5113:gst_base_sink_change_state:<dvbaudiosink0> PLAYING to PAUSED
0:04:48.775965605 ^[[334m 2283 0x76004520 DEBUG dvbaudiosink gstdvbaudiosink.c:346:gst_dvbaudiosink_unlock:<dvbaudiosink0> unlock
0:04:48.776222013 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:5122:gst_base_sink_change_state:<dvbaudiosink0> got preroll lock
0:04:48.777494568 ^[[334m 2283 0x76004520 DEBUG dvbaudiosink gstdvbaudiosink.c:354:gst_dvbaudiosink_unlock_stop:<dvbaudiosink0> unlock_stop
0:04:48.777794309 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:3313:gst_base_sink_needs_preroll:<dvbaudiosink0> have_preroll: 0, EOS: 0 => needs preroll: 1
0:04:48.778528531 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:5144:gst_base_sink_change_state:<dvbaudiosink0> PLAYING to PAUSED, we are not prerolled
0:04:48.778817161 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:5150:gst_base_sink_change_state:<dvbaudiosink0> doing async state change
0:04:48.779243976 ^[[334m 2283 0x76004520 DEBUG basesink gstbasesink.c:5158:gst_base_sink_change_state:<dvbaudiosink0> rendered: 5, dropped: 0
0:04:48.779725791 ^[[334m 2283 0x76004520 DEBUG dvbaudiosink gstdvbaudiosink.c:1540:gst_dvbaudiosink_change_state:<dvbaudiosink0> GST_STATE_CHANGE_PLAYING_TO_PAUSED
0:04:48.832513642 ^[[334m 2283 0x42db50 DEBUG basesink gstbasesink.c:3547:gst_base_sink_chain_unlocked:<dvbvideosink0> object unref after render 0x76b9d148
0:04:48.833314346 ^[[334m 2283 0x42db50 DEBUG basesink gstbasesink.c:3401:gst_base_sink_chain_unlocked:<dvbvideosink0> got times start: 0:01:08.680000000, end: 0:01:08.720000000
Eventually video hw buffer is filled and will start to block render in video-sink, which will cause quick filling of multiqueue(video part), while audio hw buffer is still not filled, which means that aqueue and multiqueue(audio part) is most of the time drained.
Now it's just matter of coincidence if we pause at the moment when avidemux tries to push video buffer to multiqueue(video part) when it's filled(video hw buffer is filled and is blocking) and multiqueue(audio part) is empty.
This is how I understand it.
Solution?
1. We can as suggested remove waiting for preroll, so video chain will not block. Problem is that drivers(at least vusolose) don't like when A/V buffers are far apart(picture freezed, while audio is playing). This is problem on start of playback(confirmed) or after flushing seek which will clear hw buffers(not happened yet). So this could be improved by doing initial wait for preroll when going from NULL to PAUSED and then turn it off, with this solution I didn't encouter any problems yet.
2. We can wait for preroll as it is right now, and treat this situation as special case in servicemp3. When audiosink cannot get it's preroll buffer, we will just unpause videoSink which will unlock videochain, so audio buffers can flow to multiqueue(audio-part) and audiosink will preroll. Currently I'm testing this solution and it looks to be working..
3. Probably the best solution would be to always wait for preroll buffer when we have clear hw buffers - on initial startup and on flushing seek. And not to wait for preroll when we are doing pause/unpause, since we are already prerolled in hw buffers.
4. ?
How to reproduce
download sample, play sample with gst-player, after ~10 seconds of playback(to fill hw buffers) start quickly pushing "space" which will pause/unpause pipeline, until you cannot unpause anymore..
Edited by mx3L, 10 September 2015 - 23:11.