[BUG] ipc4_tx_msg_unlocked: ipc message send for 0x11000005|0x0 failed: -19 on MTL-NOCODEC

[keqiaozhang]

Describe the bug
Observed this issue on MTL-RVP-NOCODEC when performing the stress test for stable-v2.8. It happened when checking the suspend/resume with audio and it can be reproduced manually. The reproduction rate is high with stress test case.
I tired to reproduce this issue on main branch(3 rounds with 400 cycles per round), but no reproductions so far. It seems to be a stable-v2.8 specific issue.

dmesg

[25723.283425] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: pipeline: 1 memory pages: 5
[25723.283430] 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
[25723.283436] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11000007|0x0: GLB_CREATE_PIPELINE
[25723.283557] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4_tx_msg_unlocked: ipc message send for 0x11000007|0x0 failed: -19
[25723.283590] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module pipeline.1
[25723.283614] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
[25723.283650] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 0
[25723.283674] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: set pcm hw_params after resume
[25723.283694] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_prepare on 0000:00:1f.3: -19
[25723.283723] kernel:  Port0: ASoC: error at __soc_pcm_prepare on Port0: -19
[25723.283741] kernel:  Port0: ASoC: error at dpcm_fe_dai_prepare on Port0: -19
[25723.284164] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 0 dir 0
[25723.284285] kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: close stream 0 dir 0
[25723.285296] kernel: PM: suspend exit

To Reproduce
~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 100 -m playback

Reproduction Rate
How often does the issue happen ? i.e. 1/10 (once in ten attempts), 1/1000 or all the time.
Does the reproduction rate vary with any other configuration or user action, if so please describe and show the new reproduction rate.

Expected behavior
A clear and concise description of what you expected to happen.

Impact
What impact does this issue have on your progress (e.g., annoyance, showstopper)

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {266ee31b71f8}
   • SOF: {67e2e41c81bf}
2. Name of the topology file
   • Topology: {sof-mtl-nocodec.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {MTLP-RVP-NOCODEC}

dmesg.txt

mtrace.txt

[lgirdwood]

Looks like the FW did not boot

[25721.268814] kernel: i915 0000:00:02.0: [drm] GT1: GUC: submission enabled
[25721.268821] kernel: i915 0000:00:02.0: [drm] GT1: GUC: SLPC enabled
[25721.268988] kernel: i915 0000:00:02.0: [drm] GT1: GUC: RC enabled
[25723.272605] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[25723.272616] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware boot failure due to timeout
[25723.272619] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (3)
[25723.272669] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x0, ROM error: 0x0
[25723.272672] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[25723.272678] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[25723.272727] 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
[25723.272730] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[25723.272733] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed to boot DSP firmware after resume -5
[25723.272737] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 3 -> 4
[25723.272740] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: PM: dpm_run_callback(): pci_pm_resume+0x0/0xe0 returns -5
[25723.272759] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: PM: failed to resume async: error -5
[25723.281375] kernel: OOM killer enabled.
[25723.281380] kernel: Restarting tasks ... 
[25723.283156] kernel: snd_sof:sof_pcm_prepare: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: prepare stream 0 dir 0
[25723.283167] kernel: snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: hw params stream 0 dir 0
[25723.283178] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1c0]=0x40000 successful
[25723.283190] kernel: done.
[25723.283202] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1c0]=0x40000 successful
[25723.283211] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-mtl 0000:00:1f.3: period_bytes:0x4000
[25723.283217] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-mtl 0000:00:1f.3: periods:4
[25723.283241] kernel: snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier host-copier.0.playback, type 23

[keqiaozhang]

Confirmed that this issue is not v2.8 specific issue, I got the reproductions on main branch this afternoon.

[abonislawski]

This is related to IMR context save
@tmleman please verify if this is the same case which you are debugging

[lgirdwood]

@abonislawski @tmleman anything that can be checked in SW to help here ?

[keqiaozhang]

I checked this issue again on latest stable-v2.8/505268c, 3*400 iterations passed without errors. This issue can be closed now.