SoundWire: rt711-sdca: mutex_lock warning

@ujfalusi

Found in one test, reproduced twice so far. @ujfalusi @bardliao would you have any ideas as to what could be wrong here?

[  699.182429] DEBUG_LOCKS_WARN_ON(lock->magic != lock)
[  699.182432] WARNING: CPU: 7 PID: 1422 at kernel/locking/mutex.c:579 __mutex_lock+0x8e6/0x960
[  699.182437] Modules linked in: snd_soc_sof_sdw(+) snd_soc_intel_sof_maxim_common snd_soc_rt711_sdca snd_ctl_led ledtrig_audio fuse snd_soc_rt1316_sdw snd_soc_rt715_sdca regmap_sdw_mbq regmap_sdw snd_sof_ipc_msg_injector snd_sof_probes snd_soc_dmic snd_sof_ipc_flood_test snd_sof_pci_intel_tgl snd_sof_intel_hda_common soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_pci snd_sof_xtensa_dsp snd_sof snd_sof_utils snd_soc_acpi_intel_match snd_soc_acpi soundwire_bus snd_soc_core snd_compress snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep snd_hda_core snd_pcm wmi_bmof snd_seq_midi snd_seq_midi_event ax88179_178a snd_rawmidi usbnet snd_seq snd_seq_device x86_pkg_temp_thermal snd_timer intel_powerclamp snd soundcore hid_multitouch iwlmvm iwlwifi mei_me mei i915 i2c_algo_bit drm_buddy drm_dp_helper processor_thermal_device_pci_legacy drm_kms_helper processor_thermal_device ttm processor_thermal_rfim processor_thermal_mbox intel_soc_dts_iosf wmi
[  699.182461]  int3403_thermal int340x_thermal_zone int3400_thermal acpi_thermal_rel intel_pmc_core squashfs drm drm_panel_orientation_quirks efivarfs intel_ishtp_hid spi_pxa2xx_platform psmouse intel_lpss_pci xhci_pci intel_lpss intel_ish_ipc idma64 xhci_hcd mfd_core vmd intel_ishtp i2c_hid_acpi i2c_hid [last unloaded: snd_soc_rt711_sdca]
[  699.182472] CPU: 7 PID: 1422 Comm: modprobe Not tainted 5.18.0-rc2-test-05262-g84c220b9448a #186
[  699.182474] Hardware name: Dell Inc. Latitude 9420/0208BI, BIOS 99.1.42 08/21/2020
[  699.182475] RIP: 0010:__mutex_lock+0x8e6/0x960
[  699.182477] Code: c0 0f 84 9c f7 ff ff 44 8b 1d ee 77 f5 00 45 85 db 0f 85 8c f7 ff ff 48 c7 c6 bb 79 be af 48 c7 c7 3e 1f bd af e8 33 1a f9 ff <0f> 0b e9 72 f7 ff ff 65 48 8b 04 25 00 af 01 00 48 8b 10 83 e2 08
[  699.182478] RSP: 0018:ffff966e013d79e0 EFLAGS: 00010282
[  699.182479] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  699.182480] RDX: 0000000000000001 RSI: ffffffffafbf57f7 RDI: 00000000ffffffff
[  699.182481] RBP: 0000000000000000 R08: ffffffffaff62d68 R09: 0000000000009ffb
[  699.182482] R10: 00000000000008e1 R11: ffffffffaff40298 R12: ffff9141266e4df0
[  699.182483] R13: ffffffffc072360b R14: 0000000000000000 R15: ffffffffc073b0e0
[  699.182483] FS:  00007f6ac7e6f540(0000) GS:ffff91447f600000(0000) knlGS:0000000000000000
[  699.182484] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  699.182485] CR2: 0000564c7a4d7d08 CR3: 0000000119544005 CR4: 0000000000770ee0
[  699.182486] PKRU: 55555554
[  699.182487] Call Trace:
[  699.182489]  <TASK>
[  699.182491]  ? lock_release+0x148/0x430
[  699.182495]  rt711_sdca_jack_init+0x1b/0x1d0 [snd_soc_rt711_sdca]
[  699.182498]  rt711_sdca_set_jack_detect+0x3b/0x90 [snd_soc_rt711_sdca]
[  699.182500]  snd_soc_component_set_jack+0x24/0x50 [snd_soc_core]
[  699.182512]  rt711_sdca_rtd_init+0x153/0x170 [snd_soc_sof_sdw]
[  699.182515]  ? soc_probe_component+0x2f/0x300 [snd_soc_core]
[  699.182521]  snd_soc_link_init+0x1e/0x40 [snd_soc_core]
[  699.182529]  snd_soc_bind_card+0x62a/0xce0 [snd_soc_core]
[  699.182535]  ? is_module_address+0x43/0x70
[  699.182538]  ? lockdep_init_map_type+0x51/0x240
[  699.182540]  devm_snd_soc_register_card+0x43/0x80 [snd_soc_core]
[  699.182547]  mc_probe+0x9bb/0x1060 [snd_soc_sof_sdw]
[  699.182551]  platform_probe+0x54/0xb0
[  699.182555]  really_probe+0x199/0x380
[  699.182557]  __driver_probe_device+0xfe/0x180
[  699.182558]  driver_probe_device+0x1e/0x90
[  699.182560]  __driver_attach+0xc4/0x1d0
[  699.182561]  ? __device_attach_driver+0xe0/0xe0
[  699.182563]  ? __device_attach_driver+0xe0/0xe0
[  699.182564]  bus_for_each_dev+0x78/0xc0
[  699.182566]  bus_add_driver+0x14c/0x1f0
[  699.182568]  driver_register+0x8f/0xe0
[  699.182570]  ? 0xffffffffc0425000
[  699.182571]  do_one_initcall+0x6f/0x270
[  699.182574]  ? kmem_cache_alloc_trace+0x4f/0x210
[  699.182577]  do_init_module+0x4c/0x240
[  699.182579]  __do_sys_finit_module+0xb4/0x120
[  699.182581]  do_syscall_64+0x38/0x90
[  699.182584]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  699.182586] RIP: 0033:0x7f6ac7fb176d
[  699.182588] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f3 36 0d 00 f7 d8 64 89 01 48
[  699.182589] RSP: 002b:00007fffe6e41c28 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[  699.182590] RAX: ffffffffffffffda RBX: 0000564c7a4cda70 RCX: 00007f6ac7fb176d
[  699.182591] RDX: 0000000000000000 RSI: 0000564c7a4d5b10 RDI: 0000000000000004
[  699.182592] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000000
[  699.182592] R10: 0000000000000004 R11: 0000000000000246 R12: 0000564c7a4d5b10
[  699.182593] R13: 0000000000000000 R14: 0000564c7a4cdba0 R15: 0000564c7a4cda70
[  699.182595]  </TASK>
[  699.182595] ---[ end trace 0000000000000000 ]---
[  699.189384] rt711-sdca sdw:0:025d:0711:01: in rt711_sdca_jack_init enable
[  699.182429] DEBUG_LOCKS_WARN_ON(lock->magic != lock)
[  699.182432] WARNING: CPU: 7 PID: 1422 at kernel/locking/mutex.c:579 __mutex_lock+0x8e6/0x960
[  699.182437] Modules linked in: snd_soc_sof_sdw(+) snd_soc_intel_sof_maxim_common snd_soc_rt711_sdca snd_ctl_led ledtrig_audio fuse snd_soc_rt1316_sdw snd_soc_rt715_sdca regmap_sdw_mbq regmap_sdw snd_sof_ipc_msg_injector snd_sof_probes snd_soc_dmic snd_sof_ipc_flood_test snd_sof_pci_intel_tgl snd_sof_intel_hda_common soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_pci snd_sof_xtensa_dsp snd_sof snd_sof_utils snd_soc_acpi_intel_match snd_soc_acpi soundwire_bus snd_soc_core snd_compress snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep snd_hda_core snd_pcm wmi_bmof snd_seq_midi snd_seq_midi_event ax88179_178a snd_rawmidi usbnet snd_seq snd_seq_device x86_pkg_temp_thermal snd_timer intel_powerclamp snd soundcore hid_multitouch iwlmvm iwlwifi mei_me mei i915 i2c_algo_bit drm_buddy drm_dp_helper processor_thermal_device_pci_legacy drm_kms_helper processor_thermal_device ttm processor_thermal_rfim processor_thermal_mbox intel_soc_dts_iosf wmi
[  699.182461]  int3403_thermal int340x_thermal_zone int3400_thermal acpi_thermal_rel intel_pmc_core squashfs drm drm_panel_orientation_quirks efivarfs intel_ishtp_hid spi_pxa2xx_platform psmouse intel_lpss_pci xhci_pci intel_lpss intel_ish_ipc idma64 xhci_hcd mfd_core vmd intel_ishtp i2c_hid_acpi i2c_hid [last unloaded: snd_soc_rt711_sdca]
[  699.182472] CPU: 7 PID: 1422 Comm: modprobe Not tainted 5.18.0-rc2-test-05262-g84c220b9448a #186
[  699.182474] Hardware name: Dell Inc. Latitude 9420/0208BI, BIOS 99.1.42 08/21/2020
[  699.182475] RIP: 0010:__mutex_lock+0x8e6/0x960
[  699.182477] Code: c0 0f 84 9c f7 ff ff 44 8b 1d ee 77 f5 00 45 85 db 0f 85 8c f7 ff ff 48 c7 c6 bb 79 be af 48 c7 c7 3e 1f bd af e8 33 1a f9 ff <0f> 0b e9 72 f7 ff ff 65 48 8b 04 25 00 af 01 00 48 8b 10 83 e2 08
[  699.182478] RSP: 0018:ffff966e013d79e0 EFLAGS: 00010282
[  699.182479] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  699.182480] RDX: 0000000000000001 RSI: ffffffffafbf57f7 RDI: 00000000ffffffff
[  699.182481] RBP: 0000000000000000 R08: ffffffffaff62d68 R09: 0000000000009ffb
[  699.182482] R10: 00000000000008e1 R11: ffffffffaff40298 R12: ffff9141266e4df0
[  699.182483] R13: ffffffffc072360b R14: 0000000000000000 R15: ffffffffc073b0e0
[  699.182483] FS:  00007f6ac7e6f540(0000) GS:ffff91447f600000(0000) knlGS:0000000000000000
[  699.182484] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  699.182485] CR2: 0000564c7a4d7d08 CR3: 0000000119544005 CR4: 0000000000770ee0
[  699.182486] PKRU: 55555554
[  699.182487] Call Trace:
[  699.182489]  <TASK>
[  699.182491]  ? lock_release+0x148/0x430
[  699.182495]  rt711_sdca_jack_init+0x1b/0x1d0 [snd_soc_rt711_sdca]
[  699.182498]  rt711_sdca_set_jack_detect+0x3b/0x90 [snd_soc_rt711_sdca]
[  699.182500]  snd_soc_component_set_jack+0x24/0x50 [snd_soc_core]
[  699.182512]  rt711_sdca_rtd_init+0x153/0x170 [snd_soc_sof_sdw]
[  699.182515]  ? soc_probe_component+0x2f/0x300 [snd_soc_core]
[  699.182521]  snd_soc_link_init+0x1e/0x40 [snd_soc_core]
[  699.182529]  snd_soc_bind_card+0x62a/0xce0 [snd_soc_core]
[  699.182535]  ? is_module_address+0x43/0x70
[  699.182538]  ? lockdep_init_map_type+0x51/0x240
[  699.182540]  devm_snd_soc_register_card+0x43/0x80 [snd_soc_core]
[  699.182547]  mc_probe+0x9bb/0x1060 [snd_soc_sof_sdw]
[  699.182551]  platform_probe+0x54/0xb0
[  699.182555]  really_probe+0x199/0x380
[  699.182557]  __driver_probe_device+0xfe/0x180
[  699.182558]  driver_probe_device+0x1e/0x90
[  699.182560]  __driver_attach+0xc4/0x1d0
[  699.182561]  ? __device_attach_driver+0xe0/0xe0
[  699.182563]  ? __device_attach_driver+0xe0/0xe0
[  699.182564]  bus_for_each_dev+0x78/0xc0
[  699.182566]  bus_add_driver+0x14c/0x1f0
[  699.182568]  driver_register+0x8f/0xe0
[  699.182570]  ? 0xffffffffc0425000
[  699.182571]  do_one_initcall+0x6f/0x270
[  699.182574]  ? kmem_cache_alloc_trace+0x4f/0x210
[  699.182577]  do_init_module+0x4c/0x240
[  699.182579]  __do_sys_finit_module+0xb4/0x120
[  699.182581]  do_syscall_64+0x38/0x90
[  699.182584]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  699.182586] RIP: 0033:0x7f6ac7fb176d
[  699.182588] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f3 36 0d 00 f7 d8 64 89 01 48
[  699.182589] RSP: 002b:00007fffe6e41c28 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[  699.182590] RAX: ffffffffffffffda RBX: 0000564c7a4cda70 RCX: 00007f6ac7fb176d
[  699.182591] RDX: 0000000000000000 RSI: 0000564c7a4d5b10 RDI: 0000000000000004
[  699.182592] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000000
[  699.182592] R10: 0000000000000004 R11: 0000000000000246 R12: 0000564c7a4d5b10
[  699.182593] R13: 0000000000000000 R14: 0000564c7a4cdba0 R15: 0000564c7a4cda70
[  699.182595]  </TASK>
[  699.182595] ---[ end trace 0000000000000000 ]---
[  699.189384] rt711-sdca sdw:0:025d:0711:01: in rt711_sdca_jack_init enable

