SoundWire: transfer timed out in suspend-resume-without-audio

[plbossart]

Internal daily tests on LNL show a problem during suspend-resume

planresultdetail/37723?model=LNLM_SDW_AIOC&testcase=check-suspend-resume-without-audio-20

[ 1189.981021] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1189.981057] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 write addr a03d count 0
[ 1189.981104] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to set private value: 610003d <= ffff ret=-5
[ 1190.484866] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1190.484902] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 read addr 803f count 0
[ 1190.484934] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to get private value: 610003f => 0000 ret=-5
[ 1190.484991] kernel: soundwire_intel soundwire_intel.link.3: IO transfer timed out, cmd 3 device 1 addr 45 len 1
[ 1190.485016] kernel: soundwire sdw-master-0-3: trf on Slave 1 failed:-110 write addr 45 count 0
[ 1190.485034] kernel: rt1316-sdca sdw:0:3:025d:1316:01: SDW_SCP_SYSTEMCTRL write failed:-110
[ 1190.485048] kernel: rt1316-sdca sdw:0:3:025d:1316:01: clock stop prepare failed:-110
[ 1190.485061] kernel: soundwire_intel soundwire_intel.link.3: prepare clock stop failed -110
[ 1190.485073] kernel: soundwire_intel soundwire_intel.link.3: intel_stop_bus: cannot stop clock: -110
[ 1190.485133] kernel: soundwire_intel soundwire_intel.link.1: IO transfer timed out, cmd 3 device 7 addr 45 len 1
[ 1190.485151] kernel: soundwire sdw-master-0-1: trf on Slave 7 failed:-110 write addr 45 count 0
[ 1190.485166] kernel: rt715-sdca sdw:0:1:025d:0714:01: SDW_SCP_SYSTEMCTRL write failed:-110
[ 1190.485178] kernel: rt715-sdca sdw:0:1:025d:0714:01: clock stop prepare failed:-110
[ 1190.485189] kernel: soundwire_intel soundwire_intel.link.1: prepare clock stop failed -110
[ 1190.485200] kernel: soundwire_intel soundwire_intel.link.1: intel_stop_bus: cannot stop clock: -110
[ 1190.485233] kernel: soundwire_intel soundwire_intel.link.2: IO transfer timed out, cmd 3 device 1 addr 45 len 1
[ 1190.485252] kernel: soundwire sdw-master-0-2: trf on Slave 1 failed:-110 write addr 45 count 0
[ 1190.485265] kernel: rt1316-sdca sdw:0:2:025d:1316:01: SDW_SCP_SYSTEMCTRL write failed:-110
[ 1190.485276] kernel: rt1316-sdca sdw:0:2:025d:1316:01: clock stop prepare failed:-110
[ 1190.485287] kernel: soundwire_intel soundwire_intel.link.2: prepare clock stop failed -110
[ 1190.485298] kernel: soundwire_intel soundwire_intel.link.2: intel_stop_bus: cannot stop clock: -110
[ 1190.988840] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1190.988877] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 read addr 8035 count 0
[ 1190.988909] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to get private value: 6100035 => 0000 ret=-5
[ 1191.492837] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1191.492873] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 read addr 8008 count 0
[ 1191.492906] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to get private value: 2000008 => 0000 ret=-5
[ 1191.996852] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1191.996888] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 read addr 8009 count 0
[ 1191.996919] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to get private value: 2000009 => 0000 ret=-5
[ 1192.500863] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1192.500904] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 read addr 8011 count 0
[ 1192.500936] kernel: rt711-sdca sdw:0:0:025d:0711:01: Failed to get private value: 2000011 => 0000 ret=-5
[ 1193.004834] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 5c len 1
[ 1193.004911] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 5c count 0
[ 1193.508759] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 5d len 1
[ 1193.508836] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 5d count 0
[ 1193.508864] kernel: snd_soc_rt711_sdca:rt711_sdca_jack_init: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_init enable
[ 1193.508891] kernel: snd_soc_rt711_sdca:rt711_sdca_io_init: rt711-sdca sdw:0:0:025d:0711:01: rt711_sdca_io_init hw_init complete
[ 1193.508906] kernel: soundwire_bus:sdw_handle_slave_status: rt711-sdca sdw:0:0:025d:0711:01: signaling initialization completion for Slave 6
[ 1194.012923] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 2f5a len 1
[ 1194.012989] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 2f5a count 0
[ 1194.516843] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[ 1194.516880] kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-5 write addr a006 count 0
[ 1194.615731] kernel: snd_sof_pci_intel_mtl:mtl_dsp_core_power_down: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000000 successful
[ 1194.617026] kernel: snd_sof_pci_intel_mtl:mtl_power_down_dsp: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x0 successful
[ 1198.129717] kernel: PM: suspend entry (s2idle)
[ 1198.131733] kernel: Filesystems sync: 0.001 seconds
[ 1198.144764] kernel: rfkill: input handler enabled
[ 1198.146006] kernel: Freezing user space processes
[ 1198.148552] kernel: Freezing user space processes completed (elapsed 0.002 seconds)
[ 1198.148558] kernel: OOM killer disabled.
[ 1198.148560] kernel: Freezing remaining freezable tasks
[ 1198.149784] kernel: Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[ 1198.149790] kernel: printk: Suspending console(s) (use no_console_suspend to debug)
[ 1198.151787] kernel: asix 3-3.1:1.0 enx000ec6706f71: Link is Down
[ 1198.153516] kernel: e1000e: EEE TX LPI TIMER: 00000011
[ 1198.578526] kernel: ACPI: EC: interrupt blocked
[ 1228.592783] kernel: ACPI Error: Aborting method \_SB.CSD3 due to previous error (AE_AML_LOOP_TIMEOUT) (20230628/psparse-529)
[ 1228.592843] kernel: ACPI Error: Aborting method \_SB.PC00.GLAN._PS3 due to previous error (AE_AML_LOOP_TIMEOUT) (20230628/psparse-529)
[ 1228.601751] kernel: ACPI BIOS Error (bug): Could not resolve symbol [\_SB.PC00.LPCB.H_EC.ECNT.PPOE], AE_NOT_FOUND (20230628/psargs-330)
[ 1228.601759] kernel: ACPI Error: Aborting method \_SB.PC00.LPCB.H_EC.ECNT due to previous error (AE_NOT_FOUND) (20230628/psparse-529)
[ 1228.601764] kernel: ACPI Error: Aborting method \_SB.PC00.LPCB.NTIR due to previous error (AE_NOT_FOUND) (20230628/psparse-529)
[ 1228.601769] kernel: ACPI Error: Aborting method \_SB.PEPD._DSM due to previous error (AE_NOT_FOUND) (20230628/psparse-529)
[ 1228.607508] kernel: ACPI: EC: interrupt unblocked
[ 1228.642897] kernel: nvme nvme0: Shutdown timeout set to 10 seconds
[ 1228.646188] kernel: nvme nvme0: 8/0/0 default/read/poll queues
[ 1229.122508] kernel: asix 3-3.1:1.0 enx000ec6706f71: configuring for phy/internal link mode
[ 1229.371294] kernel: OOM killer enabled.
[ 1229.371296] kernel: Restarting tasks ... done.
[ 1229.372817] kernel: random: crng reseeded on system resumption
[ 1229.374490] kernel: PM: suspend exit
[ 1229.405503] kernel: rfkill: input handler disabled
[ 1231.230807] kernel: asix 3-3.1:1.0 enx000ec6706f71: Link is Up - 100Mbps/Full - flow control off

