[BUG] [MTL] soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out

[keqiaozhang]

Describe the bug
Found this issue in CI daily test on MTL-SDW platform. This issue happened when testing suspend/resume without audio. But it's very hard to reproduce.

dmesg

[  112.372990] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0: MOD_SET_DX
[  112.373301] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[  112.373521] kernel: snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful
[  112.874434] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  112.874490] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 read addr a000 count 0
[  112.874545] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to get private value: 5800000 => 2580 ret=-5
[  113.378380] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  113.378429] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 read addr 8000 count 0
[  113.378478] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to get private value: 5800000 => 2580 ret=-5
[  113.882314] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  113.882329] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 read addr 8000 count 0
[  113.882340] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to get private value: 5800000 => 2580 ret=-5
[  114.386255] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  114.386303] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 read addr 8000 count 0
[  114.386352] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to get private value: 5800000 => 0040 ret=-5
[  114.890210] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  114.890259] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 write addr a06f count 0
[  114.890310] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to set private value: 200006f <= 25c0 ret=-5
[  115.394151] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  115.394198] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 write addr a04a count 0
[  115.394247] kernel: rt711-sdca sdw:0:025d:0711:01: Failed to set private value: 200004a <= 201b ret=-5
[  115.394300] kernel: snd_soc_rt711_sdca:rt711_sdca_calibration: rt711-sdca sdw:0:025d:0711:01: rt711_sdca_calibration calibration complete, ret=0
[  115.898098] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  115.898147] kernel: soundwire sdw-master-0: trf on Slave 4 failed:-5 write addr 8300 count 0

To Reproduce
~/sof-test/test-case/check-suspend-resume.sh -l 20 -u

Reproduction Rate
No reproductions after 200+ iterations manual check. Very hard to reproduce it.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: : f02bb90dd84e
   • SOF: : d7da25fc2537
