Project

General

Profile

Bug #806

Deadlock when updating song info

Added by Tom Thorogood almost 6 years ago. Updated almost 6 years ago.

Status:
Closed
Priority:
Major
Assignee:
-
Category:
libaudcore
Target version:
3.10
Start date:
July 10, 2018
Due date:
% Done:

100%

Estimated time:
Affects version:
3.9

Description

I'm running into a deadlock pretty consistently when clicking Save in the Song Info window. It happens about half the time and may occur the first time the window is opened or later.

To reproduce, I:
- add a new mp3 to my playlist,
- open the Song Info window,
- fill in the info,
- press Save.

I was able to capture the following backtrace running under gdb:

Thread 49 (Thread 0x7fff9702b700 (LWP 12328)):
#0  0x00007ffff79707fd in __lll_lock_wait () at /lib64/libpthread.so.0
#1  0x00007ffff7969cf4 in pthread_mutex_lock () at /lib64/libpthread.so.0
#2  0x00007ffff7b9f8c9 in output_set_tuple(Tuple const&) (tuple=...) at output.cc:452
#3  0x00007ffff7ba14b3 in playback_set_info(int, Tuple&&) (entry=0, tuple=...) at playback.cc:155
#4  0x00007ffff7ba318e in pl_signal_update_queued(Playlist::ID*, Playlist::UpdateLevel, int) (id=<optimized out>, level=Playlist::Metadata, flags=2) at playlist.cc:542
#5  0x00007ffff7ba8368 in PlaylistData::update_entry_from_scan(PlaylistEntry*, ScanRequest*, int) (this=0x55555583b5e0, entry=0x5555559ce2d0, request=0x555555c88660, update_flags=2) at playlist-data.cc:1019
#6  0x00007ffff7ba2bef in scan_finish(ScanRequest*) (request=0x555555c88660) at playlist.cc:420
#7  0x00007ffff7bb0bfa in ScanRequest::run() (this=0x555555c88660) at scanner.cc:108
#8  0x00007ffff7bb0d92 in scan_worker(void*, void*) (data=0x555555c88660) at scanner.cc:113
#9  0x00007ffff70c7933 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#10 0x00007ffff70c6f2a in g_thread_proxy () at /lib64/libglib-2.0.so.0
#11 0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#12 0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 48 (Thread 0x7fffae8d0700 (LWP 12280)):
#0  0x00007ffff64445a9 in poll () at /lib64/libc.so.6
#1  0x00007fffe23cb016 in pump(void*) () at /usr/lib64/audacious/Output/alsa.so
#2  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#3  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 47 (Thread 0x7fffaf2d5700 (LWP 12279)):
#0  0x00007ffff64445a9 in poll () at /lib64/libc.so.6
#1  0x00007fffe1ca0d75 in  () at /lib64/libpulse.so.0
#2  0x00007fffe1c92368 in pa_mainloop_poll () at /lib64/libpulse.so.0
#3  0x00007fffe1c929b2 in pa_mainloop_iterate () at /lib64/libpulse.so.0
#4  0x00007fffe1c92a60 in pa_mainloop_run () at /lib64/libpulse.so.0
#5  0x00007fffe1ca0cbd in  () at /lib64/libpulse.so.0
#6  0x00007fffe1a3f98c in  () at /usr/lib64/pulseaudio/libpulsecommon-11.1.so
#7  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#8  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 7 (Thread 0x7fffce8a7700 (LWP 5480)):
#0  0x00007ffff796d52c in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007fffe23cae34 in ALSAPlugin::period_wait() () at /usr/lib64/audacious/Output/alsa.so
#2  0x00007ffff7b9ed25 in write_output(Index<float>&) (data=...) at output.cc:362
#3  0x00007ffff7b9fe4a in output_write_audio(void const*, int, int) (data=data@entry=0x7fffce8a2bf0, size=size@entry=16384, stop_time=<optimized out>) at output.cc:402
#4  0x00007ffff7ba194f in InputPlugin::write_audio(void const*, int) (data=0x7fffce8a2bf0, length=16384) at playback.cc:548
#5  0x00007fffcdca16ba in MPG123Plugin::play(char const*, VFSFile&) () at /usr/lib64/audacious/Input/madplug.so
#6  0x00007ffff7ba0e14 in run_playback () at ../libaudcore/objects.h:194
#7  0x00007ffff7ba0e14 in playback_thread(void*) () at playback.cc:401
#8  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#9  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 6 (Thread 0x7fffcf2ac700 (LWP 5479)):
#0  0x00007ffff64445a9 in poll () at /lib64/libc.so.6
#1  0x00007fffe1ca0d75 in  () at /lib64/libpulse.so.0
#2  0x00007fffe1c92368 in pa_mainloop_poll () at /lib64/libpulse.so.0
#3  0x00007fffe1c929b2 in pa_mainloop_iterate () at /lib64/libpulse.so.0
#4  0x00007fffe1c92a60 in pa_mainloop_run () at /lib64/libpulse.so.0
#5  0x00007fffe1ca0cbd in  () at /lib64/libpulse.so.0
#6  0x00007fffe1a3f98c in  () at /usr/lib64/pulseaudio/libpulsecommon-11.1.so
#7  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#8  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 5 (Thread 0x7fffe2dd1700 (LWP 5478)):
#0  0x00007ffff638cccc in sigtimedwait () at /lib64/libc.so.6
#1  0x00007ffff7971b4c in sigwait () at /lib64/libpthread.so.0
#2  0x000055555555ee1b in signal_thread(void*) (data=<optimized out>) at signals.cc:35
#3  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#4  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 3 (Thread 0x7fffe3dd3700 (LWP 5476)):
#0  0x00007ffff64445a9 in poll () at /lib64/libc.so.6
#1  0x00007ffff709ebe6 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007ffff709efa2 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007ffff768f6ba in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007ffff70c6f2a in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#6  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 2 (Thread 0x7fffe45d4700 (LWP 5475)):
#0  0x00007ffff64445a9 in poll () at /lib64/libc.so.6
#1  0x00007ffff709ebe6 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007ffff709ed10 in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007ffff709ed61 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007ffff70c6f2a in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007ffff7967594 in start_thread () at /lib64/libpthread.so.0
#6  0x00007ffff644f02f in clone () at /lib64/libc.so.6

