Deadlock in `OpenPhysicalAudioDevice` for Pipewire backend on Linux

[SimonMaracine]

Hello.

I noticed for quite a while now that sometimes my SDL application which deals with audio hangs completely during start up. I then built it with thread sanitizers and indeed there is a potential for a deadlock. This is what I've got.

I'm not familiar with the code at all, so all I figured out for now is that M0 is the device lock, while M1 is some other mutex and there are the main thread and a secondary Pipewire thread at play.

static void output_callback(void *data)
{
    SDL_AudioDevice *device = (SDL_AudioDevice *) data;

    // this callback can fire in a background thread during OpenDevice, while we're still blocking
    // _with the device lock_ until the stream is ready, causing a deadlock. Write silence in this case.
    if (device->hidden->stream_init_status != PW_READY_FLAG_ALL_BITS) {
        int bufsize = 0;
        Uint8 *buf = PIPEWIRE_GetDeviceBuf(device, &bufsize);
        if (buf && bufsize) {
            SDL_memset(buf, device->silence_value, bufsize);
        }
        PIPEWIRE_PlayDevice(device, buf, bufsize);
        return;
    }

    SDL_PlaybackAudioThreadIterate(device);
}

Also reading this, it looks like the issue is known, but not high priority for now.

So I would like to gently make you reconsider this issue some time in the future. It did end up in deadlock a handful of times for me already.

[slouken]

@icculus, we're holding 3.4.2 for the Android filesystem issue, so feel free to bump this back for release if it's a safe fix.

[SimonMaracine]

Not related at all, sorry, but I would like to know if there is a way for people to make one-time donations to the project in order to help it keep alive. I know direct contributions with pull requests should be more welcome, but I myself don't have any experience with the platform APIs that SDL uses, besides some basic Linux system calls, so it's very hard to even try to get involved with actually writing code. Though I'd like to get experience...

[slouken]

Not related at all, sorry, but I would like to know if there is a way for people to make one-time donations to the project in order to help it keep alive. I know direct contributions with pull requests should be more welcome, but I myself don't have any experience with the platform APIs that SDL uses, besides some basic Linux system calls, so it's very hard to even try to get involved with actually writing code. Though I'd like to get experience...

The desire is appreciated, but we don't have a way to directly contribute money to the SDL project. However, @icculus is one of the core developers and he has a patreon that you might like: https://www.patreon.com/icculus

[icculus]

@icculus, we're holding 3.4.2 for the Android filesystem issue, so feel free to bump this back for release if it's a safe fix.

I'm looking into this, but if I don't beat the buzzer, please ship 3.4.2 when you are ready and we'll get it into 3.4.4.

[icculus]

Okay, to summarize the problem:

This is thread T12 in the screenshot:

• Pipewire, with an open SDL audio device, will grab its thread loop lock before doing any work it needs to do for that audio device in a background thread owned entire by pipewire and not SDL (its "thread loop").
• One of the tasks of the thread loop is to say "it's time to generate more audio output for this device to play," which is when it calls output_callback. The thread loop lock is held when it calls into this and stays locked at least until output_callback returns (and maybe until all pending thread loop tasks are complete).
• output_callback hooks into the standard SDL audio device iteration code, which grabs SDL's device lock (which is different than the thread loop lock), generates more audio to feed the device, then releases the device lock. Then output_callback returns and the thread loop lock releases, too.

In the main thread:

• The app calls SDL_OpenAudioDeviceStream, which calls SDL_OpenAudioDevice, which locks the device lock first.
• Eventually this lands in OpenPhysicalAudioDevice, calling current_audio.impl.OpenDevice, which is PIPEWIRE_OpenDevice() in this case. The device lock is still held.
• PIPEWIRE_OpenDevice has this at the end:

    res = PIPEWIRE_pw_thread_loop_start(priv->loop);
    if (res != 0) {
        return SDL_SetError("Pipewire: Failed to start stream loop");
    }
  
    // Wait until all pre-open init flags are set or the stream has failed.
    PIPEWIRE_pw_thread_loop_lock(priv->loop);
    while (priv->stream_init_status != PW_READY_FLAG_ALL_PREOPEN_BITS &&
           PIPEWIRE_pw_stream_get_state(priv->stream, NULL) != PW_STREAM_STATE_ERROR) {
        PIPEWIRE_pw_thread_loop_wait(priv->loop);
    }
    priv->stream_init_status |= PW_READY_FLAG_OPEN_COMPLETE;
    PIPEWIRE_pw_thread_loop_unlock(priv->loop);