2. Name of the topology file
   • Topology: {sof-mtl-rt711-4ch.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {MTL_RVP_SDW}

Uploading dmesg.txt…

[bardliao]

@keqiaozhang It is easily reproducible is you run ./sof_remove.sh; ./sof_insert.sh twice quickly. The reason is that we disable sdw irq when sof pci driver is removed, but rt711_sdca_io_init is still running. In other words, we disabled sdw irq when codec driver is still communicating to the codec. @plbossart FYI

[plbossart]

Could it be a codec bug @bardliao, where we remove the codec driver before the on-going commands are complete? Looks like a missing cancel_work_sync to me, no?

[plbossart]

Actually with the PCI deferred workqueue-based probe I am not sure how we can deal with the insert-remove scenario. There is a built-in race condition where we can call the PCI .remove while the rest of the system is being initialized. And even when the PCI deferred probe completes, the system might still be initializating. This looks quite different to the initial suspend-resume reported in this issue @bardliao ?

[bardliao]

@plbossart I think it is the same issue. ~/sof-test/test-case/check-suspend-resume.sh -l 20 -u where -u means to reload unload audio modules. And from the log

[  112.373521] kernel: snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful
[  112.874434] kernel: soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out

kernel: snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful --> This is to disable sdw irq
Then SCP Msg trf timed out happens.
I added some trace for debugging and below is the log that I reproduced with ~/sof-test/test-case/check-suspend-resume.sh -l 20 -u

[  167.840508] bard: rt711_sdca_index_read reading 0x61 0x3
[  167.840756] bard: hda_sdw_int_enable enable 0
[  167.840765] bard: mtl_enable_sdw_irq enable 0
[  167.840771] CPU: 5 PID: 7720 Comm: rmmod Not tainted 6.2.0-rc8+ #344
[  167.840783] Hardware name: Intel Corporation Meteor Lake Client Platform/MTL-P DDR5 SODIMM SBS RVP, BIOS MTLPFWI1.R00.3084.D85.2303071631 03/07/2023
[  167.840791] Call Trace:
[  167.840797]  <TASK>
[  167.840806]  dump_stack_lvl+0x38/0x4c
[  167.840829]  mtl_enable_sdw_irq+0x33/0x1b0 [snd_sof_intel_hda_common]
[  167.840920] bard: rt711_sdca_index_read read 0x61 0x3 return 0
[  167.840913]  hda_dsp_remove.cold+0xa/0xf [snd_sof_intel_hda_common]
[  167.840988]  snd_sof_device_remove+0xe3/0xf0 [snd_sof]
[  167.841072]  sof_pci_remove+0x1e/0x50 [snd_sof_pci]
[  167.841094]  pci_device_remove+0x37/0xa0
[  167.841114]  device_release_driver_internal+0x1b8/0x240
[  167.841136]  driver_detach+0x4b/0x90
[  167.841150]  bus_remove_driver+0x5c/0xe0
[  167.841166]  pci_unregister_driver+0x3f/0x90
[  167.841183]  __do_sys_delete_module+0x1a6/0x2a0
[  167.841205]  ? fpregs_assert_state_consistent+0x26/0x50
[  167.841218]  ? exit_to_user_mode_prepare+0x37/0x120
[  167.841237]  do_syscall_64+0x3c/0x90
[  167.841253]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
[  167.841266] RIP: 0033:0x7fe88ac36c9b
[  167.841276] Code: 73 01 c3 48 8b 0d 95 21 0f 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 65 21 0f 00 f7 d8 64 89 01 48
[  167.841287] RSP: 002b:00007ffcb86097b8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[  167.841302] RAX: ffffffffffffffda RBX: 000055f1db7ff770 RCX: 00007fe88ac36c9b
[  167.841310] RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055f1db7ff7d8
[  167.841317] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[  167.841324] R10: 00007fe88acceac0 R11: 0000000000000206 R12: 00007ffcb8609a10
[  167.841331] R13: 000055f1db7ff2a0 R14: 00007ffcb860a6c7 R15: 000055f1db7ff770
[  167.841366]  </TASK>
[  167.841396] snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful
[  168.347479] soundwire_intel soundwire_intel.link.0: SCP Msg trf timed out
[  168.347512] soundwire sdw-master-0: trf on Slave 4 failed:-5 write addr a047 count 0
[  168.347539] rt711-sdca sdw:0:025d:0711:01: Failed to set private value: 2000047 <= a43e ret=-5
[  168.851359] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 4 addr 2f5a len 1

Besides, @keqiaozhang can't reproduce the issue after I removed hda_sdw_int_enable(sdev, false); from hda_sdw_exit.

[plbossart]

@bardliao sorry I don't see how suspend and resume can be similar to remove/insert cases. In the former case we go through suspend and the other remove. Different code paths.

And with suspend, I don't see how we can suspend at the manager level without having the codec device already suspended.

So no, not convinced at all they are the same issue, because the parent-child relationship adds a structure that should prevent this timeout from happening.

[bardliao]

@bardliao sorry I don't see how suspend and resume can be similar to remove/insert cases. In the former case we go through suspend and the other remove. Different code paths.

And with suspend, I don't see how we can suspend at the manager level without having the codec device already suspended.

So no, not convinced at all they are the same issue, because the parent-child relationship adds a structure that should prevent this timeout from happening.

@plbossart The issue is not related to suspend/resume. It happened when CI run the " ~/sof-test/test-case/check-suspend-resume.sh -l 20 -u" command and failed at the module reload stage. It won't reproduce if we run " ~/sof-test/test-case/check-suspend-resume.sh -l 20". i.e. without the -u option.

[plbossart]

Ah, thanks for the precision @bardliao

@keqiaozhang the description of the issue is invalid then. it should not be listed as a suspend issue....

I wasn't even aware this is a test we run. Why are we doing this? It's not like suspend-resume is easy in the first place.
I am completely lost of the purpose of this test.
We can do load/unload
We can do suspend/resume
Why do both?

@keqiaozhang @bardliao @marc-hb @greg-intel @fredoh9 any context on why we enabled this test?

[marc-hb]

We can do load/unload
We can do suspend/resume
Why do both?

The -u option does NOT test both at the same time (which would admittedly never happen in the real world). The -u option unloads audio drivers BEFORE testing suspend/resume and reloads them AFTER. The -u option is meant to spot non-audio suspend/resume issues.

sof-test$ ./test-case/check-suspend-resume.sh -h

    -u |  --unload-audio
	unload audio modules for the test
	Default Value: Off

Failure is easily reproducible is you run ./sof_remove.sh; ./sof_insert.sh twice quickly [ without suspend/resume ]

[plbossart]

I am still not clear as to why we have an issue with the suspend-resume -u, and not with the kmod unload-reload test.

Something is clearly fishy if the compound test finds something that is not found in a unit test.

[bardliao]

@plbossart The context CI will reboot the DUT after some test cases are failed. The issue happened when the suspend/resume test is the first test case after DUT rebooted. So the scenario is to run ~/sof-test/test-case/check-suspend-resume.sh -l 20 -u right after boot. I was wondering why CI only reported the issue on MTL. And figured out that it takes a lot of time to wait for i915 init and it failed.

[    7.814406] snd_sof_pci:sof_pci_probe: sof-audio-pci-intel-mtl 0000:00:1f.3: PCI DSP detected
[   70.764154] sof-audio-pci-intel-mtl 0000:00:1f.3: init of i915 and HDMI codec failed

So, CI actually run the test before sof probe complete, and it will unload modules right after sof probe completed.

[marc-hb]

The i915 delay seems typical when it's not ready and we're forcing it anyway:

• check-sof-logger: SKIP on ADL because of i915 delay … sof-test#741
• Ubuntu22: GDM does not report missing GPU -> use reliable lightdm instead? sof-test#998