[Bug 740834] New: baseaudiosink: racy clock jump when renegotiating
GStreamer (bugzilla.gnome.org)
bugzilla at gnome.org
Thu Nov 27 22:50:16 PST 2014
https://bugzilla.gnome.org/show_bug.cgi?id=740834
GStreamer | gst-plugins-base | git
Summary: baseaudiosink: racy clock jump when renegotiating
Classification: Platform
Product: GStreamer
Version: git
OS/Version: All
Status: UNCONFIRMED
Severity: major
Priority: Normal
Component: gst-plugins-base
AssignedTo: gstreamer-bugs at lists.freedesktop.org
ReportedBy: thiagossantos at gmail.com
QAContact: gstreamer-bugs at lists.freedesktop.org
GNOME version: ---
When caps changes on the sink, the clock is re-calibrated but it seems to be
racy with other threads using the clock. Here is what happens:
I added some extra debug messages to make it easier to see.
1) The renegotiation starts:
0:00:37.969671518 22325 0x94eaa00 DEBUG basesink
gstbasesink.c:3157:gst_base_sink_event:<autoaudiosink0-actual-sink-alsa>
received event 0xadcd0520 caps event: 0xadcd0520, time 99:99:99.999999999,
0:00:37.969714342 22325 0x94eaa00 DEBUG basesink
gstbasesink.c:3069:gst_base_sink_default_event:<autoaudiosink0-actual-sink-alsa>
caps 0xadcd0520
0:00:37.969735137 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:860:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa>
release old ringbuffer
0:00:37.969889649 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa>
processed samples: raw 393216, delay 9216, real 384000, time
0:00:37.969945954 22325 0x94eaa00 ERROR audioclock
gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
Result: 0:00:08.000000000
0:00:37.969975788 22325 0x94eaa00 ERROR audioclock
gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> +
timeoffset: 0:00:21.851435231
0:00:37.970004100 22325 0x94eaa00 DEBUG audioclock
gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
result 0:00:29.851435231, last_time 0:00:29.851435231
0:00:37.970042086 22325 0x94eaa00 DEBUG GST_CLOCK
gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time
0:00:29.851435231
0:00:37.970075551 22325 0x94eaa00 DEBUG GST_CLOCK
gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time
0:00:29.641049743
0:00:37.970093798 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:868:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa>
time was 0:00:29.641049743
Notice how it will store the current time '29.64' to be used later.
Also notice the internal_time -> 8.00 and the timeoffset: 21.85 and the
last_time -> 29.85
2) The video sink renders a frame
0:00:38.020787346 22325 0xada3c580 LOG GST_SCHEDULING
gstpad.c:3834:gst_pad_chain_data_unchecked:<webkitvideosink0:sink> calling
chainfunction &gst_base_sink_chain with buffer buffer: 0x95980b0, pts 0:
0:00:38.020815448 22325 0xada3c580 DEBUG basesink
gstbasesink.c:3329:gst_base_sink_chain_unlocked:<webkitvideosink0> got times
start: 0:00:29.416666666, end: 0:00:29.458333332
0:00:38.020841219 22325 0xada3c580 DEBUG basesink
gstbasesink.c:1897:gst_base_sink_get_sync_times:<webkitvideosink0> got times
start: 0:00:29.416666666, stop: 0:00:29.458333332, do_sync 1
0:00:38.020866168 22325 0xada3c580 LOG basesink
gstbasesink.c:2430:gst_base_sink_do_sync:<webkitvideosink0> avg frame diff
0:00:00.185774346
0:00:38.020884193 22325 0xada3c580 DEBUG basesink
gstbasesink.c:2470:gst_base_sink_do_sync:<webkitvideosink0> reset rc_time to
time 0:00:29.416666666
0:00:38.020899970 22325 0xada3c580 DEBUG basesink
gstbasesink.c:2482:gst_base_sink_do_sync:<webkitvideosink0> possibly waiting
for clock to reach 0:00:29.416666666, adjusted 0:00:29.416666666
0:00:38.020920275 22325 0xada3c580 LOG basesink
gstbasesink.c:2068:gst_base_sink_wait_clock:<webkitvideosink0> time
0:00:29.416666666, base_time 0:00:00.000000000
0:00:38.020942711 22325 0xada3c580 DEBUG GST_CLOCK
gstclock.c:533:gst_clock_id_wait:<GstAudioSinkClock> waiting on clock entry
0xadcf2378
0:00:38.020965430 22325 0xada3c580 DEBUG audiobasesink
gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa>
processed samples: raw 394240, delay 0, real 394240, time 0:0
0:00:38.020987087 22325 0xada3c580 ERROR audioclock
gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
Result: 0:00:08.213333333
0:00:38.021003828 22325 0xada3c580 ERROR audioclock
gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> +
timeoffset: 0:00:21.851435231
0:00:38.021020087 22325 0xada3c580 DEBUG audioclock
gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
result 0:00:30.064768564, last_time 0:00:30.064768564
0:00:38.021039992 22325 0xada3c580 DEBUG GST_CLOCK
gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time
0:00:30.064768564
0:00:38.021058124 22325 0xada3c580 DEBUG GST_CLOCK
gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time
0:00:29.854383076
Nothing really wrong here (yet)
3) audio sink continues the negotiation and *resets the clock* as part of
gst_audio_sink_ring_buffer_acquire to make the clock start from 0 again
0:00:38.023680401 22325 0x94eaa00 DEBUG audioclock
gstaudioclock.c:173:gst_audio_clock_reset:<GstAudioSinkClock> reset clock to
0:00:00.000000000, last 0:00:30.064768564, offset 0:00:30.064768564
0:00:38.023807328 22325 0x94eaa00 INFO ringbuffer
gstaudioringbuffer.c:573:gst_audio_ring_buffer_acquire:<audiosinkringbuffer0>
Allocating an array for 9 timestamps
0:00:38.023846821 22325 0x94eaa00 DEBUG ringbuffer
gstaudioringbuffer.c:603:gst_audio_ring_buffer_acquire:<audiosinkringbuffer0>
acquired device
0:00:38.023861024 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:894:gst_audio_base_sink_setcaps:<autoaudiosink0-actual-sink-alsa>
activate ringbuffer
0:00:38.023874256 22325 0x94eaa00 DEBUG ringbuffer
gstaudioringbuffer.c:763:gst_audio_ring_buffer_activate:<audiosinkringbuffer0>
activate device
0:00:38.023898862 22325 0x94eaa00 DEBUG audiosink
gstaudiosink.c:445:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa>
starting thread
0:00:38.023946052 22325 0x94eaa00 DEBUG audiosink
gstaudiosink.c:453:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa>
waiting for thread
Here's when the bad things happen. Now the clock offset is at 30.06.
4) A position query happens:
0:00:38.024022982 22325 0x8ccc360 ERROR audioclock
gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
Result: 0:00:08.192000000
0:00:38.024042358 22325 0x8ccc360 ERROR audioclock
gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> +
timeoffset: 0:00:30.064768564
0:00:38.024061434 22325 0x8ccc360 DEBUG audioclock
gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
result 0:00:38.256768564, last_time 0:00:38.256768564
0:00:38.024087391 22325 0x8ccc360 DEBUG GST_CLOCK
gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time
0:00:38.256768564
0:00:38.024108207 22325 0x8ccc360 DEBUG GST_CLOCK
gstclock.c:995:gst_clock_get_time:<GstAudioSinkClock> adjusted time
0:00:38.046383076
0:00:38.024129431 22325 0x8ccc360 DEBUG basesink
gstbasesink.c:4577:gst_base_sink_get_position:<autoaudiosink0-actual-sink-alsa>
now 0:00:38.046383076 - base_time 0:00:00.000000000 - base 0:00:00.000000000 +
time 0:00:00.000000000 last 0:00:29.819333333
0:00:38.024165394 22325 0x8ccc360 DEBUG basesink
gstbasesink.c:4590:gst_base_sink_get_position:<autoaudiosink0-actual-sink-alsa>
res: 1, POSITION: 0:00:29.819333333
0:00:38.024197783 22325 0x8ccc360 DEBUG basesink
gstbasesink.c:4787:default_element_query:<autoaudiosink0-actual-sink-alsa>
query position returns 1
The query actually returns the correct 29s position, but it has the side effect
of updating the last_time in the clock to 38.25
5) setcaps continues and the clock is recalibrated (wrongly...)
0:00:38.030842676 22325 0x94eaa00 DEBUG audiosink
gstaudiosink.c:456:gst_audio_sink_ring_buffer_activate:<autoaudiosink0-actual-sink-alsa>
thread is started
0:00:38.030867116 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:548:gst_audio_base_sink_get_time:<autoaudiosink0-actual-sink-alsa>
processed samples: raw 0, delay 0, real 0, time 0:00:00.00000
0:00:38.030889831 22325 0x94eaa00 ERROR audioclock
gstaudioclock.c:191:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
Result: 0:00:00.000000000
0:00:38.030907637 22325 0x94eaa00 ERROR audioclock
gstaudioclock.c:195:gst_audio_clock_get_internal_time:<GstAudioSinkClock> +
timeoffset: 0:00:30.064768564
0:00:38.030924223 22325 0x94eaa00 DEBUG audioclock
gstaudioclock.c:206:gst_audio_clock_get_internal_time:<GstAudioSinkClock>
result 0:00:38.256768564, last_time 0:00:38.256768564
0:00:38.030945841 22325 0x94eaa00 DEBUG GST_CLOCK
gstclock.c:950:gst_clock_get_internal_time:<GstAudioSinkClock> internal time
0:00:38.256768564
0:00:38.030966176 22325 0x94eaa00 DEBUG GST_CLOCK
gstclock.c:1050:gst_clock_set_calibration:<GstAudioSinkClock> internal
0:00:38.256768564 external 0:00:29.641049743 1/1 = 1.000000
Because the last sample was updated to 38.25s, the recalibration will use that
as the new internal time, while the external (the value got in step 1) was
29.64 and at that time the internal time was much different (smaller).
6) Rendering will be delayed because the clock jumped ahead (will translate
~29s to ~38s and always add those 9s to timestamps)
0:00:38.068158241 22325 0x94eaa00 DEBUG basesink
gstbasesink.c:3329:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-alsa>
got times start: 0:00:29.789297052, end: 0:00:29.812517007
0:00:38.068190035 22325 0x94eaa00 DEBUG basesink
gstbasesink.c:1897:gst_base_sink_get_sync_times:<autoaudiosink0-actual-sink-alsa>
got times start: 0:00:29.789297052, stop: 0:00:29.812517007, do_sync 0
0:00:38.068206523 22325 0x94eaa00 DEBUG basesink
gstbasesink.c:3411:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-alsa>
rendering object 0xada8eb28
0:00:38.068218646 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:1695:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa>
time 0:00:29.789297052, offset -1, start 0:00:00.000000000, samples 1024
0:00:38.068235753 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:1732:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa>
sync-offset 0, render-delay 0:00:00.000000000, ts-offset 0
0:00:38.068248476 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:1794:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa>
running: start 0:00:29.789297052 - stop 0:00:29.812517006
0:00:38.068299882 22325 0x94eaa00 DEBUG audiobasesink
gstaudiobasesink.c:1836:gst_audio_base_sink_render:<autoaudiosink0-actual-sink-alsa>
final timestamps: start 0:00:38.405015873 - stop 0:00:38.42823
--
Configure bugmail: https://bugzilla.gnome.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.
You are the assignee for the bug.
More information about the gstreamer-bugs
mailing list