Unfortunately the dmesg log is too short to show when this happened.

FYI @bardliao @keqiaozhang @aiChaoSONG @fredoh9

[marc-hb]

Unfortunately the dmesg log is too short to show when this happened.

This is hopefully specific to suspend/resume tests. We obviously don't use dmesg to collect kernel logs but journalctl -k instead and I've seen very long kernel logs in the past.

Anyway, here's the complete log attached.
b13.log

[plbossart]

Thanks @marc-hb this is VERY useful.

The logs indicate that the RT711-sdca was enumerated, but never completed its initialization. This could be a hardware issue while doing all the regmap sync or configuration.

Rt711-initialization-failed.txt

What I don't get is this sequence after the enumeration

22:57:27 systemd[1]: Stopped target Sound Card.
22:57:27 acpid[417]: input device has been disconnected, fd 10
22:57:27 /usr/libexec/gdm-x-session[898]: (II) event4  - sof-soundwire Headset Jack: device removed
22:57:27 /usr/libexec/gdm-x-session[898]: (II) config/udev: removing device sof-soundwire Headset Jack

I have no idea what this does, but it could very well be a race condition where the codec is removed while being initialized.

I don't have any background on systemd, but I am sure @ujfalusi will love this bug :-)

[plbossart]

adding @bardliao and @shumingfan for comments.

[shumingfan]

@plbossart Sorry, I have no idea about this problem.
Is it possible to enable the SdW access log and test again?

--- a/drivers/base/regmap/regmap.c
+++ b/drivers/base/regmap/regmap.c
@@ -30,7 +30,7 @@
  * sort of problem defining LOG_DEVICE will add printks for basic
  * register I/O on a specific device.
  */
