[BUG] ipc timed out for 0x13000004|GLB_SET_PIPELINE_STATE on ADLP-NOCODEC

[keqiaozhang]

Describe the bug
Observed this issue in CI daily test, this issue happened when checking capture 100 times. But this issue cannot be reproduced manually and there's no error in mtrace.

** dmesg**

[ 2129.087779] 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: 12]
[ 2129.088193] 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
[ 2129.088290] 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]
[ 2129.088294] 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]
[ 2129.594030] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 2129.594355] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 2129.594365] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 2129.594393] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 2129.594404] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 2129.594431] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 2129.594442] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 2129.594450] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 2129.594457] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 2129.594464] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 2129.594487] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 2129.594553] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 2129.594560] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 2129.594618] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 2129.594631] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 2129.594647] kernel:  DMIC Raw: ASoC: trigger FE cmd: 1 failed: -110

To Reproduce
~/sof-test/test-case/check-capture.sh -d 1 -l 100 -r 1

Reproduction Rate
Only happened once in CI, no reproductions so far.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {3f9245260d0ae74031839a925c7965ac710fe459}
   • SOF: {1f047fe}
2. Name of the topology file
   • Topology: {avs-tplg/sof-adl-nocodec.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {ADLP_RVP_NOCODEC_IPC4ZPH}

dmesg.txt

mtrace.txt

[keqiaozhang]

Observed this issue on TGLH_SKU0A70_HDA_IPC4ZPH. Inner test ID:30594. The error is the same as ADLP_RVP_NOCODEC_IPC4ZPH.

[keqiaozhang]

Changing the priority to P1 due to this issue occurring on different platforms every day.

[kv2019i]

Having trouble to reproduce this locally. Have tried a also a few older/newer kenrels and firmware, plus the latest of both, but so far no luck. Will continue attempt to reproduce (as logs in the CI cases don't really reveal much).

[lgirdwood]

@kv2019i its' possible we have some loops iterating over HW IP state changes (e.g. in Zephyr driver for clocks, PM etc). @abonislawski and I discussed and we need to add some time outs with legging to help undcover correctly log these issues.

[kv2019i]

Still no luck to reproduce this locally. Will try on more machines.