GNOME Bugzilla – Bug 709965
vorbisdec: Does not put timestamps on first buffer sometimes
Last modified: 2013-12-04 18:51:38 UTC
Created attachment 257081 [details] Python script providing rms, stream-time values Using Python introspection bindings, 'level' will return GST_CLOCK_TIME_NONE for corresponding rms values on some media. The attached script and failing sample will show: rms = [-48.193808474285014]; stream-time = 18446744073709551615 ...at stream-time 0. To run: python problem.py file:///path/to/failing_sample.mkv Other files are fine: python problem.py file:////usr/share/sounds/alsa/Front_Center.wav -> rms = [-74.38954575771548]; stream-time = 0 === GST_CLOCK_TIME_NONE is returned much more frequently within 'pitivi/timeline/previewers.py' preventing audio waveform generation for the same failing sample. I've been unable to reproduce this in the simplified script, however. Adding 'queue max-size-buffers=0 max-size-bytes=0 max-size-time=0' between Gst.parse_launch (line 800) elements mitigates the appearance of GST_CLOCK_TIME_NONE but doesn't address the underlying issue.
Created attachment 257082 [details] Vorbis-in-mkv, produced by GStreamer 0.10.36 then chopped with mkvmerge
I can't reproduce with your script and file in either git master or 1.0.10
The original report was generated on a 'open video reference build' system: https://gitorious.org/openvideo_reference_build == On a fresh install of Debian testing amd64 (via wheezy->testing) after removal of 'post-messages=true' from Gst.parse_launch(...) I show a return value of GST_CLOCK_TIME_NONE for the first 7 entries, valid entries from 185745408 (=0.186 sec) to 119977498362 (=119.977 sec), then a final rms value of 'nan' at the same stream time of 119977498362. All .wav files in '/usr/share/sounds/alsa' are OK with the exception that the final entries, respectively, follow the same 'nan' pattern. gir1.2-gstreamer-1.0 ver. = 1.2.0-1 gir1.2-glib-2.0 ver. = 1.36.0-2+b1 Python 2.7.5+ ========= On Debian unstable (wheezy->testing->unstable) with or without 'post-messages=true' behavior is identical to the original report. gir1.2-gstreamer-1.0 ver. = 1.2.0-1 gir1.2-glib-2.0 ver. = 1.36.0-2+b1 Python 2.7.5+ ===== Lenovo x201i (w/ AC adapter); md5sum for the clip as follows: 33d3fadee50dd4670d6eec1045a577a2 pitivi_failing_sample.mkv
This could in theory happen if the buffer timestamp is outside the segment, level (and spectrum and all these elements) should check for that probably and clip such buffers first instead of handling everything they get passed. Can someone confirm that this is the case by looking at the timestamps and the segment events?
No, problem here is that vorbisdec does not put timestamps on the first buffers. Maybe what I guessed happens too on other files, but not on the attached Matroska file. Could also be matroskademux which does something wrong.
Setting pipeline to PLAYING ... /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000040 discont ) 0x7f9e90013bf0 New clock: GstSystemClock /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900139d0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900137b0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900138c0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e90013ae0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900139d0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: none, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900136a0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: 0:00:00.185745408, duration: 0:00:00.023219955, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e900138c0 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (4096 bytes, dts: none, pts: 0:00:00.208965363, duration: 0:00:00.023219954, offset: -1, offset_end: -1, flags: 00000000 ) 0x7f9e90013bf0 [...]
This bug now reads very closely to Bug #656412, starting at comment #19: vorbisdec: discard starting samples according to granpos https://bugzilla.gnome.org/show_bug.cgi?id=656412#c19 It's listed as an enhancement but provides maybe-helpful background info, in any case.
Yes, actually this seems to be the same problem. *** This bug has been marked as a duplicate of bug 656412 ***
granulepos is an ogg concept, I don't see how it applies to vorbis-in-matroska?
The GST_CLOCK_TIME_NONE behavior appears to be caused by a block parsing/lacing issue in './gst/matroska/matroska-demux.c'. Debug statements added show the else portion of: ' if (lace_time != GST_CLOCK_TIME_NONE && duration) lace_time += duration / laces; else lace_time = GST_CLOCK_TIME_NONE;', lines 3772-3775 ...is hit frequently in failing samples and only once at the start in files produced directly by GStreamer. I don't have a patch to offer but adding "--disable-lacing" to mkvmerge doesn't show GST_CLOCK_TIME_NONE in the Python script above and also fixes the PiTiVi waveform generation issue.
Was the lace_time == GST_CLOCK_TIME_NONE here or no duration available? This would seem like a problem created when cutting the file, and removing necessary timestamp information from it.
On the file produced directly from GStreamer, once, at the start, when the else block is hit: lace_time: 18446744073709551615 Duration: 0 On the files produced by mkvmerge, every time the else block is hit (frequently), with or with out '--disable-lacing': lace_time: 18446744073709551615 Duration: 0 So, both?
Oops, had missed the line-prior assignment. Correction: On the file produced directly from GStreamer, once, at the start, when the else block is hit: lace_time: 0. Duration: 0 On the same file, but with "--disable-lacing": lace_time: 0 Duration: 0 ======================================== lace_time: 1000000 Duration: 0 ======================================== lace_time: 15000000 Duration: 0 ======================================== lace_time: 38000000 Duration: 0 ... On the failing sample: lace_time: 0 Duration: 0 ======================================== lace_time: 18446744073709551615 Duration: 0 ======================================== [prior block repeated x 6] ======================================== lace_time: 185745408 Duration: 0 ======================================== lace_time: 18446744073709551615 Duration: 0 ======================================== [prior block repeated x 6] ======================================== lace_time: 280091922 Duration: 0 ======================================== lace_time: 18446744073709551615 Duration: 0 ======================================== [prior block repeated x 6] ======================================== lace_time: 455679378 Duration: 0 ======================================== ...follows the same pattern, with some variation
Please correct my statements below (In reply to comment #13) > Oops, had missed the line-prior assignment. Correction: > > On the file produced directly from GStreamer, once, at the start, when the else > block is hit: > lace_time: 0. > Duration: 0 This should cause a timestamp of 0 for the first lace in the block, and GST_CLOCK_TIME_NONE for the others > On the same file, but with "--disable-lacing": > lace_time: 0 > Duration: 0 > ======================================== > lace_time: 1000000 > Duration: 0 > ======================================== > lace_time: 15000000 > Duration: 0 > ======================================== > lace_time: 38000000 > Duration: 0 > ... This should cause proper timestamps for all > On the failing sample: > lace_time: 0 > Duration: 0 > ======================================== > lace_time: 18446744073709551615 > Duration: 0 > ======================================== > [prior block repeated x 6] > > ======================================== > lace_time: 185745408 > Duration: 0 This should cause timestamps of 0, followed by GST_CLOCK_TIME_NONE, followed by 185745408 If any of my statements is not true, that should and can be fixed. The GST_CLOCK_TIME_NONEs I mention can't be prevented by the demuxer and should be filled by the decoder.
matroskademux output has correct timestamps (none on the vorbis headers, 0 on first audio data, then none due to the lacing, and then a timestamp now and then. vorbisdec discards a frame if vorbis decoder does not produce samples for that, and as such the timestamp associated with that is lost. Depending on whether the decoder is discarding samples or merely operating with decoder delay, this behaviour is either correct or to be fixed.
Created attachment 259747 [details] [review] vorbisdec: no discarding of input frames Patch to implement correction depending on situation as described earlier.
Looks like it is not that simple :( This patch makes the pipeline/vorbisdec unit test fail, due to imperfect timestamps. That in turn is due to vorbisenc producing a first 0 duration buffer (and so 2 buffers have pts 0). That, in turn, is due to what the vorbis encoder is claiming us it has put into the first encoded data buffer (based on the granulepos). Unless that first buffer is meant to discarded, it does not seem to make sense, but that's we are being told ...
The problem is that the first two buffers have the same timestamp 0? What is wrong with that? :)
When the decoder tracks upstream timestamps, this will lead to an imperfect stream and fail the unit-test (unless the latter is made more relaxed).
Isn't the first 0 timestamp buffer just a header that produces no output, and only the second 0 timestamp buffer is containing actual audio?
Both 0 timestamps are on a "data" buffer, as in, not a vorbis header. Though decoder only produces output on second data buffer (if that makes the first one a header buffer in some sense ?). In any case, either the very first timstamp is ignored, as it is now, but then there is a problem if the second one has no timestamp, as in the this bug with matroska lacing etc. Either it is not ignored, but then imperfect output follows.
Upon further reflection, an alternative (simpler) solution is to use the current segment start timestamp if no other one has been determined so far (from buffer ts): commit 387e5f0c142fcbd3338fb86d97443b3671afc538 Author: Mark Nauwelaerts <mnauw@users.sourceforge.net> Date: Mon Dec 2 20:35:04 2013 +0100 audiodecoder: use segment start as fallback ts if no other available Fixes https://bugzilla.gnome.org/show_bug.cgi?id=709965
... and a minor addendum for good measure ... commit 6e639b73ffd0043ff6804e65c1331661d5730579 Author: Mark Nauwelaerts <mnauw@users.sourceforge.net> Date: Wed Dec 4 19:24:08 2013 +0100 audiodecoder: no fallback to segment start for reverse playback See https://bugzilla.gnome.org/show_bug.cgi?id=709965