[BUG] ipc timed out for 0x13000004|GLB_SET_PIPELINE_STATE with multiple-pipeline-capture on TGLU_NOCODEC_IPC4 #7361
Description
Describe the bug
Observed this issue in CI testing and only happened on TGLU_RVP_NOCODEC_IPC4ZPH so far. The reproduction rate >50%.
To Reproduce
~/sof-test/test-case/multiple-pipeline.sh -f c -l 50
Reproduction Rate
50%
dmesg
[ 5532.578324] 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
[ 5532.578391] 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]
[ 5532.578396] 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]
[ 5533.058084] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[ 5533.058103] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 0 state: 3
[ 5533.065031] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 12 dir 1 cmd 0
[ 5533.065045] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 0 state: 3
[ 5533.080515] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 5533.080523] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5533.080525] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5533.080542] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc000000b rirb 00
[ 5533.080545] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5533.080568] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 5533.080571] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5533.080574] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5533.080576] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5533.080579] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5533.080588] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 5533.080613] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status: 0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 5533.080615] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5533.080642] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 5533.080647] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 5533.080651] kernel: Port2: ASoC: trigger FE cmd: 1 failed: -110
mtrace
[ 111.733180] <inf> ll_schedule: task add 0xbe0bf0c0 0x20180U priority 0 flags 0x0
[ 111.733628] <inf> host_comp: comp:7 0x4000b no bytes to copy, available bytes: 0, free_bytes: 3072
[ 111.733700] <inf> dai_intel_dmic: dmic_start(), dmic->fifo_a
[ 111.733711] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 0, mask 6000000, value 4000000
[ 111.733723] <inf> dai_intel_dmic: dmic_start(), pdm0 mic_a = 1, mic_b = 1
[ 111.733733] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 1000, mask c000, value c000
[ 111.733745] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 100c, mask 3, value 3
[ 111.733756] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 1020, mask 80, value 80
[ 111.733766] <inf> dai_intel_dmic: dmic_start(), pdm1 mic_a = 1, mic_b = 1
[ 111.733778] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 2000, mask c000, value c000
[ 111.733788] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 200c, mask 3, value 3
[ 111.733800] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 2020, mask 80, value 80
[ 111.733811] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 1000, mask 10000, value 0
[ 111.733820] <inf> dai_intel_dmic: dmic_start(), cic 0x0000c001
[ 111.733831] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 2000, mask 10000, value 0
[ 111.733840] <inf> dai_intel_dmic: dmic_start(), cic 0x0000c001
[ 111.733851] <inf> dai_intel_dmic: dmic_start(), dmic_active_fifos_mask = 0x1
[ 111.733871] <wrn> dai_comp: comp:5 0x40008 dai_copy(): nothing to copy
[ 111.734566] <inf> host_comp: comp:7 0x4000b no bytes to copy, available bytes: 0, free_bytes: 3072
[ 111.734601] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 1000, mask 2, value 0
[ 111.734613] <inf> dai_intel_dmic: dai_dmic_update_bits base 10000, reg 2000, mask 2, value 0
[ 111.734705] <inf> ipc: rx : 0x13000003|0x1
[ 111.734750] <wrn> ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262151
[ 111.735293] <inf> ipc: rx : 0x13000004|0x1
[ 111.7Terminated
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: {93747c5a127c}
- SOF: {362a0781f20b}
- Name of the topology file
- Topology: {avs-tplg/sof-tgl-nocodec.tplg}
- Name of the platform(s) on which the bug is observed.
- Platform: {TGLU_NOCODEC_IPC4}