[BUG][MTL-005.0.3] ipc timedout on killing speaker pipeline aplay

[aiChaoSONG]

Describe the bug
Doing playback to speaker pipeline, and kill the process with CTRL+C. sometimes there will be ipc timed out in the kernel message. And there is no obvious error message in mtrace.

On issue happened, we are not able to do playback/capture anymore.

[  118.403776] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1c0]=0x2014001e successful
[  120.519805] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 0
[  120.519818] snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 3
[  120.519830] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[  121.020363] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x13000003|0x1
[  121.020380] sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[  121.020386] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  121.020399] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x93000003|0x1|0x0, target: 0x1b060000|0x0|0x0, ctl: 0x3
[  121.020406] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  121.020411] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  121.020414] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[  121.020418] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[  121.020428] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x0, ROM error: 0x0
[  121.020433] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[  121.020439] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[  121.020444] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  121.020460] sof-audio-pci-intel-mtl 0000:00:1f.3: failed to pause all pipelines
[  121.020468] sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[  121.020478]  Speaker: ASoC: trigger FE cmd: 0 failed: -110
[  121.020554] snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 2 dir 0
[  121.020565] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1c0]=0x140000 successful
[  121.020573] snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 2

To Reproduce

1. run aplay command: aplay -Dhw:0,2 -f dat -i -vvv chao/California_Dreaming.wav
2. kill aplay process with CTRL+C
3. iterate step 1 and 2 several times, you should see the issue.

Reproduction Rate
1/5

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {topic/sof-dev 246b5b77fc74}
   • SOF: {mtl-005.0.3 release}
2. Name of the topology file
   • Topology: {sof-mtl-rt1318-l12-rt714-l0.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {Dell SKU0C87}
4. OS: Ubuntu 22.04

speaker_dmesg.txt
speaker_mtrace.txt

With patch #8007, issue is not reproducable.

Similar issue may be the same root cause: #7990

[mengdonglin]

@abonislawski @lrgirdwo FYI

[abonislawski]

0 CPS requested for module: 0x40000, core: 0 using safe max CPC: 400000

probably missing a kernel PR to fix that part

[aiChaoSONG]

Unfortunately, this happens in Fedora with sof-dev + mtl-005.0.3 firmware, while firmware is configured with CONFIG_ADSP_IMR_CONTEXT_SAVE=n

Despite the value of CONFIG_ADSP_IMR_CONTEXT_SAVE(yes or no), if apply #8007, the issue will disapprear.

[aiChaoSONG]

Issue cannot be reproduced with sof-dev kernel + firmware latest main branch (commit fb6c3b7, IMR context save already enabled) + PR #8019 @abonislawski

[lrudyX]

Status: Waits for #8019 merge

[mengdonglin]

@aiChaoSONG @abonislawski @lrudyX The Linux workaround PR thesofproject/linux#4531? applied in upstream: https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound.git/commit/?id=26ef47e5ba600ead306ee19e0bf56c1bf59213a3

This will give us more time on final FW fix.

[mengdonglin]

@alex-cri @kv2019i I push it out to v2.8 as the CPC-based clock selection is out of scope of v2.7

[wszypelt]

@aiChaoSONG does the issue also occur on main, or on MTL_006?

[aiChaoSONG]

It is not easy to reproduce the issue as before(mtl005.0.3) with MTL6.2 release. I see another issue(some issue rander is fixing I think thesofproject/linux#4832) before I could reproduce this one.
The MTLv6.2 firmware shared by Marcin canot boot the sku0c87 dell device, I have to compile from mtl-006-drop-stable by myself.

mtrace.txt
dmesg.txt

[ 3808.443663] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x3200000c|0x0: GLB_DELETE_PIPELINE
[ 3808.443670] sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 12 - Required resource is in invalid state
[ 3808.443863] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x12010000|0x0
[ 3808.443877] sof-audio-pci-intel-mtl 0000:00:1f.3: failed to free pipeline widget pipeline.21
[ 3808.443886] sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to free connected widgets
[ 3808.443895] snd_sof:is_virtual_widget: sof-audio-pci-intel-mtl 0000:00:1f.3: sof_unprepare_widgets_in_path: virtual.sdw-amp is a virtual widget
[ 3808.443901] snd_sof:is_virtual_widget: sof-audio-pci-intel-mtl 0000:00:1f.3: sof_walk_widgets_in_order: virtual.sdw-amp is a virtual widget
[ 3808.443908] sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -22
[ 3808.444024] sdw_deprepare_stream: subdevice #0-Playback: inconsistent state state 3

[keqiaozhang]

This issue cannot be reproduced on latest main branch. Let's track the new issue in #7990. Closing this bug.