[BUG] ipc timed out for 0x13000004|0x1 GLB_SET_PIPELINE_STATE on IPC4 NOCODEC and SDW platforms

[keqiaozhang]

Describe the bug
We observed this issue in daily test, it seems that this issue only happens on IPC4 NOCODEC and SDW platforms, we didn't observe this issue on HDA platform. DSP dead after ipc timed out, so there're no useful error logs in mtrace.
The reproduction rate is about 20%. but I'm not sure if it's a regression or not, will do more tests to confirm it.

dmesg

[ 5182.381164] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 4 state: 4
[ 5182.381751] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 5182.381849] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 5182.381895] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 5182.382154] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[ 5182.382214] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 4
[ 5182.382238] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
[ 5182.382244] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 4 state: 4
[ 5182.887226] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 5182.887243] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 5182.887248] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5182.887283] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000180 rirb 00
[ 5182.887291] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5182.887330] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 5182.887338] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5182.887343] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5182.887347] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5182.887352] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5182.887372] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 5182.887423] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 5182.887429] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5182.887435] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 5182.887449] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 5182.887458] kernel:  Deepbuffer Port0: ASoC: trigger FE cmd: 4 failed: -110

To Reproduce
20%

Reproduction Rate
~/sof-test/test-case/multiple-pause-resume.sh -r 50

Environment
Kernel Branch: topic/sof-dev
Kernel Commit:
c41b1735d3da
SOF Branch: main
SOF Commit:
80adcdf36a1d
Zephyr Commit:
zephyr-v3.2.0-2606-gc5b270e7b003

[bardliao]

It usually failed when I run ~/sof-test/test-case/multiple-pause-resume.sh -r 50 twice. I can reproduce it even with -r 20. It is hard to reproduce if I run ~/sof-test/test-case/multiple-pause-resume.sh -r 50 only once. And increate -r number will not increase the reproduce rate.

[juimonen]

Can you see anything in mtrace if the test is run manually and it fails... I mean starting mtrace before the test?

[bardliao]

@juimonen mtrace log and kernel log are attached.
out.txt
dmesg.txt