GNOME Bugzilla – Bug 109041
[mad] needs to be faster on sync errors
Last modified: 2006-01-27 15:48:04 UTC
Run the following pipeline (or use another non-Mp3 file as big as an Mp3): time gst-launch filesrc location=libgstreamer-0.7.so ! mad ! fakesink The output here is: INFO (11987: 0) Initializing GStreamer Core Library version 0.7.0.1 INFO (11987: 0) CPU features: (c1c3fbff) MMX SSE 3DNOW MMXEXT INFO (11987: 0) registry: loaded user_registry in 0.000168 seconds (/root/.gstreamer/registry.xml) INFO (11987: 0) registry: loaded global_registry in 0.344941 seconds (/usr/gstreamer/var/cache/gstreamer-0.7/registry.xml) RUNNING pipeline execution ended after 845 iterations (sum 110439173000 ns, average 130697246 ns, min 252000 ns, max 618142000 ns) real 1m51.332s user 1m37.160s sys 0m0.450s Gstmad should at some point of not finding a sync point just error out, which it currently doesn't. If you play a broken Mp3 this is just too long until you realize that the file was broken. I wasn't sure how to fix this the right way, so I just filed a bug about it and seek suggestions whatz the right behaviour should be, so I can fix it.
Perusing the MPEG auudio docs the other day (doesn't everyone do that?), I read that there is an upper bound on the frame size, which is approximately 10 kB. Thus, after searching through 100 kB and not finding a sync, there is either a huge error rate in the stream, or it's not an mpeg audio stream.
btw, still relevant to current HEAD
*** Bug 140237 has been marked as a duplicate of this bug. ***
It's not correct, because there's many MP3s out there with up to more than 1 MB (!!!) of random data before the first valid mp3 data arrives. Random data is either complete garbage or nice and tidy zeroes, I've seen them all. We should support even those files. I don't think we should fix this bug. I agree that syncing should be faster, though. 1:51 is too long.
There's the nice side effect of this blocking the UI in media players until it has found the sync point. Or at least it feels like it. It shouldn't be that hard to find the next sync point, it's just comparing all the bytes with 0xFF
OK, so I try to reproduce this: $ ls -la ~/Projects/GStreamer/gstreamer/gst/.libs/libgstreamer-0.8.so.1.4.0 -rwxrwxr-x 1 rbultje rbultje 3923973 Jan 28 10:31 /home/rbultje/Projects/GStreamer/gstreamer/gst/.libs/libgstreamer-0.8.so.1.4.0 Normal filesize, right? $ time gst-launch filesrc location=~/Projects/GStreamer/gstreamer/gst/.libs/libgstreamer-0.8.so.1.4.0 ! mad ! fakesink RUNNING pipeline ... Execution ended after 961 iterations (sum 389251000 ns, average 405047 ns, min 140000 ns, max 9706000 ns). real 0m2.877s user 0m2.203s sys 0m0.126s (file was cached btw, uncached, it takes ~5 seconds.) That seems pretty good really, which tempts me to close this bug as wontfix. Alternatively, we can ssume that this is OK behaviour for local files, but not for webstreams (since those are infinitely long). For those, you'd want to error out after a while (e.g. 100k as Dave proposes). We can add an additional property to mad for that. What do you think?
I filed a bug that was marked a duplicate of this one that concerns a related but smaller issue, I think. I have MP3's that apparently have small corrupted bits in the middle of them. When I play them in madplay, I get small glitches but playback continues fine. With Rhythmbox, I end up waiting several minutes for GStreamer to recover. I have one song in particular that ought to be 3:43 long that Rhythmbox just took 13 minutes to get through! I don't know how enthusiastic you guys are about supporting MP3's, but it would be really nice if this got fixed one way or another. Is it possible to clone whatever algorithm madplay has for handling sync errors? Madplay seems to do about as good a job as possible with the problems I'm seeing, and I assume there's no reason GStreamer can't do as well or better.
Peter, your bug was fixed in 0.8.8. I don't know why it was duped, but it no longer applies. This bug is now solely about erroring out in webstreams without breaking the 1MB-trash-files.
Actually, I think I have the bug that Peter Williams describe too, and it might deserve a newer report (if you want me to open a new one, please say so). I noticed that Rhythmbox got stuck on a particular song, but gst-launch and the following pipeline: gst-launch-0.8 --gst-debug-level=3 gnomevfssrc location='foo.mp3' ! spider ! volume ! audioscale ! audioconvert ! $(gconftool-2 -g /system/gstreamer/0.8/default/audiosink) produced a high pitched sound for a split second, and then continued fine. There's probably a bug in Rhythmbox when the underlying GStreamer chuckles on a song, but I think GStreamer might be the culprit, and not necessarily mad, as madplay did go through the file, with a special error on the point where GStreamer chuckles: bee% madplay foo.mp3 MPEG Audio Decoder 0.15.2 (beta) - Copyright (C) 2000-2004 Robert Leslie et al. Artist: Francois Perusse Album: 2 Minutes du peuple Genre: Comedy error: frame 0: lost synchronization error: frame 254: lost synchronization error: frame 495: lost synchronization error: frame 496: CRC check failed error: frame 999: lost synchronization 995 frames decoded (0:00:25,9), -17,2 dB peak amplitude, 0 clipped samples At the same place, the debugging output of the pipeline is like: ... INFO (0x8050920 - 310171:56:52.301572000) GST_PADS( 8261) gstpad.c(4045):gst_pad_event_default_dispatch:<audioconvert0:sink> Sending event 0x807bc78 to all internally linked pads INFO (0x8050920 - 310171:56:52.304901000) GST_PADS( 8261) gstpad.c(4045):gst_pad_event_default_dispatch:<osssink0:sink> Sending event 0x807bc78 to all internally linked pads INFO (0x8050920 - 310171:56:52.308191000) GST_EVENT( 8261) gstevent.c(96):_gst_event_free: freeing event 0x807bc78 INFO (0x8050920 - 310171:56:58.489948000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.490874000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.490953000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.491020000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.491670000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.491731000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.491787000) mad( 8261) gstmad.c(1325):gst_mad_chain: recoverable lost sync error INFO (0x8050920 - 310171:56:58.534738000) oss( 8261) gstosssink.c(450):gst_osssink_chain:<osssink0> need sync: real 0:00:06.608979591, buffer: 0:00:09.108000000 INFO (0x8050920 - 310171:57:01.065789000) oss( 8261) gstosssink.c(450):gst_osssink_chain:<osssink0> need sync: real 0:00:09.142789114, buffer: 0:00:06.643809523 ... The "lost sync error" seems to trigger a point where mad will seek further in the stream, garbage some bytes, the ossink will empty some buffer, I get the noise, and just a split second after that, playback continues. The pipeline will then produce "need sync" lines all the time. With a bigger debug level, it's harder to follow, but grepping on mad shows: DEBUG (0x8050928 - 310172:24:11.842113000) mad( 8947) gstmad.c(1317):gst_mad_chain: mad_frame_decode had an error: lost synchronization INFO (0x8050928 - 310172:24:11.842162000) mad( 8947) gstmad.c(1325):gst_mad_chain: recoverable lost sync error DEBUG (0x8050928 - 310172:24:11.842212000) mad( 8947) gstmad.c(1386):gst_mad_chain:<mad0> resynchronization consumes 187 bytes DEBUG (0x8050928 - 310172:24:11.842260000) mad( 8947) gstmad.c(1388):gst_mad_chain:<mad0> synced to data: 0xff 0xff DEBUG (0x8050928 - 310172:24:11.842399000) mad( 8947) gstmad.c(1164):gst_mad_check_caps_reset: Header changed from 44100 Hz/2 ch to 32000 Hz/2 ch, failed sync after seek ? DEBUG (0x8050928 - 310172:24:11.842727000) mad( 8947) gstmad.c(1317):gst_mad_chain: mad_frame_decode had an error: lost synchronization INFO (0x8050928 - 310172:24:11.842773000) mad( 8947) gstmad.c(1325):gst_mad_chain: recoverable lost sync error DEBUG (0x8050928 - 310172:24:11.842819000) mad( 8947) gstmad.c(1386):gst_mad_chain:<mad0> resynchronization consumes 23 bytes DEBUG (0x8050928 - 310172:24:11.842866000) mad( 8947) gstmad.c(1388):gst_mad_chain:<mad0> synced to data: 0xff 0xfb DEBUG (0x8050928 - 310172:24:11.842920000) mad( 8947) gstmad.c(1317):gst_mad_chain: mad_frame_decode had an error: bad main_data_begin pointer this is repeated a couple of times, and then playback continues.
Loic: I think your bug should be filed separately. If it's not obsolete by now... So to summarize: this bug is "mad should probably error out if it doesn't resync within 100 kB of data, but only for web streams because for files it's faster and quite possible". I disagree though. In 0.10 the UI will not lock up because streaming is in a different thread; the user can always press stop. Because the user asked to play a bad stream, and there are no nasty errors while mad tries to resync, and the user can press stop at any time, I'm going to close this one as obsolete. The launch line from the original report with libgstreamer-0.10 now plays in half a second for me. No problemo.