Opened 10 years ago
Closed 6 years ago
#6638 closed defect (fixed)
RINGWORLD2: Game sometimes hangs in flup tube system (may affect other TsAGE games as well)
| Reported by: | eriktorbjorn | Owned by: | csnover |
|---|---|---|---|
| Priority: | blocker | Component: | Engine: TsAGE |
| Version: | Keywords: | has-save-game, has-backtrace, has-pull-request | |
| Cc: | Game: | Return to Ringworld |
Description
I can't really provide any steps to reproducing this, but twice now the game has hung while trying to navigate the flup tube system. (For a savegame, see bug #6636.)
Both times it happened while trying to navigate a tight corner, so there was a lot of banging into walls. I attached GDB to the running process, and apparently it's hanging on a mutex in the mixer. Here is a stack trace:
~~~~
0 0xb778d424 in __kernel_vsyscall ()
1 0xb6c33672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb6c2f1c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb6c2f043 in __GI___pthread_mutex_lock (mutex=0xa5f41b8)
at ../nptl/pthread_mutex_lock.c:114
4 0xb7056cc4 in pthread_mutex_lock (mutex=0xa5f41b8) at forward.c:192
5 0xb7713c7f in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x0936d41b in SdlMutexManager::lockMutex (this=0xa52c240, mutex=0xa5f41b8)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0935d3df in ModularBackend::lockMutex (this=0xa4f7028, mutex=0xa5f41b8)
at backends/modular-backend.cpp:222
8 0x094778b0 in Common::StackLock::lock (this=0xbf99d8c0)
at common/mutex.cpp:68
9 0x0947784a in Common::StackLock::StackLock (this=0xbf99d8c0, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x09417d98 in Audio::MixerImpl::isSoundHandleActive (this=0xa6c2a98,
handle=...) at audio/mixer.cpp:452
11 0x091571e6 in TsAGE::SoundBlasterDriver::updateVoice (this=0xa7ba120,
channel=0) at engines/tsage/sound.cpp:3131
12 0x09151250 in TsAGE::SoundManager::sfRethinkVoiceTypes ()
at engines/tsage/sound.cpp:1273
13 0x0914ef90 in TsAGE::SoundManager::sfAddToPlayList (sound=0xa7ec504)
at engines/tsage/sound.cpp:625
14 0x0914e4a5 in TsAGE::SoundManager::addToPlayList (this=0xa797d40,
sound=0xa7ec504) at engines/tsage/sound.cpp:357
15 0x091524e0 in TsAGE::Sound::play (this=0xa7ec504, soundNum=276)
at engines/tsage/sound.cpp:1564
16 0x09154fc8 in TsAGE::ASound::play (this=0xa7ec4fc, soundNum=276, endAction=
0x0, volume=127) at engines/tsage/sound.cpp:2472
17 0x09134cdc in TsAGE::Ringworld2::Scene3500::dispatch (this=0xa7eaed8)
at engines/tsage/ringworld2/ringworld2_scenes3.cpp:4261
18 0x08fea2fa in TsAGE::SceneHandler::dispatch (this=0xa73f068)
at engines/tsage/core.cpp:4459
19 0x09085e1d in TsAGE::Ringworld2::SceneHandlerExt::dispatch (this=0xa73f068)
at engines/tsage/ringworld2/ringworld2_logic.cpp:630
20 0x08fe988c in TsAGE::GameHandler::execute (this=0xa73f068)
at engines/tsage/core.cpp:4263
21 0x0914d244 in TsAGE::Game::execute (this=0xa73f058)
at engines/tsage/scenes.cpp:617
22 0x08fd8ef7 in TsAGE::TSageEngine::run (this=0xa5f3400)
at engines/tsage/tsage.cpp:134
23 0x08051e5b in runGame (plugin=0xa547e48, system=..., edebuglevels=...)
at base/main.cpp:244
24 0x08052d9b in scummvm_main (argc=4, argv=0xbf9e3be4) at base/main.cpp:489
25 0x08050af9 in main (argc=4, argv=0xbf9e3be4)
at backends/platform/sdl/posix/posix-main.cpp:45
~~~~
Ticket imported from: bugs/6638.
Attachments (1)
Change History (24)
comment:1 by , 10 years ago
comment:2 by , 10 years ago
I added some debug messages to mutex locking/unlocking (easier than I thought, since we already have the option of naming mutexes) and then deliberately flew into walls until it hung.
From the look of it, it locked the mutex from MixerImpl::mixCallback(), which is what you would expect. From there it probably called readBuffer() to get the audio data, and at some point before that terminated it called MixerImpl::setChannelVolume(), which tried to lock the already locked mutex.
That's probably not quite the same spot as in the backtrace above, but the point is that readBuffer() must not be allowed to do anything that waits for the mixer mutex to become unlocked, because that's not going to happen until after readBuffer() finishes. Or at least, that's how I understand it.
comment:3 by , 10 years ago
| Summary: | RINGWORLD2: Game sometimes hangs in flup tube system → RINGWORLD2: Game sometimes hangs in flup tube system (may affect other TsAGE games as well) |
|---|
comment:4 by , 10 years ago
So in summary, my understanding is that the problem is that we call the mixer from within readBuffer(), i.e. from within the mixer callback when the mutex is already locked.
To fix the problem, we'd either have to stop doing that, or the mixer would have to provide alternative versions of those functions that are safe to call from within the mixer callback. Though that would probably still require some rewriting in TsAGE because I think this is code that's also called from the main thread.
comment:5 by , 10 years ago
I am not sure whether I understand you correctly, but: When you call the Mixer from within the Mixer's callback, like in readBuffer, that shouldn't be an issue because we allow recursive locking, i.e. you can lock a mutex multiple times from the same thread.
I think it would be helpful if you can get a backtrace of both the main thread and the audio thread. Probably the audio thread tries to lock an mutex from within TsAGE which is already locked from the main thread. For example, in the backtrace TsAGE::SoundManager::sfRethinkVoiceTypes is called which locks an TsAGE internal mutex. This same mutex is also locked inside TsAGE::AdlibSoundDriver::readBuffer, which is called from the audio thread. So, my guess is that this mutex in TsAGE itself is locked from the main thread. Then the audio thread kicks in and waits for the TsAGE mutex to be unlocked. The main thread in the meantime waits for the Mixer mutex to be unlocked (which won't happen because now TsAGE::SoundBlasterDriver::updateVoice waits for the Mixer mutex to be unlocked).
comment:6 by , 10 years ago
I did not know you could lock the mutex recursively like that. Maybe I've been barking up the wrong tree, but I could have sworn that the sound stopped...
I've made two more attempts at reproducing the hang, but so far I've only got what I think is a completely different hang, where sound keeps playing but the mouse cursor is gone. (I've been using arrow keys rather that clicking on-screen buttons, so maybe I was doing that too quickly for it to keep up, or something silly like that.)
comment:7 by , 10 years ago
Finally got the deadlock again. I think this is the backtrace for all the threads:
~~~~~ Thread 3 (Thread 0xb5fc1b40 (LWP 24901)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb785a0a6 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
2 0xb7f66ed7 in SDL_Delay () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
3 0xb7f66f24 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
4 0xb7f1cea5 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
5 0xb7f6465b in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0xb7471efb in start_thread (arg=0xb5fc1b40) at pthread_create.c:312
7 0xb788efce in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 2 (Thread 0xb67c2b40 (LWP 24900)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb7478672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb74741c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb7474043 in __GI___pthread_mutex_lock (mutex=0x9eefc08)
at ../nptl/pthread_mutex_lock.c:114
4 0xb789bd34 in pthread_mutex_lock (mutex=0x9eefc08) at forward.c:192
5 0xb7f64c7f in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092adc9d in SdlMutexManager::lockMutex (this=0x9e70240, mutex=0x9eefc08)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929e251 in ModularBackend::lockMutex (this=0x9e3b028, mutex=0x9eefc08)
at backends/modular-backend.cpp:222
8 0x093b7489 in Common::StackLock::lock (this=0xb67c2078)
at common/mutex.cpp:68
9 0x093b7424 in Common::StackLock::StackLock (this=0xb67c2078, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x090a5c42 in TsAGE::AdlibSoundDriver::readBuffer (this=0x9ef2b28,
buffer=0xb5300468, numSamples=2048) at engines/tsage/sound.cpp:3029
11 0x09391119 in Audio::CopyRateConverter::flow (
this=0x9ef1500, input=..., obuf=0x9ea8c78, osamp=2048, vol_l=256,
vol_r=256) at audio/rate.cpp:305
12 0x09358e75 in Audio::Channel::mix (this=0x9ef2df0, data=0x9ea8c78,
len=2048) at audio/mixer.cpp:621
13 0x09357ad7 in Audio::MixerImpl::mixCallback (this=0x9e8f0e0,
samples=0x9ea8c78 "", len=2048) at audio/mixer.cpp:293
14 0x092adbc5 in SdlMixerManager::callbackHandler (this=0x9e74390,
samples=0x9ea8c78 "", len=8192) at backends/mixer/sdl/sdl-mixer.cpp:144
15 0x092adc0d in SdlMixerManager::sdlCallback (this_=0x9e74390,
samples=0x9ea8c78 "", len=8192) at backends/mixer/sdl/sdl-mixer.cpp:151
16 0xb7f147db in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
17 0xb7f1cea5 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
18 0xb7f6465b in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
19 0xb7471efb in start_thread (arg=0xb67c2b40) at pthread_create.c:312
20 0xb788efce in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 1 (Thread 0xb6a6a800 (LWP 24898)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb7478672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb74741c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb7474043 in __GI___pthread_mutex_lock (mutex=0x9e9b938)
at ../nptl/pthread_mutex_lock.c:114
4 0xb789bd34 in pthread_mutex_lock (mutex=0x9e9b938) at forward.c:192
5 0xb7f64c7f in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092adc9d in SdlMutexManager::lockMutex (this=0x9e70240, mutex=0x9e9b938)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929e251 in ModularBackend::lockMutex (this=0x9e3b028, mutex=0x9e9b938)
at backends/modular-backend.cpp:222
8 0x093b7489 in Common::StackLock::lock (this=0xbffb9020)
at common/mutex.cpp:68
9 0x093b7424 in Common::StackLock::StackLock (this=0xbffb9020, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x09358572 in Audio::MixerImpl::isSoundHandleActive (this=0x9e8f0e0,
handle=...) at audio/mixer.cpp:452
11 0x090a6093 in TsAGE::SoundBlasterDriver::updateVoice (this=0x9f449e0,
channel=0) at engines/tsage/sound.cpp:3131
12 0x090a0624 in TsAGE::SoundManager::sfRethinkVoiceTypes ()
at engines/tsage/sound.cpp:1273
13 0x0909e3e6 in TsAGE::SoundManager::sfAddToPlayList (sound=0x9f02dd0)
at engines/tsage/sound.cpp:625
14 0x0909d8bf in TsAGE::SoundManager::addToPlayList (this=0x9effec0,
sound=0x9f02dd0) at engines/tsage/sound.cpp:357
15 0x090a16f6 in TsAGE::Sound::play (this=0x9f02dd0, soundNum=14)
at engines/tsage/sound.cpp:1564
16 0x090a3fb2 in TsAGE::ASound::play (this=0x9f02dc8, soundNum=14,
endAction=0x0, volume=63) at engines/tsage/sound.cpp:2472
17 0x09083167 in TsAGE::Ringworld2::Scene3500::process (this=0x9f55100,
event=...) at engines/tsage/ringworld2/ringworld2_scenes3.cpp:3821
18 0x08f50eeb in TsAGE::SceneHandler::process (this=0x9ef1320, event=...)
at engines/tsage/core.cpp:4333
19 0x08fe6cef in TsAGE::Ringworld2::SceneHandlerExt::process (this=0x9ef1320,
event=...) at engines/tsage/ringworld2/ringworld2_logic.cpp:625
20 0x08f51665 in TsAGE::SceneHandler::dispatch (this=0x9ef1320)
at engines/tsage/core.cpp:4469
21 0x08fe6d20 in TsAGE::Ringworld2::SceneHandlerExt::dispatch (this=0x9ef1320)
at engines/tsage/ringworld2/ringworld2_logic.cpp:630
22 0x08f50bae in TsAGE::GameHandler::execute (this=0x9ef1320)
at engines/tsage/core.cpp:4263
23 0x0909c55a in TsAGE::Game::execute (this=0x9ef1310)
at engines/tsage/scenes.cpp:617
24 0x08f40329 in TsAGE::TSageEngine::run (this=0x9e73f60)
at engines/tsage/tsage.cpp:134
25 0x08051f5c in runGame (plugin=0x9e8cd38, system=..., edebuglevels=...)
at base/main.cpp:244
26 0x08052fd3 in scummvm_main (argc=4, argv=0xbffff354) at base/main.cpp:489
27 0x08050ac4 in main (argc=4, argv=0xbffff354)
at backends/platform/sdl/posix/posix-main.cpp:45
~~~~~
comment:8 by , 10 years ago
I should point out that unlike the other hang I mentioned, in the one where it hangs on a mutex the sound has indeed gone quiet. The mouse cursor is visible, but is not being updated.
(In the other one, the sound is playing and the mouse cursor is gone. Code is being executed, but nothing is happening.)
comment:9 by , 10 years ago
I think I've correctly removed mutex locks from my sound code that could result in deadlocks in the main thread versus the calls made by readBuffer in the audio processing thread. But it will still need testing.
by , 10 years ago
| Attachment: | ringworld2-cd.042 added |
|---|
comment:10 by , 10 years ago
I don't know if it's any help whatsoever, but here's a savegame with the game having hung in the non-deadlocky way.
comment:11 by , 10 years ago
It deadlocked again for me:
~~~~~ Thread 3 (Thread 0xb5eb5b40 (LWP 11275)):
0 0xb7701424 in __kernel_vsyscall ()
1 0xb6b9b672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb6b971c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb6b97043 in __GI___pthread_mutex_lock (mutex=0x9f3ef88)
at ../nptl/pthread_mutex_lock.c:114
4 0xb6fbed84 in pthread_mutex_lock (mutex=0x9f3ef88) at forward.c:192
5 0xb7687c7f in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeae3 in SdlMutexManager::lockMutex (this=0x9eb9240, mutex=0x9f3ef88)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f097 in ModularBackend::lockMutex (this=0x9e84028, mutex=0x9f3ef88)
at backends/modular-backend.cpp:222
8 0x093b82c9 in Common::StackLock::lock (this=0xb5eb5078)
at common/mutex.cpp:68
9 0x093b8264 in Common::StackLock::StackLock (this=0xb5eb5078, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x090a6a88 in TsAGE::AdlibSoundDriver::readBuffer (this=0x9f6f4c8,
buffer=0xb4a00468, numSamples=4096) at engines/tsage/sound.cpp:3024
11 0x09391f59 in Audio::CopyRateConverter::flow (
this=0x9f42228, input=..., obuf=0x9ef4028, osamp=4096, vol_l=256,
vol_r=256) at audio/rate.cpp:305
12 0x09359cb5 in Audio::Channel::mix (this=0x9f421e0, data=0x9ef4028,
len=4096) at audio/mixer.cpp:621
13 0x09358917 in Audio::MixerImpl::mixCallback (this=0x9ee6c50,
samples=0x9ef4028 "", len=4096) at audio/mixer.cpp:293
14 0x092aea0b in SdlMixerManager::callbackHandler (this=0x9ebd380,
samples=0x9ef4028 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:143
15 0x092aea53 in SdlMixerManager::sdlCallback (this_=0x9ebd380,
samples=0x9ef4028 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:150
16 0xb76377db in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
17 0xb763fea5 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
18 0xb768765b in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
19 0xb6b94efb in start_thread (arg=0xb5eb5b40) at pthread_create.c:309
20 0xb6fb1fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 2 (Thread 0xb56b4b40 (LWP 11276)):
0 0xb7701424 in __kernel_vsyscall ()
1 0xb6f7d0b6 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
2 0xb7689ed7 in SDL_Delay () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
3 0xb7689f24 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
4 0xb763fea5 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
5 0xb768765b in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0xb6b94efb in start_thread (arg=0xb56b4b40) at pthread_create.c:309
7 0xb6fb1fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 1 (Thread 0xb615d800 (LWP 11273)):
0 0xb7701424 in __kernel_vsyscall ()
1 0xb6b9b672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb6b971c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb6b97043 in __GI___pthread_mutex_lock (mutex=0x9ee54f8)
at ../nptl/pthread_mutex_lock.c:114
4 0xb6fbed84 in pthread_mutex_lock (mutex=0x9ee54f8) at forward.c:192
5 0xb7687c7f in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeae3 in SdlMutexManager::lockMutex (this=0x9eb9240, mutex=0x9ee54f8)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f097 in ModularBackend::lockMutex (this=0x9e84028, mutex=0x9ee54f8)
at backends/modular-backend.cpp:222
8 0x093b82c9 in Common::StackLock::lock (this=0xbf956a00)
at common/mutex.cpp:68
9 0x093b8264 in Common::StackLock::StackLock (this=0xbf956a00, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x09358cd2 in Audio::MixerImpl::setChannelVolume (this=0x9ee6c50,
handle=..., volume=126 '~') at audio/mixer.cpp:351
11 0x090a6f69 in TsAGE::SoundBlasterDriver::proc38 (this=0x9f93da8,
channel=0, cmd=7, value=63) at engines/tsage/sound.cpp:3137
12 0x090a1589 in TsAGE::SoundManager::sfRethinkVoiceTypes ()
at engines/tsage/sound.cpp:1275
13 0x0909f27e in TsAGE::SoundManager::sfAddToPlayList (sound=0x9f52150)
at engines/tsage/sound.cpp:624
14 0x0909e77f in TsAGE::SoundManager::addToPlayList (this=0x9f4f240,
sound=0x9f52150) at engines/tsage/sound.cpp:357
15 0x090a2566 in TsAGE::Sound::play (this=0x9f52150, soundNum=14)
at engines/tsage/sound.cpp:1561
16 0x090a4df8 in TsAGE::ASound::play (this=0x9f52148, soundNum=14, endAction=
0x0, volume=63) at engines/tsage/sound.cpp:2467
17 0x09083fff in TsAGE::Ringworld2::Scene3500::process (this=0x9fc35c0,
event=...) at engines/tsage/ringworld2/ringworld2_scenes3.cpp:3822
18 0x08f51d6d in TsAGE::SceneHandler::process (this=0x9f406e0, event=...)
at engines/tsage/core.cpp:4333
19 0x08fe7b71 in TsAGE::Ringworld2::SceneHandlerExt::process (this=0x9f406e0,
event=...) at engines/tsage/ringworld2/ringworld2_logic.cpp:625
20 0x08f524e7 in TsAGE::SceneHandler::dispatch (this=0x9f406e0)
at engines/tsage/core.cpp:4469
21 0x08fe7ba2 in TsAGE::Ringworld2::SceneHandlerExt::dispatch (this=0x9f406e0)
at engines/tsage/ringworld2/ringworld2_logic.cpp:630
22 0x08f51a30 in TsAGE::GameHandler::execute (this=0x9f406e0)
at engines/tsage/core.cpp:4263
23 0x0909d41a in TsAGE::Game::execute (this=0x9f406d0)
at engines/tsage/scenes.cpp:617
24 0x08f411ab in TsAGE::TSageEngine::run (this=0x9ed7b28)
at engines/tsage/tsage.cpp:134
25 0x08051f5c in runGame (plugin=0x9ed80d0, system=..., edebuglevels=...)
at base/main.cpp:244
26 0x08052fd3 in scummvm_main (argc=4, argv=0xbf99cd34) at base/main.cpp:489
27 0x08050ac4 in main (argc=4, argv=0xbf99cd34)
at backends/platform/sdl/posix/posix-main.cpp:45
~~~~~
comment:12 by , 10 years ago
It turns out that the deadlock can happen in other places as well. I got this backtrace when trying to open a door after getting through the flup tubes:
~~~~~ Thread 3 (Thread 0xb5ee3b40 (LWP 26280)):
0 0xb7741424 in __kernel_vsyscall ()
1 0xb6bd2672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb6bce1c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb6bce043 in __GI___pthread_mutex_lock (mutex=0xa6a0360)
at ../nptl/pthread_mutex_lock.c:114
4 0xb6ff1d84 in pthread_mutex_lock (mutex=0xa6a0360) at forward.c:192
5 0xb76bdee0 in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeb53 in SdlMutexManager::lockMutex (this=0xa620240, mutex=0xa6a0360)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f107 in ModularBackend::lockMutex (this=0xa5eb028, mutex=0xa6a0360)
at backends/modular-backend.cpp:222
8 0x093b8339 in Common::StackLock::lock (this=0xb5ee3068)
at common/mutex.cpp:68
9 0x093b82d4 in Common::StackLock::StackLock (this=0xb5ee3068, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x090a6a88 in TsAGE::AdlibSoundDriver::readBuffer (this=0xa6a3270,
buffer=0xb4a00468, numSamples=4096) at engines/tsage/sound.cpp:3024
11 0x09391fc9 in Audio::CopyRateConverter::flow (
this=0xa6a3580, input=..., obuf=0xa65c440, osamp=4096, vol_l=256,
vol_r=256) at audio/rate.cpp:305
12 0x09359d25 in Audio::Channel::mix (this=0xa6a3538, data=0xa65c440,
len=4096) at audio/mixer.cpp:621
13 0x09358987 in Audio::MixerImpl::mixCallback (this=0xa6424a8,
samples=0xa65c440 "", len=4096) at audio/mixer.cpp:293
14 0x092aea7b in SdlMixerManager::callbackHandler (this=0xa63aa38,
samples=0xa65c440 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:143
15 0x092aeac3 in SdlMixerManager::sdlCallback (this_=0xa63aa38,
samples=0xa65c440 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:150
16 0xb766e708 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
17 0xb7676f25 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
18 0xb76bd898 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
19 0xb6bcbefb in start_thread (arg=0xb5ee3b40) at pthread_create.c:309
20 0xb6fe4fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 2 (Thread 0xb56e2b40 (LWP 26281)):
0 0xb7741424 in __kernel_vsyscall ()
1 0xb6fb00b6 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
2 0xb76c01d0 in SDL_Delay () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
3 0xb76c0212 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
4 0xb7676f25 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
5 0xb76bd898 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0xb6bcbefb in start_thread (arg=0xb56e2b40) at pthread_create.c:309
7 0xb6fe4fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 1 (Thread 0xb618ba80 (LWP 26277)):
0 0xb7741424 in __kernel_vsyscall ()
1 0xb6bd2672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb6bce1c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb6bce043 in __GI___pthread_mutex_lock (mutex=0xa642630)
at ../nptl/pthread_mutex_lock.c:114
4 0xb6ff1d84 in pthread_mutex_lock (mutex=0xa642630) at forward.c:192
5 0xb76bdee0 in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeb53 in SdlMutexManager::lockMutex (this=0xa620240, mutex=0xa642630)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f107 in ModularBackend::lockMutex (this=0xa5eb028, mutex=0xa642630)
at backends/modular-backend.cpp:222
8 0x093b8339 in Common::StackLock::lock (this=0xbfca4380)
at common/mutex.cpp:68
9 0x093b82d4 in Common::StackLock::StackLock (this=0xbfca4380, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x09359422 in Audio::MixerImpl::isSoundHandleActive (this=0xa6424a8,
handle=...) at audio/mixer.cpp:452
11 0x090a6ed9 in TsAGE::SoundBlasterDriver::updateVoice (this=0xa6fdd00,
channel=0) at engines/tsage/sound.cpp:3126
12 0x090a14bc in TsAGE::SoundManager::sfRethinkVoiceTypes ()
at engines/tsage/sound.cpp:1272
13 0x0909f27e in TsAGE::SoundManager::sfAddToPlayList (sound=0xa703c7c)
at engines/tsage/sound.cpp:624
14 0x0909e77f in TsAGE::SoundManager::addToPlayList (this=0xa6b91f0,
sound=0xa703c7c) at engines/tsage/sound.cpp:357
15 0x090a2566 in TsAGE::Sound::play (this=0xa703c7c, soundNum=314)
at engines/tsage/sound.cpp:1561
16 0x090a4df8 in TsAGE::ASound::play (this=0xa703c74, soundNum=314,
endAction=0x0, volume=127) at engines/tsage/sound.cpp:2467
17 0x09132488 in TsAGE::SequenceManager::signal (this=0xa703ad0)
at engines/tsage/converse.cpp:236
18 0x08f45478 in TsAGE::ObjectMover::endMove (this=0xa7251a0)
at engines/tsage/core.cpp:395
19 0x08f45203 in TsAGE::ObjectMover::dispatch (this=0xa7251a0)
at engines/tsage/core.cpp:342
20 0x08f4be67 in TsAGE::SceneObject::dispatch (this=0xa6b93d0)
at engines/tsage/core.cpp:2585
21 0x08f52620 in TsAGE::SceneHandler::dispatchObject (obj=0xa6b93d0)
at engines/tsage/core.cpp:4495
22 0x08f531ba in TsAGE::SceneObjectList::recurse (this=0xa6b9084,
Fn=0x8f52608 )
at ./engines/tsage/core.h:759
23 0x08f52468 in TsAGE::SceneHandler::dispatch (this=0xa6a1a68)
at engines/tsage/core.cpp:4455
24 0x08fe7ba2 in TsAGE::Ringworld2::SceneHandlerExt::dispatch (this=0xa6a1a68)
at engines/tsage/ringworld2/ringworld2_logic.cpp:630
25 0x08f51a30 in TsAGE::GameHandler::execute (this=0xa6a1a68)
at engines/tsage/core.cpp:4263
26 0x0909d41a in TsAGE::Game::execute (this=0xa6a1a58)
at engines/tsage/scenes.cpp:617
27 0x08f411ab in TsAGE::TSageEngine::run (this=0xa623f60)
at engines/tsage/tsage.cpp:134
28 0x08051f5c in runGame (plugin=0xa63f338, system=..., edebuglevels=...)
at base/main.cpp:244
29 0x08052fd3 in scummvm_main (argc=4, argv=0xbfcea7f4) at base/main.cpp:489
30 0x08050ac4 in main (argc=4, argv=0xbfcea7f4)
at backends/platform/sdl/posix/posix-main.cpp:45
~~~~~
comment:13 by , 10 years ago
Here is the backtrace of a deadlock I got when restoring an earlier savegame while I was in the middle of the final (?) confrontation.
~~~~~ Thread 3 (Thread 0xb5f7fb40 (LWP 26751)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb784d0b6 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
2 0xb7f5d1d0 in SDL_Delay () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
3 0xb7f5d212 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
4 0xb7f13f25 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
5 0xb7f5a898 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0xb7468efb in start_thread (arg=0xb5f7fb40) at pthread_create.c:309
7 0xb7881fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 2 (Thread 0xb6780b40 (LWP 26750)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb746f672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb746b1c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb746b043 in __GI___pthread_mutex_lock (mutex=0x9ef2250)
at ../nptl/pthread_mutex_lock.c:114
4 0xb788ed84 in pthread_mutex_lock (mutex=0x9ef2250) at forward.c:192
5 0xb7f5aee0 in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeb53 in SdlMutexManager::lockMutex (this=0x9e72240, mutex=0x9ef2250)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f107 in ModularBackend::lockMutex (this=0x9e3d028, mutex=0x9ef2250)
at backends/modular-backend.cpp:222
8 0x093b8339 in Common::StackLock::lock (this=0xb6780070)
at common/mutex.cpp:68
9 0x093b82d4 in Common::StackLock::StackLock (this=0xb6780070, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x090a6a6e in TsAGE::AdlibSoundDriver::readBuffer (this=0x9ef5180,
buffer=0xb5200468, numSamples=4096) at engines/tsage/sound.cpp:3023
11 0x09391fc9 in Audio::CopyRateConverter::flow (
this=0x9ef5490, input=..., obuf=0x9eae440, osamp=4096, vol_l=256,
vol_r=256) at audio/rate.cpp:305
12 0x09359d25 in Audio::Channel::mix (this=0x9ef5448, data=0x9eae440,
len=4096) at audio/mixer.cpp:621
13 0x09358987 in Audio::MixerImpl::mixCallback (this=0x9e944a8,
samples=0x9eae440 "", len=4096) at audio/mixer.cpp:293
14 0x092aea7b in SdlMixerManager::callbackHandler (this=0x9e8ca38,
samples=0x9eae440 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:143
15 0x092aeac3 in SdlMixerManager::sdlCallback (this_=0x9e8ca38,
samples=0x9eae440 "", len=16384) at backends/mixer/sdl/sdl-mixer.cpp:150
16 0xb7f0b708 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
17 0xb7f13f25 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
18 0xb7f5a898 in ?? () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
19 0xb7468efb in start_thread (arg=0xb6780b40) at pthread_create.c:309
20 0xb7881fee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129
Thread 1 (Thread 0xb6a28a80 (LWP 26745)):
0 0xb7fde424 in __kernel_vsyscall ()
1 0xb746f672 in __lll_lock_wait ()
at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/lowlevellock.S:144
2 0xb746b1c2 in _L_lock_920 ()
from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
3 0xb746b043 in __GI___pthread_mutex_lock (mutex=0x9e94630)
at ../nptl/pthread_mutex_lock.c:114
4 0xb788ed84 in pthread_mutex_lock (mutex=0x9e94630) at forward.c:192
5 0xb7f5aee0 in SDL_mutexP () from /usr/lib/i386-linux-gnu/libSDL-1.2.so.0
6 0x092aeb53 in SdlMutexManager::lockMutex (this=0x9e72240, mutex=0x9e94630)
at backends/mutex/sdl/sdl-mutex.cpp:36
7 0x0929f107 in ModularBackend::lockMutex (this=0x9e3d028, mutex=0x9e94630)
at backends/modular-backend.cpp:222
8 0x093b8339 in Common::StackLock::lock (this=0xbffb90b0)
at common/mutex.cpp:68
9 0x093b82d4 in Common::StackLock::StackLock (this=0xbffb90b0, mutex=...,
mutexName=0x0) at common/mutex.cpp:57
10 0x09358b68 in Audio::MixerImpl::stopHandle (this=0x9e944a8, handle=...)
at audio/mixer.cpp:324
11 0x090a5596 in TsAGE::PlayStream::stop (this=0x9f0f0b8)
at engines/tsage/sound.cpp:2641
12 0x09091b17 in TsAGE::Ringworld2::VisualSpeaker::stopSpeaking (
this=0x9f779fc) at engines/tsage/ringworld2/ringworld2_speakers.cpp:269
13 0x091345e2 in TsAGE::StripManager::remove (this=0x9f76f14)
at engines/tsage/converse.cpp:746
14 0x08f44ad3 in TsAGE::Action::remove (this=0x9f76ee8)
at engines/tsage/core.cpp:195
15 0x08fe70e6 in TsAGE::Ringworld2::SceneExt::remove (this=0x9f76ee8)
at engines/tsage/ringworld2/ringworld2_logic.cpp:402
16 0x090802ec in TsAGE::Ringworld2::Scene3400::remove (this=0x9f76ee8)
at engines/tsage/ringworld2/ringworld2_scenes3.cpp:2818
17 0x0909b149 in TsAGE::SceneManager::sceneChange (this=0x9f0ac18)
at engines/tsage/scenes.cpp:78
18 0x0909ba8b in TsAGE::SceneManager::listenerSynchronize (this=0x9f0ac18,
s=...) at engines/tsage/scenes.cpp:252
19 0x08f3f261 in TsAGE::Saver::restore (this=0x9e76418, slot=44)
at engines/tsage/saveload.cpp:201
20 0x08f523e0 in TsAGE::SceneHandler::dispatch (this=0x9ef3978)
at engines/tsage/core.cpp:4445
21 0x08fe7ba2 in TsAGE::Ringworld2::SceneHandlerExt::dispatch (this=0x9ef3978)
at engines/tsage/ringworld2/ringworld2_logic.cpp:630
22 0x08f51a30 in TsAGE::GameHandler::execute (this=0x9ef3978)
at engines/tsage/core.cpp:4263
23 0x0909d41a in TsAGE::Game::execute (this=0x9ef3968)
at engines/tsage/scenes.cpp:617
24 0x08f411ab in TsAGE::TSageEngine::run (this=0x9e75f60)
at engines/tsage/tsage.cpp:134
25 0x08051f5c in runGame (plugin=0x9e91338, system=..., edebuglevels=...)
at base/main.cpp:244
26 0x08052fd3 in scummvm_main (argc=4, argv=0xbffff354) at base/main.cpp:489
27 0x08050ac4 in main (argc=4, argv=0xbffff354)
at backends/platform/sdl/posix/posix-main.cpp:45
~~~~~
comment:14 by , 10 years ago
Is there any details you can give me to help me replicate the non-deadlocky lock?
For technical details: This lock is happening during the signalling sequence of Scene3500::Action1::signal.. it has an _actionIndex controlling the switch that handles the states of animating changing direction. At index 2, it starts a mover to move _tunnelVertCircle to a given position, at the end of which it should signal the action to do the next index (3). In the given savegame, it seems like the mover has finished, but the action hasn't been signaled. So the scene remains in a "move disabled state", stopping any further movement actions from being done.
comment:15 by , 10 years ago
I'm afraid not. As I wrote earlier, it seemed to me like it would happen when trying to navigate some tight corner, by which I meant trying to make a turn right after another turn. And since I would often try it at default speed first, rather than slowing down, that meant hitting the arrow keys in rapid succession to first turn one way, then another, usually hitting a wall instead.
But that could have just been my imagination.
comment:16 by , 10 years ago
I can confirm this bug.
It doesn't only happen when trying to navigate a tight corner. It seems that it does only happen when you hit a wall or the end of a tube. I also noticed that when you hit a wall or the end of a tube the sound of the crash is sometimes too late or no sound at all.
comment:17 by , 10 years ago
This bug doesn't happen when you follow a walkthrough and fly straight to the end of the end of the flub tube system. But if you don't follow a walkthrough (like I do) and fly around in the flub tube system trying the find the right way, you should run in to this bug sooner or later.
comment:18 by , 6 years ago
| Priority: | normal → blocker |
|---|
Raising all identified crasher, hang, and memory violation bugs which I could not fully triage myself to blocker priority for the next release.
comment:19 by , 6 years ago
| Keywords: | has-save-game has-backtrace added |
|---|
comment:20 by , 6 years ago
| Owner: | set to |
|---|
comment:21 by , 6 years ago
In the attached save game there is a deadlock because:
- The save game restoration code acquires a lock on a game sound manager mutex which causes the audio thread to block on the game sound manager mutex when the OPL callback timer fires;
- The audio thread acquires the system mixer mutex prior to calling the OPL callback timer;
- The save game causes a fatal error in ManagedSurface which causes the debugger to be entered;
- The debugger tries to pause all audio in the system mixer, which causes the main thread to block on the system mixer mutex;
- Deadlock.
I’m not sure why the save game restore code is acquiring a lock instead of just pausing the system mixer to stop audio from being serviced during the restore. I’m also not sure if this save game is even valid; fixing the ManagedSurface error just causes the game to be restored with no visible mouse cursor, and then forcing the cursor to be visible again by hitting F1 to show the game menu leaves me with a running game, but one where I can’t seem to get anything to happen.
comment:22 by , 6 years ago
| Keywords: | has-pull-request added |
|---|
comment:23 by , 6 years ago
| Resolution: | → fixed |
|---|---|
| Status: | new → closed |
Thanks for your report! A patch for this issue has been added in commit fe45300891fea90f7ad72d66af7f060c3ec6b753 and will be available in daily builds 1.10.0git-5490 and later.
One thing that struck me is that while it seems pretty clear that it's the main thread hanging, waiting for a mutex, it also seems reasonable to think that the mutex was locked by another thread.
I noticed that rethinkVoiceTypes() also gets killed from sfSoundServer(), which is called from readBuffer(). To me that seems like a possible race condition, though I'm rather too tired to give it much more of a thought.