Thread 1 (Thread 0x7ffff7fbd940 (LWP 5462)):
#0  0x00007ffff79707fd in __lll_lock_wait () at /lib64/libpthread.so.0
#1  0x00007ffff7969cf4 in pthread_mutex_lock () at /lib64/libpthread.so.0
#2  0x00007ffff7ba1bc1 in lock () at playback.cc:627
#3  0x00007ffff7ba1bc1 in aud_drct_get_playing() () at playback.cc:627
#4  0x00007fffacc199d0 in update(void*) () at /usr/lib64/audacious/General/mpris2.so
#5  0x00007ffff7bb17c5 in timer_run(void*) (list_=0x7ffff7dd5920 <lists+32>) at timer.cc:87
#6  0x00007ffff7b9dc83 in QueuedFuncHelper::run() (this=0x555555a64fc0) at mainloop.cc:136
#7  0x00007ffff7b9dcad in QueuedFuncHelper::<lambda(void*)>::operator() (__closure=0x0, me=0x7ffff7dd5440 <_ZL5mutex>) at mainloop.cc:152
#8  0x00007ffff7b9dcad in QueuedFuncHelper::<lambda(void*)>::_FUN(void *) () at mainloop.cc:154
#9  0x00007ffff709f371 in g_timeout_dispatch () at /lib64/libglib-2.0.so.0
#10 0x00007ffff709e8ad in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#11 0x00007ffff709ec78 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#12 0x00007ffff709efa2 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#13 0x00007fffcccb595f in gtk_main () at /lib64/libgtk-x11-2.0.so.0
#14 0x00007ffff7b9d30e in interface_run() () at interface.cc:163
#15 0x00007ffff7bb0716 in aud_run() () at runtime.cc:323
#16 0x000055555555e424 in main (argc=<optimized out>, argv=<optimized out>) at main.cc:395
#17 0x00007ffff637818b in __libc_start_main () at /lib64/libc.so.6
#18 0x000055555555ea5a in _start () at main.cc:410

