After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 484210 - crossfade backend can't preroll some files
crossfade backend can't preroll some files
Status: RESOLVED OBSOLETE
Product: rhythmbox
Classification: Other
Component: playback
0.11.x
Other All
: Normal normal
: ---
Assigned To: RhythmBox Maintainers
RhythmBox Maintainers
: 511616 539759 554590 637912 (view as bug list)
Depends on:
Blocks:
 
 
Reported: 2007-10-06 18:30 UTC by freggy1
Modified: 2018-05-24 12:54 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
fix preroll queue size (1.41 KB, patch)
2008-05-08 10:45 UTC, Jonathan Matthew
committed Details | Review
Debug Log (12.53 KB, text/plain)
2008-05-12 21:46 UTC, Steve Fosdick
  Details
Patch to avoid race condition that had been causing failure to play pre-rolled stream (917 bytes, patch)
2008-05-21 16:56 UTC, Steve Fosdick
none Details | Review
patch to avoid the race condition as per Jonathan Matthew's last comment (276 bytes, patch)
2008-05-27 08:19 UTC, Steve Fosdick
committed Details | Review

Description freggy1 2007-10-06 18:30:49 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
Comment 1 Jonathan Matthew 2007-10-24 12:05:07 UTC
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.
Comment 2 Jonathan Matthew 2008-02-05 11:30:48 UTC
*** Bug 511616 has been marked as a duplicate of this bug. ***
Comment 3 freggy1 2008-03-04 22:03:18 UTC
Is this a bug in gstreamer or in rhythmbox?
Comment 4 James Gregory 2008-05-05 08:31:12 UTC
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.
Comment 5 Steve Fosdick 2008-05-07 15:10:02 UTC
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
Comment 6 Jonathan Matthew 2008-05-08 10:45:48 UTC
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.
Comment 7 Tino Meinen 2008-05-10 00:13:28 UTC
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!
Comment 8 Tino Meinen 2008-05-10 11:33:04 UTC
Oh, perhaps the patch is missing a changelog entry telling what it does and what bug it fixed.
Comment 9 Steve Fosdick 2008-05-12 21:39:26 UTC
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.
Comment 10 Steve Fosdick 2008-05-12 21:46:26 UTC
Created attachment 110808 [details]
Debug Log
Comment 11 Jonathan Matthew 2008-05-13 01:05:32 UTC
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.
Comment 12 Jonathan Matthew 2008-05-14 08:31:43 UTC
I've committed the patch, but apparently there are other problems here, so I'm leaving the bug open.
Comment 13 Steve Fosdick 2008-05-14 09:45:08 UTC
(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?
Comment 14 Jonathan Matthew 2008-05-14 23:13:34 UTC
(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.
Comment 15 Tino Meinen 2008-05-19 02:03:05 UTC
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!

Comment 16 Steve Fosdick 2008-05-21 10:56:52 UTC
(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.

Comment 17 Christophe Fergeau 2008-05-21 11:00:50 UTC
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.
Comment 18 Steve Fosdick 2008-05-21 12:28:41 UTC
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?
Comment 19 Steve Fosdick 2008-05-21 16:56:53 UTC
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.
Comment 20 Jonathan Matthew 2008-05-22 06:02:03 UTC
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.
Comment 21 Steve Fosdick 2008-05-27 08:19:39 UTC
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.
Comment 22 Jonathan Matthew 2008-06-07 02:06:02 UTC
I've committed that change, as it's obviously correct.  Any update on whether it actually fixes the problem for you?
Comment 23 Steve Fosdick 2008-06-07 11:25:25 UTC
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.
Comment 24 Jonathan Matthew 2008-06-07 23:44:50 UTC
Thanks for confirming.

Your analysis sounds fairly likely.  I'll take a look at how we can handle that case.
Comment 25 Jonathan Matthew 2008-06-23 21:39:15 UTC
*** Bug 539759 has been marked as a duplicate of this bug. ***
Comment 26 Jonathan Matthew 2008-10-01 22:26:12 UTC
*** Bug 554590 has been marked as a duplicate of this bug. ***
Comment 27 André Klapper 2017-03-07 21:18:03 UTC
*** Bug 637912 has been marked as a duplicate of this bug. ***
Comment 28 GNOME Infrastructure Team 2018-05-24 12:54:23 UTC
-- 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.