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

@bardliao

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

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

@marc-hb

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 :-)

@bardliao

adding @bardliao and @shumingfan for comments.

@plbossart

@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"

@shumingfan

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

@plbossart

@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.

@bardliao

@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.

@bardliao

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

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.

@plbossart

@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

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

@ranj063

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?

The issue is that intel_shim_check_wake() return 1 unconditionally. So, whenever SOF resume, we will resume sdw manager devices. Unfortunately, I don't have a good solution for this issue. Maybe check how HW can provide proper waken detection information.

@bardliao

but why are we unloading modules in a suspend-resume test case? Not following @bardliao

@bardliao

but why are we unloading modules in a suspend-resume test case? Not following @bardliao

That's the first step of the check-suspend-resume-without-audio-20 test. The check-suspend-resume-without-audio-20 test will unload all audio modules then test suspend/resume.

ok, but they shouldn't there be some sort of cancel_work_sync() in the rt711 remove part?

The delay only masks the fact that there is a race condition that the codec driver does not handle well.

But rt711_sdca_dev_resume is called after the issue happened.

The sequence is that

sof resume
soundwire_intel.link resume
Codec attached, and codec driver start to initialize the codec
sof_pci_remove() is called
sdw bus stop working, and SCP Msg trf timed out happens
rt711_sdca_dev_resume() is called

dmesg_lnl_2.txt

But rt711_sdca_dev_resume is called after the issue happened.

The sequence is that

sof resume

soundwire_intel.link resume

Codec attached, and codec driver start to initialize the codec

sof_pci_remove() is called

That should also call the .remove for the codec driver, otherwise there's something really problematic, no?

sdw bus stop working, and SCP Msg trf timed out happens

rt711_sdca_dev_resume() is called

@plbossart

But rt711_sdca_dev_resume is called after the issue happened.
The sequence is that

sof resume

soundwire_intel.link resume

Codec attached, and codec driver start to initialize the codec

sof_pci_remove() is called

That should also call the .remove for the codec driver, otherwise there's something really problematic, no?

sdw bus stop working, and SCP Msg trf timed out happens

rt711_sdca_dev_resume() is called

Thanks @plbossart The comment does give me better understanding to the issue. Please see #4833 for the fix.

@bardliao

but why are we unloading modules in a suspend-resume test case? Not following @bardliao

That's the first step of the check-suspend-resume-without-audio-20 test. The check-suspend-resume-without-audio-20 test will unload all audio modules then test suspend/resume.

In fact, I can reproduce the issue with simply sudo ./sof-test/tools/kmod/sof_remove.sh.

We have a kmod-load-unload.sh test but we don't run it for LNL right now. I don't know why.

Could it be that the load-unload test was disabled because of the old HDMI issue, but now we have a means to disable HDMI with a kernel parameter so that test should definitively be run....

@plbossart

@plbossart, @bardliao - does the fix #4849 resolve this issue?

It's possible that the issue re-appeared since, see #4889

That's what happens when the devices are not in CI... Things work at some point and drift. Oh well.

The issue in #4889 had nothing to do with this, so closing.

Navigation Menu

Repository navigation

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

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

marc-hb commented on Feb 10, 2024

plbossart commented on Feb 15, 2024

plbossart commented on Feb 15, 2024

shumingfan commented on Feb 16, 2024

bardliao commented on Feb 16, 2024

bardliao commented on Feb 16, 2024

plbossart commented on Feb 16, 2024

plbossart commented on Feb 16, 2024

plbossart commented on Feb 16, 2024

bardliao commented on Feb 19, 2024

bardliao commented on Feb 19, 2024

bardliao commented on Feb 19, 2024

bardliao commented on Feb 20, 2024

bardliao commented on Feb 20, 2024

plbossart commented on Feb 20, 2024

bardliao commented on Feb 20, 2024

plbossart commented on Feb 20, 2024

bardliao commented on Feb 20, 2024

plbossart commented on Feb 21, 2024

bardliao commented on Feb 22, 2024

marc-hb commented on Feb 26, 2024

plbossart commented on Feb 26, 2024

salwansearty commented on Mar 28, 2024

plbossart commented on Mar 28, 2024

plbossart commented on Apr 11, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions