[BUG] ipc timed out for 0x13040004 GLB_SET_PIPELINE_STATE on MTLP_RVP when testing with DMIC pipeline

[keqiaozhang]

Describe the bug
Observed this ERROR in CI test(Test ID:21755), this is a new IPC error on MTLP_RVP_HDA. No obvious errors in mtrace.

dmesg

[ 4655.963575] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 4 state 4
[ 4655.963580] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13040004|0x0: GLB_SET_PIPELINE_STATE
[ 4656.461841] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 6 dir 1 cmd 0
[ 4656.461860] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 3
[ 4656.469198] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x13040004|0x0
[ 4656.469251] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 4656.469255] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 4656.469301] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x93040004|0x0|0x0, target: 0x33000000|0x0|0x0, ctl: 0x3
[ 4656.469352] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 4656.469390] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4656.469430] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 4656.469458] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 4656.469498] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[ 4656.469533] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 4656.469575] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 4656.469606] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 4656.469654] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 4656.469699] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 4656.469719] kernel: 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]
[ 4656.469759] kernel:  HDA Analog: ASoC: trigger FE cmd: 1 failed: -110

To Reproduce
~/sof-test/test-case/multiple-pipeline.sh -f p -c 20 -l 50

Reproduction Rate
TBD

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: sof-dev / [f02bb90dd84e]
   • SOF: main/b637889efb5e
2. Name of the topology file
   • Topology: sof-hda-generic-4ch.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: MTL-HDA

dmesg.txt

mtrace.log

[keqiaozhang]

A similar issue happened on TGLU_RVP_NOCODEC_IPC4ZPH. Daily test ID：22388

dmesg

[ 3283.800207] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 16]
[ 3283.800670] 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
[ 3283.800736] 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: 16]
[ 3283.800752] 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: 16]
[ 3284.306558] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 3284.306574] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 3284.306580] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 3284.306604] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 3284.306611] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3284.306652] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 3284.306660] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 3284.306666] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 3284.306671] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 3284.306676] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 3284.306697] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 3284.306755] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 3284.306761] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 3284.306804] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 3284.306813] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 3284.306823] kernel:  DMIC0 Raw 2: ASoC: trigger FE cmd: 1 failed: -110

[lrudyX]

@keqiaozhang we need IPC logs with payloads to reproduce with FW tests, could you prepare?

[keqiaozhang]

@keqiaozhang we need IPC logs with payloads to reproduce with FW tests, could you prepare?

This bug is extremely hard to reproduce, a lot of fixes merged recently, maybe this bug has already been fixed. So let's continue to monitor this bug for a while in CI testing.