-#undef LOG_DEVICE
+#define LOG_DEVICE "sdw:0:0:025d:0711:01"

[bardliao]

@shumingfan Please check the log with #define LOG_DEVICE "sdw:0:0:025d:0711:01"
dmesg_lnl.txt

[bardliao]

@plbossart I noticed that rt1316 and rt715 fail to access sdw registers, too in dmesg_lnl.txt.

[   38.958529] rt1316-sdca sdw:0:3:025d:1316:01: SDW_SCP_SYSTEMCTRL write failed:-110
[   38.958544] rt1316-sdca sdw:0:3:025d:1316:01: clock stop prepare failed:-110
[   38.958556] soundwire_intel soundwire_intel.link.3: prepare clock stop failed -110
[   38.958568] soundwire_intel soundwire_intel.link.3: intel_stop_bus: cannot stop clock: -110
[   38.958662] soundwire_intel soundwire_intel.link.2: IO transfer timed out, cmd 3 device 1 addr 45 len 1
[   38.958701] soundwire sdw-master-0-2: trf on Slave 1 failed:-110 write addr 45 count 0
[   38.958717] rt1316-sdca sdw:0:2:025d:1316:01: SDW_SCP_SYSTEMCTRL write failed:-110
[   38.958729] rt1316-sdca sdw:0:2:025d:1316:01: clock stop prepare failed:-110
[   38.958740] soundwire_intel soundwire_intel.link.2: prepare clock stop failed -110
[   38.958753] soundwire_intel soundwire_intel.link.2: intel_stop_bus: cannot stop clock: -110
[   38.958804] soundwire_intel soundwire_intel.link.1: IO transfer timed out, cmd 3 device 7 addr 45 len 1
[   38.958824] soundwire sdw-master-0-1: trf on Slave 7 failed:-110 write addr 45 count 0
[   38.958839] rt715-sdca sdw:0:1:025d:0714:01: SDW_SCP_SYSTEMCTRL write failed:-110
[   38.958851] rt715-sdca sdw:0:1:025d:0714:01: clock stop prepare failed:-110

And they are on different sdw links.

[plbossart]

@bardliao the error on other links happens 3 seconds later while trying to suspend. It's probably failing as a result of ripple effects from the first error IMHO, I am not sure the error handling is completely independent across links - the interrupt handling is common for example.

[plbossart]

oh wait @bardliao, are you saying this bug is reproducible? I thought it was a random issue...

[plbossart]

Answering to my own question, this issue is present in the last daily test

#/result/planresultdetail/38021?model=LNLM_SDW_AIOC&testcase=check-suspend-resume-without-audio-20

Oh well.

[bardliao]

oh wait @bardliao, are you saying this bug is reproducible? I thought it was a random issue...

Yes, I can reproduce it easily on LNLM_SDW_AIOC devices.

[bardliao]

@plbossart I added some trace, and it looks like that snd_sof_device_remove is called while rt711 haven't finished its initialization job. The test is ongoing, but I didn't reproduce the issue with the TPLG=/lib/firmware/intel/sof-ipc4-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg MODEL=LNLM_SDW_AIOC SOF_TEST_INTERVAL=5 ~/sof-test/test-case/check-suspend-resume.sh -l 20 command so far. I.e. without the -u option. @keqiaozhang FYI

[bardliao]

The issue is not reproducible if I add 5 sec delay between unload the drivers and suspend/resume starts, too.

diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh
index d0c3b44..e12501e 100755
--- a/test-case/check-suspend-resume.sh
+++ b/test-case/check-suspend-resume.sh
@@ -150,6 +150,7 @@ main()
     $already_unloaded || $keep_modules || "$TOPDIR"/tools/kmod/sof_remove.sh ||
         die "Failed to unload audio drivers"

+    sleep 5
     expected_wakeup_count=$(cat /sys/power/wakeup_count)
     expected_stats_success=$(cat /sys/power/suspend_stats/success)
     save_initial_stats

[bardliao]

In fact, I can reproduce the issue with simply sudo ./sof-test/tools/kmod/sof_remove.sh. The issue is that soundwire_intel.link resume runtime is trigger when snd_sof_pci_intel_lnl is unloading. And the codecs are attached and doing its initialization job. Then codecs can no longer access sdw registers once snd_sof_pci_intel_lnl is unloaded. What I didn't get is that why soundwire_intel.link resume runtime is only trigger on LNL but not MTL platforms. @ranj063 @ujfalusi Any idea about the issue?