I'm not familiar with the audacious codebase and couldn't figure out what's causing this, but I'm pretty sure it's deadlocking on a mutex or something similar. (There is no abnormal CPU usage suggesting any sort of infinite loop).

The audio output plug-in is ALSA Output, ReplayGain is enabled, and the following plugins are enabled:
- Audio CD Menu Items,
- Desktop Notifications,
- MPRIS 2 Server,
- ModPlug (Module Player),
- MPG123 Plugin,
- Tact Generator,
- Tone Generator,
- WavPack Decoder,
- FLAC Decoder,
- Ogg Vorbis Decoder,
- Sndfile Plugin,
- ASXv1/ASXv2 Playlists,
- ASXv3 Playlists,
- Audacious Playlists (audpl),
- Cue Sheet Plugin,
- M3U Playlists,
- PLS Playlists,
- XML ShHareable Playlists (XSPF),
- GIO Plugin,
- Neon HTTP/HTTPS Plugin.

I'm running this on Fedora 28 (but I'm pretty sure I had the same problem under 27). The versions I have installed are:

audacious.x86_64                           3.9-3.fc28                   @fedora 
audacious-debuginfo.x86_64                 3.9-3.fc28                   @fedora-debuginfo
audacious-debugsource.x86_64               3.9-3.fc28                   @fedora-debuginfo
audacious-libs.x86_64                      3.9-3.fc28                   @fedora 
audacious-libs-debuginfo.x86_64            3.9-3.fc28                   @fedora-debuginfo
audacious-plugins.x86_64                   3.9-6.fc28                   @fedora 
audacious-plugins-debuginfo.x86_64         3.9-6.fc28                   @fedora-debuginfo
audacious-plugins-debugsource.x86_64       3.9-6.fc28                   @fedora-debuginfo

History

#1 Updated by John Lindgren almost 6 years ago

I think I see what is going on here.

Thread 7 (decoder/output) is waiting for space in the output buffer. I'm guessing you had Audacious paused at this point, so it might be waiting a while, which is okay.
Thread 49 (background worker) is waiting on Thread 7 (decoder/output). This is unnecessary and causes Thread 49 to hang.
Thread 1 (GUI) is waiting on Thread 49, which would normally be okay if Thread 49 weren't stuck.

Please see if this fixes the problem:
https://github.com/audacious-media-player/audacious/commit/34dc86b67a830e63de9094affa6f069d0bb3ca83

#2 Updated by John Lindgren almost 6 years ago

Thanks for the excellently detailed report, by the way.

#3 Updated by John Lindgren almost 6 years ago

  • % Done changed from 0 to 100
  • Target version set to 3.10
  • Status changed from New to Closed
  • Category set to libaudcore

Okay, I can reproduce this pretty easily as well, and the change above does fix it.

Key step to reproducing is to edit and try to save the tag of the currently playing song, while it's paused.

#4 Updated by Tom Thorogood almost 6 years ago

Wonderful John, thank you for getting to the bottom of this! It didn't click that it was always the paused song.

I had trouble getting it to run after building from source so I can't verify the fix. If you can reproduce, I'm sure it is though.

Thanks again.

#5 Updated by Tom Thorogood almost 6 years ago

I've managed to build audacious at 31b5f7fa0e (one ahead of the fix), and I can't reproduce anymore. I'm quite sure it's fixed.

Thanks heaps.

Also available in: Atom PDF