Soundwire - recursive locking - 5.16

[perexg]

[   40.315931] ============================================
[   40.315932] WARNING: possible recursive locking detected
[   40.315933] 5.16.0-0.rc8.20220107gitddec8ed2d490.57.fc36.x86_64 #1 Not tainted
[   40.315935] --------------------------------------------
[   40.315936] pipewire-media-/1312 is trying to acquire lock:
[   40.315937] ffff906789c498d0 (&bus->bus_lock){+.+.}-{3:3}, at: sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.315947] 
               but task is already holding lock:
[   40.315948] ffff9067eb2690d0 (&bus->bus_lock){+.+.}-{3:3}, at: sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.315953] 
               other info that might help us debug this:
[   40.315954]  Possible unsafe locking scenario:

[   40.315955]        CPU0
[   40.315956]        ----
[   40.315956]   lock(&bus->bus_lock);
[   40.315958]   lock(&bus->bus_lock);
[   40.315959] 
                *** DEADLOCK ***

[   40.315960]  May be due to missing lock nesting notation

[   40.315961] 4 locks held by pipewire-media-/1312:
[   40.315962]  #0: ffffffffc0f7c1b8 (snd_pcm_link_rwsem){.+.+}-{3:3}, at: snd_pcm_prepare+0x9a/0x1b0 [snd_pcm]
[   40.315972]  #1: ffffffffc148b1f8 (&card->mutex/1){+.+.}-{3:3}, at: dpcm_fe_dai_prepare+0x33/0x1e0 [snd_soc_core]
[   40.315991]  #2: ffffffffc148b338 (&card->pcm_mutex){+.+.}-{3:3}, at: soc_pcm_prepare+0x28/0x100 [snd_soc_core]
[   40.316003]  #3: ffff9067eb2690d0 (&bus->bus_lock){+.+.}-{3:3}, at: sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316009] 
               stack backtrace:
[   40.316010] CPU: 5 PID: 1312 Comm: pipewire-media- Not tainted 5.16.0-0.rc8.20220107gitddec8ed2d490.57.fc36.x86_64 #1
[   40.316012] Hardware name: Dell Inc. Precision 5750/, BIOS 1.4.0 09/03/2020
[   40.316013] Call Trace:
[   40.316015]  <TASK>
[   40.316017]  dump_stack_lvl+0x59/0x73
[   40.316022]  __lock_acquire.cold+0x140/0x2b8
[   40.316027]  lock_acquire+0xd3/0x2f0
[   40.316030]  ? sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316034]  ? lock_is_held_type+0xea/0x140
[   40.316039]  __mutex_lock+0x93/0x910
[   40.316042]  ? sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316047]  ? soc_pcm_prepare+0x28/0x100 [snd_soc_core]
[   40.316058]  ? lock_acquired+0xef/0x3e0
[   40.316060]  ? sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316065]  ? sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316068]  sdw_prepare_stream+0x43/0x1f0 [soundwire_bus]
[   40.316072]  ? lock_is_held_type+0xea/0x140
[   40.316075]  ? find_held_lock+0x32/0x90
[   40.316077]  snd_soc_link_prepare+0x28/0x50 [snd_soc_core]
[   40.316088]  ? soc_pcm_prepare+0x28/0x100 [snd_soc_core]
[   40.316098]  soc_pcm_prepare+0x30/0x100 [snd_soc_core]
[   40.316109]  dpcm_be_dai_prepare+0xb3/0x120 [snd_soc_core]
[   40.316120]  dpcm_fe_dai_prepare+0xaf/0x1e0 [snd_soc_core]
[   40.316131]  snd_pcm_prepare+0x14b/0x1b0 [snd_pcm]
[   40.316138]  snd_pcm_ioctl+0x23/0x30 [snd_pcm]
[   40.316143]  __x64_sys_ioctl+0x7f/0xb0
[   40.316147]  do_syscall_64+0x38/0x90
[   40.316150]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   40.316152] RIP: 0033:0x7f74646740ab
[   40.316154] Code: ff ff ff 85 c0 79 9b 49 c7 c4 ff ff ff ff 5b 5d 4c 89 e0 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 9d bd 0c 00 f7 d8 64 89 01 48
[   40.316156] RSP: 002b:00007ffe28df93d8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[   40.316158] RAX: ffffffffffffffda RBX: 0000564d757409a0 RCX: 00007f74646740ab
[   40.316160] RDX: 0000000000000000 RSI: 0000000000004140 RDI: 0000000000000022
[   40.316161] RBP: 00007ffe28df9990 R08: 0000000000000000 R09: 00000000000012bd
[   40.316162] R10: 0000000000000004 R11: 0000000000000202 R12: 0000000000000000
[   40.316163] R13: 00007ffe28df9690 R14: 00007f745595d4d0 R15: 00007ffe28df9420
[   40.316167]  </TASK>

I believe that there are no soundwire updates between 5.16-rc8 and 5.16.

[ranj063]

Thanks for reporting this @perexg. @bardliao FYI

[plbossart]

@perexg thanks for reporting this issue. This seems related to the DPCM locking change. It's the same signature as in the other cases reported on alsa-devel

https://lore.kernel.org/alsa-devel/[email protected]/

https://lore.kernel.org/alsa-devel/[email protected]/

@tiwai @jwrdegoede FYI

I wonder why this was not reported in our internal tests.

[jwrdegoede]

I wonder why this was not reported in our internal tests.

Maybe your CI does not enable lockdep in any of its test kernel .config files ?

[plbossart]

I wonder why this was not reported in our internal tests.

Maybe your CI does not enable lockdep in any of its test kernel .config files ?

I think we do, but it doesn't hurt to double-check if we are missing something:
https://github.com/thesofproject/kconfig/blob/master/lock-stall-defconfig
https://github.com/thesofproject/kconfig/blob/master/kconfig-sof-default.sh#L16

Maybe we miss the warning level though, IIRC we only stop on errors.

[jwrdegoede]

Maybe we miss the warning level though, IIRC we only stop on errors.

Ah yes a lockdep "splat" is a warning only, but a warning with a full backtrace, note I think any kernel WARN() triggers are warning level only, but your CI really should catch any kernel backtraces getting printed and consider those an error.

[plbossart]

@perexg does the patch suggested by @tiwai in https://lore.kernel.org/alsa-devel/[email protected]/ makes this go away?

[plbossart]

@tiwai provided fixes for the warnings in https://lore.kernel.org/alsa-devel/[email protected]/

Closing