• So we're starting the thread loop, and locking/waiting on it (pw_thread_loop_wait releases the lock so work can happen, and reobtains it when work has been done...so the thread loop eventually does work to get set up.
• One we decide the device stream is ready, we set a flag and drop the thread loop lock. Eventually, SDL_OpenAudioDevice should finish and drop the SDL device lock.

So it looks like the output_callback is firing, holding the pipewire thread loop lock, then calls SDL stuff that grabs the SDL device lock, but we are still opening the device, so we're holding the device lock first and then also grabbing the thread loop lock.

The problem, though, is this shouldn't happen, since we shouldn't be entering the SDL device iteration code until we have set a flag and dropped the lock from the main thread for good.

I'm building a debug pipewire right now; both the screenshot and my own system seem to have a pipewire without debug symbols or frame pointers, and I think it's concealing the actual information we need. Stay tuned.

[SimonMaracine]

I kind of understand. But I'm not at the computer now. Can't you just check in the output_callback with an atomic flag if the stream is fully initialized and if it is not, then don't acquire the device lock M0 at all? If I understood correctly, this should prevent the deadlock while inducing a performance hit.

[icculus]

The problem is output_callback shouldn't run at all when we hold that lock, so the flag we're already setting should be fine.

I added printf() calls, and it looks like we are releasing the lock before output_callback runs, so this is a mystery still.

