[BUG][IPC4]ipc error when suspend/resume with FW error "specified resource not found" on ADLP_RVP_NOCODEC_IPC4

[XiaoyunWu6666]

Describe the bug Suspend/resume fails on ADLP_RVP_NOCODEC_IPC4 at the Round 9/50 This happened first in inner daily IPC4 12604 with FW error "specified resource not found" and ipc error when setting pipeline state

To Reproduce TPLG=/lib/firmware/intel/avs-tplg/cavs-tgl-nocodec.tplg MODEL=ADLP_RVP_NOCODEC_IPC4 ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m capture

Environment Kernel Branch: topic/sof-dev Kernel Commit: db34128c2a8d SOF Branch: main SOF Commit: 6c4f3ea42f0d Zephyr Commit: 782480313edc Topology: cavs-tgl-nocodec.tplg

Platform: ADLP_RVP_NOCODEC_IPC4

Screenshots or console output [dmesg]

[  126.440904] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: prepare stream 0 dir 0
[  126.440908] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: hw params stream 0 dir 0
[  126.440920] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  126.440945] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  126.440951] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_setup_bdl: period_bytes:0x1000
[  126.440953] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_setup_bdl: periods:16
[  126.441407] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[  126.441933] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x14001e successful
[  126.441941] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 1 state 3
[  126.441946] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  126.442074] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000009|0x0: GLB_SET_PIPELINE_STATE
[  126.442080] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[  126.442113] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13010003|0x0
[  126.442127] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to pause pipeline 1
[  126.442135] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
[  126.442150] kernel:  Port0: ASoC: trigger FE cmd: 1 failed: -22
[  126.442161] kernel: rfkill: input handler enabled
[  126.442162] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[  126.442164] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc4 set pipeline 1 state 3
[  126.442167] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  126.442252] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000009|0x0: GLB_SET_PIPELINE_STATE
[  126.442254] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[  126.442267] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13010003|0x0
[  126.442281] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to pause pipeline 1
[  126.442300] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x140000 successful
[  126.442305] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
[  126.442314] kernel:  Port0: ASoC: trigger FE cmd: 0 failed: -22
[  126.442455] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 0 dir 0
[  126.442477] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_ipc4_route_free: unbind modules copier.host.1.1 -> copier.SSP.2.1
[  126.442480] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x46000004|0x10004: MOD_UNBIND
[  126.442570] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x66000009|0x10004: MOD_UNBIND
[  126.442572] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[  126.442586] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x46000004|0x10004
[  126.442597] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to unbind modules copier.host.1.1 -> copier.SSP.2.1

IPC4-dmesg.txt

[XiaoyunWu6666]

I checked past tests for TGLU_UP_HDA (sof Zephyr IPC4) and ADLP RVP NOCODEC(sof Zephyr IPC4) in inner CI. There are a couple of possible types of errors:

I . only IO error in the console log : inner IPC4 result 12563 12593 (#5820 ) II. fw report error specified resource not found when setting pipeline state 3 on ADL , no IO error : inner daily IPC4 12604 III. IO error with ipc time out when creating module on ADL and TGL ; TGL has fw error specified resource not found ; ADL failed to boot DSP firmware after resume after that : inner daily IPC4 12637

[lgirdwood]

@RanderWang @tmleman any insights ?

[RanderWang]

First we need 5844. and we still have a random issue in stress test. I am debugging it

[XiaoyunWu6666]

Some notes FYI:

(Sometimes the FW "specified resource not found " error does not happen and the failure looks similar to #5825 then , with ipc timed out when setting pipeline status)

[XiaoyunWu6666]

in inner daily 13137 on model TGLU_UP_HDA_IPC4ZPH when check-suspend-resume-with-capture-5 ipc timed out happened when MOD BIND

[ 1417.782147] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.3.1 setup complete
[ 1417.782150] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Create widget copier.host.3.1 instance 1 - pipe 3 - core 0
[ 1417.782158] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x40010004|0x30015: MOD_INIT_INSTANCE [data size: 84]
[ 1417.782325] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x60000000|0x30015: MOD_INIT_INSTANCE
[ 1417.782337] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x40010004|0x30015: MOD_INIT_INSTANCE [data size: 84]
[ 1417.782340] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.host.3.1 setup complete
[ 1417.782344] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_ipc4_route_setup: bind gain.3.1 -> copier.host.3.1
[ 1417.782347] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x45010006|0x10004: MOD_BIND
[ 1417.799869] kernel: done.
[ 1417.800004] kernel: video LNXVIDEO:00: Restoring backlight state
[ 1417.800074] kernel: PM: suspend exit
[ 1417.872626] kernel: rfkill: input handler disabled
[ 1418.284396] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x45010006|0x10004
[ 1418.284408] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_ipc4_route_setup: failed to bind modules gain.3.1 -> copier.host.3.1
[ 1418.284417] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.HDA.4.1 freed
[ 1418.284420] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.4.1 freed
[ 1418.284425] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12040000|0x0: GLB_DELETE_PIPELINE
[ 1418.284737] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 1418.284754] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12040000|0x0: GLB_DELETE_PIPELINE
[ 1418.284758] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.4 freed
[ 1418.284761] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget mixin.4.1 freed
[ 1418.284763] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget mixout.3.1 freed
[ 1418.284765] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.3.1 freed
[ 1418.284769] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12030000|0x0: GLB_DELETE_PIPELINE
[ 1418.285015] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 1418.285025] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12030000|0x0: GLB_DELETE_PIPELINE
[ 1418.285029] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.3 freed
[ 1418.285031] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.host.3.1 freed
[ 1418.285038] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 1
[ 1418.285043] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: set pcm hw_params after resume
[ 1418.285047] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_prepare on 0000:00:1f.3: -110
[ 1418.285052] kernel:  HDA Analog: ASoC: __soc_pcm_prepare() failed (-110)
[ 1418.285057] kernel:  HDA Analog: ASoC: dpcm_fe_dai_prepare() failed (-110)
[ 1418.285141] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 0 dir 1
[ 1418.285299] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: close stream 0 dir 1
[ 1420.760153] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 1420.760297] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0: MOD_SET_DX
[ 1420.760312] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 1420.760353] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x9010f0f successful
[ 1420.760875] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[ 1420.760880] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[ 1420.760961] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 1420.760967] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
[ 1420.760974] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Turning i915 HDAC power 0
[ 1420.760978] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D3
[ 1420.760980] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 6 -> 0
[ 1421.085550] kernel: e1000e 0000:00:1f.6 eno1: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None

[keqiaozhang]

This issue is duplicated with https://github.com/thesofproject/sof/issues/6214. let's track the issue in https://github.com/thesofproject/sof/issues/6214