GNOME Bugzilla – Bug 685870
Regression with position when seeking beyond the media duration
Last modified: 2012-11-20 18:18:40 UTC
Created attachment 226165 [details] Test program I wrote this test program were we play, then pause, then seek a bit beyond the duration and query for the position. In 0.10, we always got the duration as position, meaning that we were at the end of the file, but in the case of 1.0, I am getting a position beyond the duration and it seems to be related to the start time that is used as "now" when calculating the position. Behavior in 0.10: 0:00:00.074659529 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4842:default_element_query:<audiosink-actual-sink-pulse> position query in format time 0:00:00.074661629 31570 0x1c33940 DEBUG basesink gstbasesink.c:3058:gst_base_sink_render_object:<videosink-actual-sink-xvimage> Got seqnum #323 0:00:00.074674555 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4763:gst_base_sink_get_position:<audiosink-actual-sink-pulse> position in wrong state, return -1 0:00:00.074685342 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4752:gst_base_sink_get_position:<audiosink-actual-sink-pulse> res: 0, POSITION: 99:99:99.999999999 0:00:00.074683863 31570 0x1c33940 DEBUG basesink gstbasesink.c:1544:gst_base_sink_configure_segment:<videosink-actual-sink-xvimage> configured NEWSEGMENT update 0, rate 1,000000, applied rate 1,000000, format GST_FORMAT_TIME, 0:00:06.060400000 -- 0:00:06.060400000, time 0:00:06.027200000, accum 0:00:00.000000000 0:00:00.074695647 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4947:default_element_query:<audiosink-actual-sink-pulse> query position returns 0 0:00:00.074702708 31570 0x1c33940 DEBUG basesink gstbasesink.c:3113:gst_base_sink_render_object:<videosink-actual-sink-xvimage> object unref after render 0x1bdaca0 0:00:00.074711505 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4842:default_element_query:<videosink-actual-sink-xvimage> position query in format time 0:00:00.074714631 31570 0x1c33940 DEBUG basesink gstbasesink.c:3284:gst_base_sink_queue_object_unlocked:<videosink-actual-sink-xvimage> rendering queued object 0x1c5fc50 0:00:00.074734465 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4647:gst_base_sink_get_position:<videosink-actual-sink-xvimage> in paused, using start time 0:00:00.000000000 0:00:00.074739790 31570 0x1c33940 DEBUG basesink gstbasesink.c:2612:gst_base_sink_do_sync:<videosink-actual-sink-xvimage> non syncable object 0x1c5fc50 0:00:00.074749390 31570 0x1c33940 DEBUG basesink gstbasesink.c:3044:gst_base_sink_render_object:<videosink-actual-sink-xvimage> rendering event 0x1c5fc50, type tag 0:00:00.074746778 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4739:gst_base_sink_get_position:<videosink-actual-sink-xvimage> now 0:00:00.000000000 - base 0:00:00.000000000 - accum 0:00:00.000000000 + time 0:00:06.027200000 last 99:99:99.999999999 0:00:00.074763177 31570 0x1c33940 DEBUG basesink gstbasesink.c:3058:gst_base_sink_render_object:<videosink-actual-sink-xvimage> Got seqnum #331 0:00:00.074768130 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4752:gst_base_sink_get_position:<videosink-actual-sink-xvimage> res: 1, POSITION: 0:00:06.027200000 0:00:00.074773907 31570 0x1c33940 DEBUG basesink gstbasesink.c:3113:gst_base_sink_render_object:<videosink-actual-sink-xvimage> object unref after render 0x1c5fc50 0:00:00.074781103 31570 0x1a3c0a0 DEBUG basesink gstbasesink.c:4947:default_element_query:<videosink-actual-sink-xvimage> query position returns 1 0:00:00.074784424 31570 0x1c33940 DEBUG basesink gstbasesink.c:3284:gst_base_sink_queue_object_unlocked:<videosink-actual-sink-xvimage> rendering queued object 0x1c5fca0 0:00:00.074793942 31570 0x1c33940 DEBUG basesink gstbasesink.c:2612:gst_base_sink_do_sync:<videosink-actual-sink-xvimage> non syncable object 0x1c5fca0 (test:31570): main-test-DEBUG: seeking finished, position: 6027200000 Regression: 0:00:00.179138977 30869 0x18c1560 DEBUG basesink gstbasesink.c:4452:default_element_query:<audiosink-actual-sink-pulse> position query in format time 0:00:00.179155432 30869 0x18c1560 DEBUG basesink gstbasesink.c:4269:gst_base_sink_get_position:<audiosink-actual-sink-pulse> in paused, using start time 0:00:00.000788000 0:00:00.179166459 30869 0x18c1560 DEBUG basesink gstbasesink.c:4361:gst_base_sink_get_position:<audiosink-actual-sink-pulse> now 0:00:00.000788000 - base_time 0:00:00.000000000 - base 0:00:00.000000000 + time 0:00:06.027200000 last 99:99:99.999999999 0:00:00.179180082 30869 0x18c1560 DEBUG basesink gstbasesink.c:4374:gst_base_sink_get_position:<audiosink-actual-sink-pulse> res: 1, POSITION: 0:00:06.027988000 0:00:00.179201959 30869 0x18c1560 DEBUG basesink gstbasesink.c:4558:default_element_query:<audiosink-actual-sink-pulse> query position returns 1 0:00:00.179231936 30869 0x18c1560 DEBUG basesink gstbasesink.c:4452:default_element_query:<videosink-actual-sink-ximage> position query in format time 0:00:00.179242193 30869 0x18c1560 DEBUG basesink gstbasesink.c:4269:gst_base_sink_get_position:<videosink-actual-sink-ximage> in paused, using start time 0:00:00.000788000 0:00:00.179251304 30869 0x18c1560 DEBUG basesink gstbasesink.c:4361:gst_base_sink_get_position:<videosink-actual-sink-ximage> now 0:00:00.000788000 - base_time 0:00:00.000000000 - base 0:00:00.000000000 + time 0:00:06.027200000 last 99:99:99.999999999 0:00:00.179263168 30869 0x18c1560 DEBUG basesink gstbasesink.c:4374:gst_base_sink_get_position:<videosink-actual-sink-ximage> res: 1, POSITION: 0:00:06.027988000 0:00:00.179273125 30869 0x18c1560 DEBUG basesink gstbasesink.c:4558:default_element_query:<videosink-actual-sink-ximage> query position returns 1 (test:30869): main-test-DEBUG: seeking finished, position: 6027988000
Created attachment 226558 [details] Test for both 1.0 and 0.10 You can compile now either: $ gcc -o test -Wall -Werror `pkg-config --libs --cflags gstreamer-0.10` main.c $ gcc -o test -Wall -Werror `pkg-config --libs --cflags gstreamer-1.0` main.c -DGSTREAMER_1_0
You can find for download the media file we are using at https://svn.webkit.org/repository/webkit/trunk/LayoutTests/media/content/test.mp4 .
Created attachment 226562 [details] Test for both 1.0 and 0.10 Forgot about playbin2
I forgot to mention that his happens around 30% of times only.
This only happens when using the AAC decoder from gst-libav, which faad it works perfectly fine.
Actually happens with faad too, just less often. The problem seems to be that the audio clock advanced a bit already when the position query happens.
Yes, it happens with both. I tried with the systemclock and it fails both in 1.0 but not in 0.10, so systemclock has no effect. What does have effect is the sink, because if I force alsasink, it works perfectly fine in 1.0, 0.10 with or without systemclock.
Created attachment 227344 [details] Gzipped log of the problem
It would be really nice to have this fixed as this is preventing WebKit from being ported definitely to 1.0 because of https://bugs.webkit.org/show_bug.cgi?id=98804 .
(In reply to comment #7) > What does have effect is the sink, because if I force alsasink, it works > perfectly fine in 1.0, 0.10 with or without systemclock. I lied, it does not work with alsasink. It has the very same problem. So the situation is that the audiosink reports always wrong state, so position query returns 0, no matter the sink. In the case of the video sink it reports the wrong position based on a wrong start_time (that is forwarded to base_time and then to now in the video sink), no matter the sink (I tried ximage, xvimage and even fakesink) and bin takes the video as the position.
commit 14714891045d66e1573f57a4b56396512e4282ad Author: Wim Taymans <wim.taymans@collabora.co.uk> Date: Tue Nov 20 16:19:16 2012 +0100 basesink: reset START_TIME when needed Fixes https://bugzilla.gnome.org/show_bug.cgi?id=685870
Thanks!