And here's a debug build of SDL3 and libpipewire (no optimizations, -fno-omit-frame-pointer), which didn't help. Obviously we didn't call do_lock inside of libpipewire directly from SDL's high-level code (and in this source tree, SDL_audio.c:1828 is the call to PIPEWIRE_OpenDevice, so we clearly still lost some stackframes somehow.

I don't know, this whole thing is weird. Maybe we aren't holding the lock we think we are. I'll keep digging.

WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=160106)
  Cycle in lock order graph: M0 (0x720c00001920) => M1 (0x724400001068) => M0

  Mutex M1 acquired here while holding mutex M0 in main thread:
    #0 pthread_mutex_lock ../../../../src/libsanitizer/tsan/tsan_interceptors_posix.cpp:1341 (libtsan.so.2+0x59a13) (BuildId: 38097064631f7912bd33117a9c83d08b42e15571)
    #1 do_lock ../src/pipewire/thread-loop.c:53 (libpipewire-0.3.so.0+0x116e50) (BuildId: 4256f7ad82e6da41b3050358eb700c5d650d88d9)
    #2 OpenPhysicalAudioDevice /home/icculus/projects/SDL/src/audio/SDL_audio.c:1828 (libSDL3.so.0+0x56f1d) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #3 SDL_OpenAudioDevice_REAL /home/icculus/projects/SDL/src/audio/SDL_audio.c:1896 (libSDL3.so.0+0x573d7) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #4 SDL_OpenAudioDeviceStream_REAL /home/icculus/projects/SDL/src/audio/SDL_audio.c:2207 (libSDL3.so.0+0x589ce) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #5 SDL_OpenAudioDeviceStream /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:693 (libSDL3.so.0+0xaafe7) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #6 SDL_AppInit /home/icculus/projects/SDL/test/loopwave.c:114 (loopwave+0x75cc) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)
    #7 SDL_InitMainCallbacks /home/icculus/projects/SDL/src/main/SDL_main_callbacks.c:104 (libSDL3.so.0+0x12655b) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #8 SDL_EnterAppMainCallbacks_REAL /home/icculus/projects/SDL/src/main/generic/SDL_sysmain_callbacks.c:56 (libSDL3.so.0+0x5716f5) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #9 SDL_EnterAppMainCallbacks /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:207 (libSDL3.so.0+0xa1b12) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #10 SDL_main /home/icculus/projects/SDL/include/SDL3/SDL_main_impl.h:59 (loopwave+0x70c4) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)
    #11 SDL_CallMainFunction /home/icculus/projects/SDL/src/main/SDL_main_callbacks.c:164 (libSDL3.so.0+0x126824) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #12 SDL_RunApp_REAL /home/icculus/projects/SDL/src/main/SDL_runapp.c:37 (libSDL3.so.0+0x12687f) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #13 SDL_RunApp_DEFAULT /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:804 (libSDL3.so.0+0x921de) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #14 SDL_RunApp /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:804 (libSDL3.so.0+0xad52e) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #15 main /home/icculus/projects/SDL/include/SDL3/SDL_main_impl.h:137 (loopwave+0x710d) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)

    Hint: use TSAN_OPTIONS=second_deadlock_stack=1 to get more informative warning message

  Mutex M0 acquired here while holding mutex M1 in thread T6:
    #0 pthread_mutex_lock ../../../../src/libsanitizer/tsan/tsan_interceptors_posix.cpp:1341 (libtsan.so.2+0x59a13) (BuildId: 38097064631f7912bd33117a9c83d08b42e15571)
    #1 SDL_LockMutex_REAL /home/icculus/projects/SDL/src/thread/pthread/SDL_sysmutex.c:80 (libSDL3.so.0+0x51e8ec) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #2 SDL_PlaybackAudioThreadIterate /home/icculus/projects/SDL/src/audio/SDL_audio.c:1176 (libSDL3.so.0+0x5365d) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #3 output_callback /home/icculus/projects/SDL/src/audio/pipewire/SDL_pipewire.c:1032 (libSDL3.so.0+0x3cbc21) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #4 do_call_process ../src/pipewire/stream.c:449 (libpipewire-0.3.so.0+0x10bebc) (BuildId: 4256f7ad82e6da41b3050358eb700c5d650d88d9)

  Thread T6 'SDLAudioP15' (tid=160115, running) created by main thread at:
    #0 pthread_create ../../../../src/libsanitizer/tsan/tsan_interceptors_posix.cpp:1022 (libtsan.so.2+0x5ac1a) (BuildId: 38097064631f7912bd33117a9c83d08b42e15571)
    #1 impl_create ../src/pipewire/thread.c:71 (libpipewire-0.3.so.0+0x116610) (BuildId: 4256f7ad82e6da41b3050358eb700c5d650d88d9)
    #2 OpenPhysicalAudioDevice /home/icculus/projects/SDL/src/audio/SDL_audio.c:1828 (libSDL3.so.0+0x56f1d) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #3 SDL_OpenAudioDevice_REAL /home/icculus/projects/SDL/src/audio/SDL_audio.c:1896 (libSDL3.so.0+0x573d7) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #4 SDL_OpenAudioDeviceStream_REAL /home/icculus/projects/SDL/src/audio/SDL_audio.c:2207 (libSDL3.so.0+0x589ce) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #5 SDL_OpenAudioDeviceStream /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:693 (libSDL3.so.0+0xaafe7) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #6 SDL_AppInit /home/icculus/projects/SDL/test/loopwave.c:114 (loopwave+0x75cc) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)
    #7 SDL_InitMainCallbacks /home/icculus/projects/SDL/src/main/SDL_main_callbacks.c:104 (libSDL3.so.0+0x12655b) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #8 SDL_EnterAppMainCallbacks_REAL /home/icculus/projects/SDL/src/main/generic/SDL_sysmain_callbacks.c:56 (libSDL3.so.0+0x5716f5) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #9 SDL_EnterAppMainCallbacks /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:207 (libSDL3.so.0+0xa1b12) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #10 SDL_main /home/icculus/projects/SDL/include/SDL3/SDL_main_impl.h:59 (loopwave+0x70c4) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)
    #11 SDL_CallMainFunction /home/icculus/projects/SDL/src/main/SDL_main_callbacks.c:164 (libSDL3.so.0+0x126824) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #12 SDL_RunApp_REAL /home/icculus/projects/SDL/src/main/SDL_runapp.c:37 (libSDL3.so.0+0x12687f) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #13 SDL_RunApp_DEFAULT /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:804 (libSDL3.so.0+0x921de) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #14 SDL_RunApp /home/icculus/projects/SDL/src/dynapi/SDL_dynapi_procs.h:804 (libSDL3.so.0+0xad52e) (BuildId: 6f72ab712569d03fcd3b44bd83e7915afc6f34e1)
    #15 main /home/icculus/projects/SDL/include/SDL3/SDL_main_impl.h:137 (loopwave+0x710d) (BuildId: 56593a5e1b9e4a642b9d98770c169b3b1e901996)

SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) ../src/pipewire/thread-loop.c:53 in do_lock

[cgutman]

I wonder if this particular TSan warning is just a red herring because TSan doesn't understand that the locking in those threads is affected by the stream_init_status flags.

This feels very similar to the bug I fixed in #12365. @SimonMaracine Any chance your initial deadlocks were using an early version of SDL 3 without that fix? If you can still reproduce the deadlock on the latest SDL3 code, I'd like to see the backtraces of the actual deadlocked threads rather than what TSan thinks might lead to a deadlock.

[SimonMaracine]

It is already midnight for me, so only tomorrow I will check the current commit of SDL that I use right now and compare to the commit of the pull request. I didn't update the SDL main branch in a while, like two months maybe.

Also note that I'm only assuming the application hangs because of the deadlock. That seemed to be the most logical cause.

I don't understand, do you mean this could be a false positive?

[cgutman]

The TSan warning about the lock order itself is true, but TSan is not aware of other control flow (such as our stream_init_status check) that can prevent the lock order variation from ever leading to a deadlock.

What TSan is doing here is tracking acquisition order of locks across all threads. If it sees a thread acquiring locks in the order M0 then M1 and another thread acquiring M1 then M0, it will flag that as a possible deadlock. TSan cannot be sure it will actually deadlock unless it witnesses those 2 threads violating lock order rules simultaneously (which would deadlock with or without TSan). Since hitting a deadlock due to lock ordering determininstically is nearly impossible, it will warn if it sees threads acquiring the locks in different orders even seconds or minutes apart to flag the potential of a deadlock.

In our case here (as far as we can tell), the code acquiring M0 then M1 can never run at the same time as the thread acquiring M1 then M0 due to the device->hidden->stream_init_status != PW_READY_FLAG_ALL_BITS in output_callback(). At the moment that the main thread sets that final PW_READY_FLAG_OPEN_COMPLETE bit to make device->hidden->stream_init_status != PW_READY_FLAG_ALL_BITS false, it already holds both M0 and M1, so there is no possibility for the pipewire thread to grab them in a different order and deadlock.

[icculus]

So is there a way to tell TSan this is okay so we don't generate bug reports?

[SimonMaracine]

Any chance your initial deadlocks were using an early version of SDL 3 without that fix?

I looked it up. The SDL version that I used had the mentioned commit. So should this issue be closed then? I am confused, because I was pretty sure the rare black screens that I got many times with no apparent reason where because of race conditions.

[icculus]

Okay, so first things first: we're probably using threads wrong with PipeWire.

We've got a pw_thread_loop per device, instead of just one thread loop for the entire app, so there's all sort of locking shenanigans going on that shouldn't be.

This is not the cause of the deadlock here--I think--but fixing that is going to take some reworking that needs to be done before we can properly address this. If nothing else, the locking behavior is going to dramatically change, so current knowledge on this issue will be all wrong after that.

We did this work for PulseAudio (which also used a "threaded mainloop" per device incorrectly) at some point. I think I might have tried to do this for PipeWire at some point, too, and abandoned it for some reason. I'll have to look up the details.

At any rate, I'm going to kick this to 3.6.0 to see about doing the redesign work to get this moving forward.