GNOME Bugzilla – Bug 484210
crossfade backend can't preroll some files
Last modified: 2018-05-24 12:54:23 UTC
Please describe the problem: Especially when quickly using the previous song/next song button several times after each other, the requested action is not done. Steps to reproduce: 1. Start playing a song 2. Fairly quickly press two times the next song button, make sure you click not too fast so you can also read the name of the song you are skipping 3. Quicly press the previous song button Actual results: Nothing happens: song number three continues playing Expected results: Previous song (number two) is played. When clicking a second time the previous button, you are back at the song you started playing in step 1 (first song), so it has certainly registered the first click on the previous song button somewhere, but for some reason did not start playing the right song Does this happen every time? Yes Other information: I'm using random playmode and the crossfade back-end for gapless playback. rhythmbox-0.11.2-2mdv2008.0 on Mandriva 2008.0
This happens when the crossfading player backend doesn't preroll the new song properly. This used to happen with (some?) WMA files, but I've fixed that in svn (bug 424836). For me, it also happens with particular ogg vorbis files.
*** Bug 511616 has been marked as a duplicate of this bug. ***
Is this a bug in gstreamer or in rhythmbox?
I've been noticing a similar thing in Fedora 9 Preview (rawhide). Rhythmbox (0.11.5) plays a few tracks, but will then randomly stop on one track, and I have to push it along manually. It doesn't appear to be tied to one format of track either (I have both OGG and MP3 tracks). My gstreamer is version 0.10.19, with various different 0.10.x gstreamer-plugins packages. I can do a rhythmbox --debug if that would help at all.
I am also experiencing the failure to advance to the next file. I did an initial test of the crossfade/gapless backend with the hydrogen audio samples (which unpack to WAV format) and it worked flawlessly but when I try to play files from my collection it more often than not fails to advance from one file to the next. I have a mixture of Ogg/Vorbis, FLAC and MP3. After a little research it seems the problem occurs when the file rhythmbox is advancing to is a FLAC file. Having got stuck once trying to advance to a FLAC file advancing to the next file gets stuck every time even if the next file is MP3 or Ogg/Vorbis but after a restart advancing between Ogg/Vorbis and MP3 seems to work correctly. Here are the versions I am running: Package: rhythmbox Version: 0.11.5-2 -- System Information: Debian Release: lenny/sid APT prefers testing APT policy: (500, 'testing') Architecture: amd64 (x86_64) Kernel: Linux 2.6.25-ecrins Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8) Shell: /bin/sh linked to /bin/bash Versions of packages rhythmbox depends on: ii dbus 1.2.1-1 simple interprocess messaging syst ii gconf2 2.22.0-1 GNOME configuration database syste ii gnome-icon-theme 2.22.0-1 GNOME Desktop icon theme ii gstreamer0.10-alsa [gs 0.10.19-1 GStreamer plugin for ALSA ii gstreamer0.10-esd [gst 0.10.7-3 GStreamer plugin for ESD ii gstreamer0.10-gnomevfs 0.10.19-1 GStreamer plugin for GnomeVFS ii gstreamer0.10-plugins- 0.10.19-1 GStreamer plugins from the "base" ii gstreamer0.10-plugins- 0.10.7-3 GStreamer plugins from the "good" ii gstreamer0.10-x 0.10.19-1 GStreamer plugins for X11 and Pang ii libart-2.0-2 2.3.20-1 Library of functions for 2D graphi ii libatk1.0-0 1.22.0-1 The ATK accessibility toolkit ii libavahi-client3 0.6.22-3 Avahi client library ii libavahi-common3 0.6.22-3 Avahi common library ii libavahi-glib1 0.6.22-3 Avahi glib integration library ii libbonobo2-0 2.22.0-1 Bonobo CORBA interfaces library ii libbonoboui2-0 2.22.0-1 The Bonobo UI library ii libc6 2.7-10 GNU C Library: Shared libraries ii libcairo2 1.4.14-1 The Cairo 2D vector graphics libra ii libdbus-1-3 1.2.1-1 simple interprocess messaging syst ii libdbus-glib-1-2 0.74-2 simple interprocess messaging syst ii libexpat1 1.95.8-4 XML parsing C library - runtime li ii libfontconfig1 2.5.0-2 generic font configuration library ii libfreetype6 2.3.5-1+b1 FreeType 2 font engine, shared lib ii libgconf2-4 2.22.0-1 GNOME configuration database syste ii libglade2-0 1:2.6.2-1 library to load .glade files at ru ii libglib2.0-0 2.16.1-2 The GLib library of C routines ii libgnome-keyring0 2.22.1-1 GNOME keyring services library ii libgnome-media0 2.22.0-1 runtime libraries for the GNOME me ii libgnome2-0 2.20.1.1-1 The GNOME 2 library - runtime file ii libgnomecanvas2-0 2.20.1.1-1 A powerful object-oriented display ii libgnomeui-0 2.20.1.1-1 The GNOME 2 libraries (User Interf ii libgnomevfs2-0 1:2.22.0-2 GNOME Virtual File System (runtime ii libgpod3 0.6.0-4 a library to read and write songs ii libgstreamer-plugins-b 0.10.19-1 GStreamer libraries from the "base ii libgstreamer0.10-0 0.10.19-3 Core GStreamer libraries and eleme ii libgtk2.0-0 2.12.9-2 The GTK+ graphical user interface ii libhal1 0.5.11~rc2-1 Hardware Abstraction Layer - share ii libice6 2:1.0.4-1 X11 Inter-Client Exchange library ii liblircclient0 0.8.2-2 infra-red remote control support - ii libmtp7 0.2.6.1-2 Media Transfer Protocol (MTP) libr ii libmusicbrainz4c2a 2.1.5-2 Second generation incarnation of t ii libnautilus-burn4 2.20.0-1 Nautilus Burn Library - runtime ve ii libnotify1 [libnotify1 0.4.4-3 sends desktop notifications to a n ii libnspr4-0d 4.7.0-2 NetScape Portable Runtime Library ii liborbit2 1:2.14.12-0.1 libraries for ORBit2 - a CORBA ORB ii libpango1.0-0 1.20.2-2 Layout and rendering of internatio ii libpng12-0 1.2.27-1 PNG library - runtime ii libpopt0 1.10-3 lib for parsing cmdline parameters ii libsexy2 0.1.11-2 collection of additional GTK+ widg ii libsm6 2:1.0.3-1+b1 X11 Session Management library ii libsoup2.4-1 2.4.1-1 an HTTP library implementation in ii libtotem-plparser10 2.22.2-1 Totem Playlist Parser library - ru ii libusb-0.1-4 2:0.1.12-9 userspace USB programming library ii libx11-6 2:1.0.3-7 X11 client-side library ii libxcursor1 1:1.1.9-1 X cursor management library ii libxext6 2:1.0.4-1 X11 miscellaneous extension librar ii libxfixes3 1:4.0.3-2 X11 miscellaneous 'fixes' extensio ii libxi6 2:1.1.3-1 X11 Input extension library ii libxinerama1 2:1.0.3-1 X11 Xinerama extension library ii libxml2 2.6.32.dfsg-2 GNOME XML library ii libxrandr2 2:1.2.2-1 X11 RandR extension library ii libxrender1 1:0.9.4-1 X Rendering Extension client libra ii python 2.5.2-1 An interactive high-level object-o ii python-gnome2 2.22.0-1 Python bindings for the GNOME desk ii python-gtk2 2.12.1-1 Python bindings for the GTK+ widge ii python-support 0.7.7 automated rebuilding support for P ii python2.4 2.4.5-2 An interactive high-level object-o ii zlib1g 1:1.2.3.3.dfsg-12 compression library - runtime
Created attachment 110571 [details] [review] fix preroll queue size The problems I've been having with ogg vorbis files are caused by the preroll queue reaching its maximum buffer count (200) before it reaches the minimum time threshold (1 second). When this happens, the stream will never preroll. This patch increases the maximum buffer count to 1000 while prerolling, which fixes playback of all the files I can find that previously failed.
Hey, that's great Jonathan!. I compiled rhythmbox trunk with your patch and I can now play every ogg file without problems, Whereas without your patch I couldn't play about 1% of my files because of the prerolling error. In those cases, when rhythmbox encountered such a file, it would just pause doing nothing. Clicking 'next' would play the next file, skipping the problematic file. So, your patch works great, I hope it gets applied soon!
Oh, perhaps the patch is missing a changelog entry telling what it does and what bug it fixed.
I tried applying the patch to change the preroll queue size but I am still having problems with failing to advance to the next track. I have a vague impression that this depends on system load - if I am compiling something or running a qemu emulated PC it is more likely to get stuck than if the system is otherwise idle. Anyway, for what it is worth I attach a copy of the debug output for one example of a failure to advance to the next track.
Created attachment 110808 [details] Debug Log
That appears to be a different (but similar) problem. If you can figure out how to reliably reproduce it, running 'GST_DEBUG=*:5,GST_PLUGIN_LOADING:0,GST_REGISTRY:0 rhythmbox 2>/tmp/gstdebuglog' will produce a (very large) file that should provide enough information to figure out what's going on.
I've committed the patch, but apparently there are other problems here, so I'm leaving the bug open.
(In reply to comment #11) > That appears to be a different (but similar) problem. If you can figure out > how to reliably reproduce it, running > 'GST_DEBUG=*:5,GST_PLUGIN_LOADING:0,GST_REGISTRY:0 rhythmbox > 2>/tmp/gstdebuglog' will produce a (very large) file that should provide enough > information to figure out what's going on. I have tried this and what a frustrating day it has been. I listened so several hours of music with debugging enabled as described above and it never got stuck moving from one track to the next. Immediately I tried running without the extra logging it started getting stuck again. So I tried again with the extra logging enabled and again there was no getting stuck. Does this, perhaps, mean that in this case the getting stuck is due to a race condition? Perhaps enabling the extra debugging causes one of more of the threads involved to give up the CPU more frequently (to wait for I/O to the log file) and thus avoids the problem? That would also explain why this seems to be sensitive to system load. Is there a slightly lower level of debugging I can enable that might provide enough detail without changing the thread timing so that the problem becomes unreproducable?
(In reply to comment #13) > Is there a slightly lower level of debugging I can enable that might provide > enough detail without changing the thread timing so that the problem becomes > unreproducable? GST_DEBUG=*:4 might be enough to track it down, or at least to work out a more specific debug setting that gets the information we need. This gst-launch command line should also hang just as readily as rhythmbox itself does: gst-launch-0.10 filesrc location=/path/to/file ! decodebin ! audioconvert ! audioresample ! audio/x-raw-int,rate=44100,channels=2,width=16,depth=16 ! queue min-threshold-time=1000000000 max-size-buffers=1000 ! fakesink which might make it easier to test.
I've been playing rhythmbox with the patch for about 5 days now. As I mentioned before, I have no playing errors anymore (tracks not playing because of pre-rolling errors). That's fantastic. But what's even better is that I haven't experienced a crash/segfault as well. Rhythmbox used to crash on me about once or twice a week. Beside that, once every 1 or 2 days, rhythmbox would stop playing normally, but skip through the files as fast as possible, consuming 100% CPU and not producing any sound. Stop/Pausing play, and then playing again would start the 100% skipping again. Only way to solve this would be to exit rhythmbox and starting again. Since applying the patch 5 days ago, I haven't seen this strange behaviour, not once! And I have been running the program almost continuously. So kudo's to you, by fixing just this bug, you smashed two very annoying collateral bugs!
(In reply to comment #14) > GST_DEBUG=*:4 might be enough to track it down, or at least to work out a more > specific debug setting that gets the information we need. I tried this but I still have the same problem - enabling debug stops the problem from occurring. > This gst-launch command line should also hang just as readily as rhythmbox > itself does: > > gst-launch-0.10 filesrc location=/path/to/file ! decodebin ! audioconvert ! > audioresample ! audio/x-raw-int,rate=44100,channels=2,width=16,depth=16 ! queue > min-threshold-time=1000000000 max-size-buffers=1000 ! fakesink I tried this command immediately after rhythmbox had hung giving it the file that rhythmbox was to be moving on to (rather than the one just finishing). It did not hang - retrying it several times did not cause it to hang. If I replace fakesink with alsasink it plays nicely. Is there any way of waiting until rhythmbox has hung and then using a debugging tool to discover more information. Can I force bug-buddy to generate something to send you or can I attach gdb to the process and execute a few commands to find out what is going on? I am happy to re-compile with -g to make the output more useful.
Recompiling with -g would help.L Once it has hung, you can attach a gdb to the running process with gdb --pid <rhythmbox pid> (which you can find using ps). Once gdb is attached to the process, ctrl+c followed by 'thread apply all bt' should give you a backtrace.
I have just been looking at the debug log I originally submitted for this bug and the design that appears at the top of the rb-player-gst-xfade.c file. Something odd seems to be happening around lines 8 to 10. Line 8 says: (22:33:52) [0x1719230] [stream_src_blocked_cb] rb-player-gst-xfade.c:2313: stream file:///home/fozzy/music/ardour/stowmarket-chorale/2007-07-07-vivaldi-mozart/export/flac/04_vivaldi_gloria_04_gratias_agimus_tibi.flac is prerolled, not starting yet -> WAITING The text of the message suggests the preroll is complete and that is consistent with the design saying that a stream goes from PREROLL_PLAY to WAITING (lines 60,61 of rb-player-gst-xfade.c). Lines 9 says: (22:33:52) [0x6a6500] [rb_player_gst_xfade_play] rb-player-gst-xfade.c:3097: playing stream file:///home/fozzy/music/ardour/stowmarket-chorale/2007-07-07-vivaldi-mozart/export/flac/04_vivaldi_gloria_04_gratias_agimus_tibi.flac, crossfade 0 According to the design (line 65 of rb-player-gst-xfade.c) with crossfade 0 the next state after WAITING should be WAITING_EOS, but line 10 says: (22:33:52) [0x6a6500] [rb_player_gst_xfade_play] rb-player-gst-xfade.c:3112: stream file:///home/fozzy/music/ardour/stowmarket-chorale/2007-07-07-vivaldi-mozart/export/flac/04_vivaldi_gloria_04_gratias_agimus_tibi.flac is prerolling; will start playback once prerolling is complete -> PREROLL_PLAY According to the design this is the state before WAITING. Is it possible that the callback event in line 8 occurs unexpectedly soon. Should the code associated with lines 9 and 10 be executed first, putting the stream state into PREROLL_PLAY and then the event in line 8 would lead it going correctly through WAITING and on to WAITING_EOS?
Created attachment 111283 [details] [review] Patch to avoid race condition that had been causing failure to play pre-rolled stream After a bit more looking at the code and experimenting here is what I think is going on. The preroll_stream function is called to initiate the pre-roll of the new stream but this happens asynchronously finishing in a call to stream_src_blocked_cb which seems to happen in a different thread than the one that was executing preroll_stream. If the pipeline for the new stream completes the pre-roll unexpectedly fast the stream_src_blocked_cb function is called before preroll_stream has finished and preroll_stream overwrites the stream->status value set by stream_src_blocked_cb. After this rb_player_gst_xfade_play sees the wrong status and does not call actually_start_stream hence the pre-rolled stream is never played. The attached patch attempts to stop this happening using a mutex. I have not had a chance to do very much testing yet, but so far it is working.
Great work in tracking down the cause, but I think the solution could be much simpler than that. The race condition you've identified only occurs when the state change returns GST_STATE_CHANGE_ASYNC. In the other cases, the pad block callback has either already been called before gst_element_set_state returns, or it will never be called. Since we already set the stream state to PREROLLING before calling gst_element_set_state, there's no need to do it again afterwards, so just removing that line from the switch statement should have the same effect.
Created attachment 111588 [details] [review] patch to avoid the race condition as per Jonathan Matthew's last comment I have been testing the version of rhythmbox I compiled with my original patch to see if I was right about the cause of the problem and it worked flawlessly. I have now changed to Jonathan Matthew's suggestion of removing the second statement setting the stream state in preroll_stream, i.e. the one attached to the GST_STATE_CHANGE_ASYNC case label and I attach a patch mostly as documentation. So far this is looking good too.
I've committed that change, as it's obviously correct. Any update on whether it actually fixes the problem for you?
My testing suggests that this change has indeed fixed the race condition. Advancing from one track to the next has been very much more reliable for me since applying it whereas cases of getting stuck were pretty common before hand. I did have a strange occurrance a couple of times though which I suspect is yet another different but related problem. This one occurred under heavy load, running a qemu virtual machine while at the same time compiling ardour, and it took me by surprise so I hope I remember the details correctly. Rythmbox is playing track one and, at the end of this fails to advance to track two. Double-clicking track two causes track two to start playing. At the end of track two track three starts playing but track two also starts playing again and the two are mixed together. The two reasons I think is latest issue has a different cause are that the getting stuck due to the race condition addressed above happened often enough that I would regard it as reproducible whereas this latest thing has happened only twice and I could not guarantee to reproduce it and because the two tracks playing at once was not a characteristic of the previous problem. I wonder if this latest issue is caused by the pre-roll completing unexpectedly late (rather than unexpectedly early), i.e. after the previous track has finished playing. The qemu virtual machine takes quite a bit of RAM and so does g++ when compiling ardour so my suspicion is that there was enough paging activity that the pre-roll could not allocate memory and read the file from disk fast enough to be ready in time.
Thanks for confirming. Your analysis sounds fairly likely. I'll take a look at how we can handle that case.
*** Bug 539759 has been marked as a duplicate of this bug. ***
*** Bug 554590 has been marked as a duplicate of this bug. ***
*** Bug 637912 has been marked as a duplicate of this bug. ***
-- GitLab Migration Automatic Message -- This bug has been migrated to GNOME's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.gnome.org/GNOME/rhythmbox/issues/443.