@plbossart

@plbossart What does DEBUG_LOCKS_WARN_ON(lock->magic != lock) means?
What will happen if we reload rt711-saca driver when rt711-sdca is just attached?
rt711_sdca_calibration will take some time. It is called when rt711-sdca is attached.
If we remove rt711-sdca driver and insmod it again when rt711-sdca just attached.
Will below scenario cause any issue?

rt711_sdca_calibration -> mutex_lock(&rt711->calibrate_mutex);, but didn't call mutex_unlock(&rt711->calibrate_mutex); yet
Reload rt711-sdca driver -> rt711_sdca_init() -> rt711->first_hw_init = false;
rt711-sdca reattach -> rt711_sdca_io_init() -> mutex_init(&rt711->calibrate_mutex);

I don't understand what this warning means, and I have to find the sequence that triggers it. One possibility is that on .remove some workqueues are still running and not properly cancelled.

I found the sequence, it's when loading the machine driver a second time

echo "removing machine driver"
modprobe -r snd-soc-sof-sdw
sleep 1
dmesg | grep DEBUG

echo "removing headset"
modprobe -r snd_soc_rt711_sdca
sleep 1
dmesg | grep DEBUG

echo "adding headset"
modprobe snd_soc_rt711_sdca
sleep 1
dmesg | grep DEBUG

echo "adding machine driver"
modprobe snd-soc-sof-sdw
sleep 1
dmesg | grep DEBUG

output:

removing machine driver
removing headset
adding headset
adding machine driver
[  289.228362] DEBUG_LOCKS_WARN_ON(lock->magic != lock)

If I increase the sleep to 5s, I am not able to reproduce, so there's likely a workqueue that's not cancelled properly.

ASoC: rt711-sdca-sdw: fix calibrate mutex initialization

Looks like you already have a solution 85d4391 :)

yep, i think the initialization needs to be done by the same probe callback, in the existing code one of the mutexes was initialized when the machine driver was probed and the other when the codec driver was probed. I don't think there was a functional issue, it's just that the code didn't allow for proper lock detection.

fixed, closing

ASoC: rt711-sdca-sdw: fix calibrate mutex initialization

Navigation Menu

Repository navigation

SoundWire: rt711-sdca: mutex_lock warning #3644

36 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

SoundWire: rt711-sdca: mutex_lock warning #3644

Description

Activity

bardliao commented on May 12, 2022

plbossart commented on May 12, 2022

plbossart commented on May 12, 2022

bardliao commented on May 13, 2022

plbossart commented on May 13, 2022

plbossart commented on May 13, 2022

36 remaining items

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions