Bug#304233: Sound is messed up when rhythmbox plays the first mp3 song, UI subsequently hangs
Lo?c Minier wrote: Hi, On lun, avr 11, 2005, Kevin Brown wrote: Running rhythmbox with the '-d' option produces no output once the UI has hung. Running it with the 'gst-debug-level=5' option produces the following debug statements continuously, once the UI has hung: DEBUG (0x80d84c8 - 309174:09:41.60618) GST_THREAD(22151) gstthread.c(406):gst_thread_sync:pipeline wait LOG (0x80d84c8 - 309174:09:41.608127000) GST_THREAD(22151) gstthread.c(400):gst_thread_sync:pipeline syncing thread... DEBUG (0x80d84c8 - 309174:09:41.608249000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element src I just read the bug log again, and this seemed like an interesting trail after all. This looks like a dead lock in releasing the playing pipeline. Could you get more of those? Is this happening in a loop? Could you paste the first lines before entering this loop? Yeah, it's happening in a loop, it seems. But note that the loop in question only happens *after* the sound is messed up. At that point, rhythmbox thinks it's playing the song but only a once-per-second pop comes out of the speakers. There are some 7000 lines of debugging info between the time I push the play button and the time I push the pause button. However, the debug output itself has at that point stopped for some time. Here are the last few (well, okay, a little more than a few) lines right before I push the pause button (at this point, the periodic popping sound has been going on for some time without generating any debug output at all): LOG (0x8331e10 - 309872:04:09.890771000) GST_SCHEDULING(19621) gstpad.c(3297):gst_pad_push:audioconvert:src calling chainhandler gst_pad_call_chain_function of peer pad audioscale:sink LOG (0x8331e10 - 309872:04:09.890886000)GST_DATAFLOW(19621) gstpad.c(4496):gst_pad_call_chain_function:audioscale:sink calling chain function with buffer 0x8109104 (size 2048, refcount 1) DEBUG (0x8331e10 - 309872:04:09.891037000) audioscale(19621) gstaudioscale.c(617):gst_audioscale_chain: gst_audioscale_chain: got buffer of 2048 bytes in 'audioscale' DEBUG (0x8331e10 - 309872:04:09.891163000) audioscale(19621) gstaudioscale.c(622):gst_audioscale_chain: doing gstresample DEBUG (0x8331e10 - 309872:04:09.891538000) audioscale(19621) gstaudioscale.c(394):gst_audioscale_get_buffer: size requested: 3970 irate: 1.00 orate: 1.953125 LOG (0x8331e10 - 309872:04:09.891766000) GST_BUFFER(19621) gstbuffer.c(211):gst_buffer_new: new 0x8109178 LOG (0x8331e10 - 309872:04:09.894545000) GST_BUFFER(19621) gstdata.c(239):gst_data_unref: 0x8109104 1-0 DEBUG (0x8331e10 - 309872:04:09.894743000) audioscale(19621) gstaudioscale.c(633):gst_audioscale_chain: doing gst_audioscale_increase_rate LOG (0x8331e10 - 309872:04:09.89492) GST_BUFFER(19621) gstbuffer.c(211):gst_buffer_new: new 0x8109104 DEBUG (0x8331e10 - 309872:04:09.895049000) audioscale(19621) gstaudioscale.c(462):gst_audioscale_increase_rate: iteration = 0 channels = 1 in size = 3970 out size = 7940 out rate = 3.906250 LOG (0x8331e10 - 309872:04:09.895191000) GST_BUFFER(19621) gstdata.c(239):gst_data_unref: 0x8109178 1-0 DEBUG (0x8331e10 - 309872:04:09.895288000) audioscale(19621) gstaudioscale.c(633):gst_audioscale_chain: doing gst_audioscale_increase_rate LOG (0x8331e10 - 309872:04:09.895611000) GST_BUFFER(19621) gstbuffer.c(211):gst_buffer_new: new 0x8109178 DEBUG (0x8331e10 - 309872:04:09.895711000) audioscale(19621) gstaudioscale.c(462):gst_audioscale_increase_rate: iteration = 1 channels = 1 in size = 7940 out size = 15880 out rate = 7.812500 LOG (0x8331e10 - 309872:04:09.895875000) GST_BUFFER(19621) gstdata.c(239):gst_data_unref: 0x8109104 1-0 DEBUG (0x8331e10 - 309872:04:09.895976000) audioscale(19621) gstaudioscale.c(633):gst_audioscale_chain: doing gst_audioscale_increase_rate LOG (0x8331e10 - 309872:04:09.896072000) GST_BUFFER(19621) gstbuffer.c(211):gst_buffer_new: new 0x8109104 DEBUG (0x8331e10 - 309872:04:09.896166000) audioscale(19621) gstaudioscale.c(462):gst_audioscale_increase_rate: iteration = 2 channels = 1 in size = 15880 out size = 31760 out rate = 15.625000 LOG (0x8331e10 - 309872:04:09.896583000) GST_BUFFER(19621) gstdata.c(239):gst_data_unref: 0x8109178 1-0 DEBUG (0x8331e10 - 309872:04:09.896737000) audioscale(19621) gstaudioscale.c(633):gst_audioscale_chain: doing gst_audioscale_increase_rate LOG (0x8331e10 - 309872:04:09.896844000) GST_BUFFER(19621) gstbuffer.c(211):gst_buffer_new: new 0x8109178 DEBUG (0x8331e10 - 309872:04:09.896968000) audioscale(19621) gstaudioscale.c(462):gst_audioscale_increase_rate: iteration = 3 channels = 1 in size = 31760 out size = 63520 out rate = 31.25 LOG (0x8331e10 - 309872:04:09.897503000) GST_BUFFER(19621) gstdata.c(239):gst_data_unref: 0x8109104 1-0
Bug#304233: Sound is messed up when rhythmbox plays the first mp3 song, UI subsequently hangs
Lo?c Minier wrote: Hi, On mar, avr 12, 2005, Kevin Brown wrote: I tried it (the command line using gst-launch-0.8, right?) and it works perfectly -- it does *not* reproduce the problem. That's weird. From reading the file, to outputing a resampled audio stream, through the MP3/OGG decoding, everything is done by GStreamer in Rhythmbox. How's it done? In a thread within the same memory space as rhythmbox, or as a separate process? What audiosink are you using? (you can check with the gconf subcommand in the example) The default, which appears to be osssink. Could you try with other sinks such as esdsink, alsasink, and osssink? I get the same results will all the other audio sinks you mentioned (esdsink and alsasink). Strange, that -- I would have thought that some of them would just fail outright. I tried modifying both /system/gstreamer/0.8/default/audiosink and /system/gstreamer/default/audiosink (the latter defaults to osssink sync=false) Hmm...since it doesn't seem to reproduce the problem, what next? :-) Please run rhythmbox -d and paste the relevant part of the output in this report. OK, see attached. The whole thing was far too large to reasonably include, so I'm including only the bit that occurs after I press the play button. With any luck, it'll prove useful, but if you need the whole thing just let me know... Please try playing a file with totem. That seemed to work without issue. Sounds to me like the problem is with the UI component somehow interfering with the streamer... The UI wouldn't happen to check on the streamer every, say, half a second, would it? :-) -- Kevin Brown [EMAIL PROTECTED] Script started on Tue Apr 12 23:54:16 2005 [EMAIL PROTECTED]:/tmp/[EMAIL PROTECTED]:/tmp/rhythmbox$ rhythmbox -d [0x80d84c0] [rb_debug_init] rb-debug.c:129 (23:54:27): Debugging enabled [0x80d84c0] [main] main.c:177 (23:54:27): initializing Rhythmbox 0.8.8 [0x80d84c0] [main] main.c:191 (23:54:27): Going to create a new shell ...lots more debugging output... ...at this point, I've selected one song out of the list for playback, and I now press the play button... [0x80d84c0] [queue_changed_sig] rb-entry-view.c:1645 (23:54:44): queueing changed signal [0x80d84c0] [rb_shell_clipboard_entryview_changed_cb] rb-shell-clipboard.c:556 (23:54:45): entryview changed [0x80d84c0] [rb_shell_clipboard_sync] rb-shell-clipboard.c:364 (23:54:45): syncing clipboard [0x80d84c0] [rb_shell_player_entry_view_changed_cb] rb-shell-player.c:1515 (23:54:45): entry view changed [0x80d84c0] [rb_shell_player_sync_buttons] rb-shell-player.c:1684 (23:54:45): syncing with source 0x829e200 [0x80d84c0] [rb_shell_player_set_play_button] rb-shell-player.c:1577 (23:54:45): setting play button [0x80d84c0] [rb_statusbar_entry_view_changed_cb] rb-statusbar.c:582 (23:54:45): entry view changed [0x80d84c0] [rb_shell_player_playpause] rb-shell-player.c:1319 (23:54:47): no playing source, using selected source [0x80d84c0] [rb_shell_player_set_playing_source_internal] rb-shell-player.c:1764 (23:54:47): setting playing source to 0x829e200 [0x80d84c0] [rb_shell_player_sync_with_source] rb-shell-player.c:1621 (23:54:47): playing source: 0x829e200, active entry: (nil) [0x80d84c0] [rb_shell_set_window_title] rb-shell.c:2050 (23:54:47): clearing title [0x80d84c0] [rb_header_sync] rb-header.c:489 (23:54:47): syncing with node = (nil) [0x80d84c0] [rb_header_sync] rb-header.c:580 (23:54:47): not playing [0x80d84c0] [rb_shell_player_sync_buttons] rb-shell-player.c:1684 (23:54:47): syncing with source 0x829e200 [0x80d84c0] [rb_shuffle_play_order_get_next] rb-play-order-shuffle.c:196 (23:54:47): choosing current entry in shuffle [0x80d84c0] [rb_shell_player_set_play_button] rb-shell-player.c:1577 (23:54:47): setting play button [0x80d84c0] [rb_shell_player_playpause] rb-shell-player.c:1329 (23:54:47): choosing first selected entry [0x80d84c0] [rb_shell_player_open_location] rb-shell-player.c:848 (23:54:47): Opening file:///export/home/kevin/mp3/talk_talk/the_very_best_of_natural_history/02.mp3... [0x80d84c0] [rb_player_construct] rb-player-gst.c:457 (23:54:47): constructing element pipeline [0x80d84c0] [rb_player_construct] rb-player-gst.c:506 (23:54:47): constructing queue [0x80d84c0] [rb_player_construct] rb-player-gst.c:519 (23:54:47): constructing element typefind [0x80d84c0] [rb_player_construct] rb-player-gst.c:522 (23:54:47): constructing element decoder [0x80d84c0] [rb_player_construct] rb-player-gst.c:525 (23:54:47): constructing element volume [0x80d84c0] [rb_player_construct] rb-player-gst.c:534 (23:54:47): constructing element audioconvert [0x80d84c0] [rb_player_construct] rb-player-gst.c:537 (23:54:47): constructing element audioscale [0x80d84c0] [rb_player_construct] rb-player-gst.c:576 (23:54:47): pipeline construction complete [0x80d84c0] [rb_player_sync_pipeline] rb-player-gst.c:627 (23:54:47): syncing
Bug#304233: Sound is messed up when rhythmbox plays the first mp3 song, UI subsequently hangs
Lo?c Minier wrote: Hi, On Mon, Apr 11, 2005, Kevin Brown wrote: Immediately after starting rhythmbox, when I tell it to begin playing any mp3 (I haven't tested with other file types), rhythmbox thinks it's playing the song but instead what comes out via the audio is a series of pops of descending volume, at half-second intervals (until the volume fades to nothing -- the series of pops will reappear and then disappear in the same way every couple of minutes). Thanks for your report. Did you check whether the command line described in the README/README.Debian has the same problem? Wasn't even aware of that. I tried it (the command line using gst-launch-0.8, right?) and it works perfectly -- it does *not* reproduce the problem. If it does suffer from the same problem, please try the patch at https://bugzilla.ubuntu.com/show_bug.cgi?id=7359 or the Ubuntu GStreamer packages. Hmm...since it doesn't seem to reproduce the problem, what next? :-) I can take source code patches and apply them to the current -unstable rhythmbox source if necessary. -- Kevin Brown [EMAIL PROTECTED] -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of unsubscribe. Trouble? Contact [EMAIL PROTECTED]
Bug#304233: Sound is messed up when rhythmbox plays the first mp3 song, UI subsequently hangs
I wrote: I can take source code patches and apply them to the current -unstable rhythmbox source if necessary. Meaning I'd be happy to apply patches against the current -unstable source code that will generate enough debugging info to help you get to the bottom of this, if that'll help. -- Kevin Brown [EMAIL PROTECTED] -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of unsubscribe. Trouble? Contact [EMAIL PROTECTED]
Bug#304233: Sound is messed up when rhythmbox plays the first mp3 song, UI subsequently hangs
---BeginMessage--- Package: rhythmbox Version: 0.8.8-11 Severity: important The following is completely reproducible, every time: Immediately after starting rhythmbox, when I tell it to begin playing any mp3 (I haven't tested with other file types), rhythmbox thinks it's playing the song but instead what comes out via the audio is a series of pops of descending volume, at half-second intervals (until the volume fades to nothing -- the series of pops will reappear and then disappear in the same way every couple of minutes). When this occurs (and it always happens with this version of rhythmbox), any attempt to use the UI to change any aspect of what rhythmbox thinks it's playing (like pausing the song, or telling it to play a different song), will cause the UI to hang, to the point that it doesn't even redraw when a window is positioned over it and then moved out of the way. If I instead first have rhythmbox connect to an internet radio source, it works fine, and I'm subsequently able to select music files to be played without any problems with the sound or the UI (I have had the UI hang on me in much the same way when telling it to play from a different location within the current song, however). The number of entries in the library is of no consequence -- the same behaviour occurs whether there is only one entry or hundreds. Running rhythmbox with the '-d' option produces no output once the UI has hung. Running it with the 'gst-debug-level=5' option produces the following debug statements continuously, once the UI has hung: DEBUG (0x80d84c8 - 309174:09:41.60618) GST_THREAD(22151) gstthread.c(406):gst_thread_sync:pipeline wait LOG (0x80d84c8 - 309174:09:41.608127000) GST_THREAD(22151) gstthread.c(400):gst_thread_sync:pipeline syncing thread... DEBUG (0x80d84c8 - 309174:09:41.608249000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element src DEBUG (0x80d84c8 - 309174:09:41.608336000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element typefind DEBUG (0x80d84c8 - 309174:09:41.608423000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element decoder DEBUG (0x80d84c8 - 309174:09:41.608511000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element volume DEBUG (0x80d84c8 - 309174:09:41.608597000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element audioconvert DEBUG (0x80d84c8 - 309174:09:41.608683000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element audioscale DEBUG (0x80d84c8 - 309174:09:41.608769000) GST_THREAD(22151) gstthread.c(332):gst_thread_release_children_locks:pipeline waking element bin0 -- System Information: Debian Release: 3.1 APT prefers unstable APT policy: (990, 'unstable'), (500, 'testing') Architecture: i386 (i686) Kernel: Linux 2.6.10-1-686 Locale: LANG=C, LC_CTYPE=C (charmap=ANSI_X3.4-1968) Versions of packages rhythmbox depends on: ii gconf2 2.8.1-5 GNOME configuration database syste ii gstreamer0.8-flac0.8.8-3 FLAC plugin for GStreamer ii gstreamer0.8-gnomevf 0.8.8-3 Gnome VFS plugin for GStreamer ii gstreamer0.8-mad 0.8.8-3 MAD MPEG audio decoder plugin for ii gstreamer0.8-misc0.8.8-3 Collection of various GStreamer pl ii gstreamer0.8-oss [gs 0.8.8-3 OSS plugin for GStreamer ii gstreamer0.8-vorbis 0.8.8-3 Vorbis plugin for GStreamer ii libart-2.0-2 2.3.17-1Library of functions for 2D graphi ii libatk1.0-0 1.8.0-4 The ATK accessibility toolkit ii libaudiofile00.2.6-6 Open-source version of SGI's audio ii libbonobo2-0 2.8.1-2 Bonobo CORBA interfaces library ii libbonoboui2-0 2.8.1-2 The Bonobo UI library ii libc62.3.2.ds1-20GNU C Library: Shared libraries an ii libesd0 0.2.35-2Enlightened Sound Daemon - Shared ii libgconf2-4 2.8.1-5 GNOME configuration database syste ii libgcrypt11 1.2.0-11LGPL Crypto library - runtime libr ii libglade2-0 1:2.4.2-2 library to load .glade files at ru ii libglib2.0-0 2.6.4-1 The GLib library of C routines ii libgnome-keyring00.4.2-1 GNOME keyring services library ii libgnome2-0 2.8.1-2 The GNOME 2 library - runtime file ii libgnomecanvas2-02.8.0-1 A powerful object-oriented display ii libgnomeui-0 2.8.1-3 The GNOME 2 libraries (User Interf ii libgnomevfs2-0 2.8.4-2 The GNOME virtual file-system libr ii libgnutls11 1.0.16-13 GNU TLS library - runtime library ii libgpg-error0
