[BUG] Various IPC timed out with multi-core run simultaneously

[keqiaozhang]

Describe the bug
Observed this issue on both main branch and mtl-007-drop-stable when checking the multiple-pipeline stress test. The reproduction rate is almost 100%. Sometimes it fails with a simple I/O error and no error logs in kernel message, but sometimes it fails with different IPC timed out.

dmesg

[  311.736404] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create pipeline pipeline.1 (pipe 1) - instance 0, core 0
[  311.736409] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11000005|0x0: GLB_CREATE_PIPELINE
[  312.241983] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x11000005|0x0
[  312.242016] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[  312.242021] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  312.242067] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x91000005|0x0|0x0, target: 0x1b060000|0x0|0x0, ctl: 0x3
[  312.242094] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  312.242113] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  312.242132] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[  312.242147] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[  312.242187] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[  312.242205] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[  312.242244] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[  312.242282] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-mtl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[  312.242286] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  312.242326] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module pipeline.1
[  312.242349] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
[  312.242375] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 0
[  312.242397] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
[  312.242444] kernel:  Port0: ASoC: error at __soc_pcm_hw_params on Port0: -110
[  312.242470] kernel:  Port0: ASoC: error at dpcm_fe_dai_hw_params on Port0: -110

  946.451242] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12060000|0x0: GLB_DELETE_PIPELINE
[  946.550780] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[  946.551127] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12060000|0x0: GLB_DELETE_PIPELINE
[  946.551144] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[  947.058649] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[  947.058690] sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[  947.058695] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  947.058742] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x47000000|0x0|0x0, target: 0x1b060000|0x0|0x0, ctl: 0x3
[  947.058774] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  947.058798] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  947.058822] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[  947.058840] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[  947.058883] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x0, ROM error: 0x0
[  947.058905] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[  947.058948] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[  947.058994] snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-mtl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[  947.058996] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  947.059033] sof-audio-pci-intel-mtl 0000:00:1f.3: failed to disable target core: 1 for pipeline pipeline.4
[  947.059061] sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to free connected widgets
[  947.059092] sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110

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

Reproduction Rate
100%

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {c052a47323f9}
   • SOF: {[mtl-007-drop-stable] and main branch}
2. Name of the topology file
   • Topology: {development/sof-mtl-nocodec.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {MTLP_RVP_NOCODEC}

dmesg.txt
mtrace.txt

[keqiaozhang]

A new IPC timed out error on ADLP-NOCODEC when checking check-capture-50rounds(Test ID 36111):

[ 3786.426946] kernel: Message payload: 00000000: 00000003 00000002 00000001 00000000
[ 3786.426948] 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]
[ 3786.933519] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 3786.933850] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 3786.933859] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 3786.933888] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 3786.933899] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3786.933925] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 3786.933937] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 3786.933945] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 3786.933952] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 3786.933959] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 3786.933982] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 3786.934087] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 3786.934096] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 3786.934147] kernel: Message payload: 00000000: 00000003 00000002 00000001 00000000
[ 3786.934156] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 3786.934170] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 3786.934186] kernel:  DMIC SFX2: ASoC: trigger FE cmd: 1 failed: -110

[RanderWang]

The ipc timeout issue for: Create pipeline pipeline.1 (pipe 1) - instance 0, core 0 was not caused by this ipc message, it was caused by last set_dx. I add memory print in fw and found FW didn't received ipc msg for creating pipeline

[keqiaozhang]

For tip of mtl-007-drop-stable, the IPC timed out issues are very easy to reproduce on MTLP_RVP_NOCODEC. Inner test report ID: 36618

For SOF main branch, it seems that this issue does not exist on SOF main branch, or the reproduction rate is extremely low on MTLP_RVP_NOCODEC. We haven't observed this issue in previous 3 weekly stress testing with main branch.
Please refer to the inner test reports:
2023-12-28: 36337 - clock gating was enabled on main branch at that time.
2023-12-30: 36366
2024-01-06: 36554

[keqiaozhang]

Observed a new IPC error on mtl-007/519c597182ef. Inner test ID:37207.

[49810.582551] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 2
[49810.582559] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000002|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[49810.583040] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x330000a4|0x1: GLB_SET_PIPELINE_STATE
[49810.583045] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 164 - Unknown
[49810.583066] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x13000002|0x1
[49810.583075] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to set final state 2 for all pipelines
[49810.583093] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules dai-copier.SSP.NoCodec-2.capture:0 -> src.11.1:0
[49810.583099] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x46130004|0x10008: MOD_UNBIND
[49810.583531] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x66000000|0x10008: MOD_UNBIND
[49810.583552] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x46130004|0x10008: MOD_UNBIND
[49810.583561] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x120f0000|0x0: GLB_DELETE_PIPELINE
[49810.583940] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x3200000c|0x0: GLB_DELETE_PIPELINE
[49810.583944] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 12 - Required resource is in invalid state
[49810.583959] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x120f0000|0x0
[49810.583967] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to free pipeline widget pipeline.12
[49810.583974] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules src.11.1:0 -> host-copier.2.capture:0
[49810.583980] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget src.11.1 freed
[49810.583986] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12100000|0x0: GLB_DELETE_PIPELINE
[49810.584438] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x3200000c|0x0: GLB_DELETE_PIPELINE
[49810.584442] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 12 - Required resource is in invalid state
[49810.584456] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x12100000|0x0
[49810.584461] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to free pipeline widget pipeline.11
[49810.584466] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to free connected widgets
[49810.584474] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -22