[BUG] IPC timed out for 0x13050003 GLB_SET_PIPELINE_STATE when testing multiple pipelines

[keqiaozhang]

Describe the bug
Observed this issue on mtl-005-stable-drop branch. The reproduce rate is low and hard to reproduce it manually. There're no errors in mtrace.

dmesg

[ 2817.809591] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 5 state 3
[ 2817.809598] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13050003|0x0: GLB_SET_PIPELINE_STATE
[ 2817.817074] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 6 dir 1 cmd 0
[ 2817.817082] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 3
[ 2818.313225] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x13050003|0x0
[ 2818.313251] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 2818.313256] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 2818.313276] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x93050003|0x0|0x0, target: 0x33000000|0x0|0x0, ctl: 0x3
[ 2818.313294] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 2818.313307] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 2818.313319] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 2818.313329] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 2818.313345] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x0, ROM error: 0x0
[ 2818.313356] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 2818.313371] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 2818.313381] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 2818.313409] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at soc_dai_trigger on Analog CPU DAI: -110
[ 2818.313433] kernel:  HDA Analog: ASoC: error at dpcm_be_dai_trigger on HDA Analog: -110
[ 2818.313446] kernel:  HDA Analog: ASoC: trigger FE cmd: 0 failed: -110

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

Reproduction Rate
hard to reproduce it manually.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {c4cf3be86125}
   • SOF: {mtl-005-drop-stable}/tag: releases/mtl/v5.0.3
2. Name of the topology file
   • Topology: {sof-ace-tplg/sof-hda-generic-4ch.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {mtl-hda}

dmesg.txt
mtrace.txt

[fredoh9]

Found same problem with daily test with main branch with TGLH_SKU0A70_HDA_IPC4ZPH also.

• Kernel Branch: topic/sof-dev
• Kernel Commit: e2b8ebcd30b4
• SOF Branch: main
• SOF Commit: 8937929b4ec9
• Zephyr Commit: zephyr-v3.4.0-301-g23b3cae1b1d9

Failed in DMIC pipeline while running check-capture-100times

2023-07-10 11:01:17 UTC [REMOTE_INFO] ===== Testing: (Round: 1/1) (PCM: DMIC Raw [hw:0,6]) (Loop: 74/100) =====
2023-07-10 11:01:17 UTC [REMOTE_INFO] no file prefix, use /dev/null as dummy capture output
2023-07-10 11:01:17 UTC [REMOTE_COMMAND] arecord   -Dhw:0,6 -r 48000 -c 2 -f S32_LE -d 1 /dev/null -v -q
Hardware PCM card 0 'sof-hda-dsp' device 6 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 48000
  exact rate   : 48000 (48000/1)
  msbits       : 32
  buffer_size  : 8192
  period_size  : 2048
  period_time  : 42666
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 2048
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 8192
  silence_threshold: 0
  silence_size : 0
  boundary     : 4611686018427387904
  appl_ptr     : 0
  hw_ptr       : 0
arecord: pcm_read:2221: read error: Connection timed out
2023-07-10 11:01:19 UTC [REMOTE_ERROR] arecord on PCM hw:0,6 failed at 74/100.

dmesg,

[ 1715.780131] 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]
[ 1716.286786] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 1716.286800] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 1716.286805] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 1716.286825] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 1716.286830] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1716.286841] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 1716.286847] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 1716.286851] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 1716.286855] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 1716.286858] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 1716.286864] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 1716.286880] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 1716.286884] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 1716.286897] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 1716.286903] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 1716.286911] kernel:  DMIC Raw: ASoC: trigger FE cmd: 1 failed: -110

Intel internal daily test link: planresultdetail/28790?model=TGLH_SKU0A70_HDA_IPC4ZPH&testcase=check-capture-100times

[keqiaozhang]

This issue cannot be reproduced on main branch. Closing this bug.