[BUG][mtl-006] ipc timed out for 0x47000000|MOD_SET_DX on MTL secondary cores

[keqiaozhang]

Describe the bug
Observed this issue on MTL-006 branch, it happens when testing the playback pipeline on secondary cores. The reproduce rate is 100%, very easy to reproduce it.

dmesg

[  208.571428] kernel: snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: Output audio format for dai-copier.SSP.NoCodec-2.playback
[  208.571430] kernel: snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 32bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x2002) buffer size 384
[  208.571433] kernel: snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier dai-copier.SSP.NoCodec-2.playback, IPC size is 188
[  208.571436] kernel: snd_sof:sof_ipc4_update_resource_usage: sof-audio-pci-intel-mtl 0000:00:1f.3: dai-copier.SSP.NoCodec-2.playback: ibs / obs / cpc: 384 / 384 / 6388
[  208.571443] kernel: 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]
[  209.075070] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[  209.075086] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[  209.075090] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  209.075135] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x47000000|0x0|0x0, target: 0x1b060000|0x0|0x0, ctl: 0x3
[  209.075139] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  209.075142] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  209.075144] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[  209.075147] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[  209.075157] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[  209.075159] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[  209.075166] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[  209.075168] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  209.075187] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed to enable target core for widget pipeline.5
[  209.075192] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
[  209.075205] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 2 dir 0
[  209.075209] 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
[  209.075238] kernel:  Port2: ASoC: error at __soc_pcm_hw_params on Port2: -110
[  209.075249] kernel:  Port2: ASoC: error at dpcm_fe_dai_hw_params on Port2: -110
[  209.075257] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 2 dir 0
[  209.075697] kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: close stream 2 dir 0

To Reproduce
Test the playback on secondary cores (hw:0,1 is on core#1, hw:0,2 is on core#2)
aplay -Dhw:0,1 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q
aplay -Dhw:0,2 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q

Reproduction Rate
100%

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: sof-dev, commit {e327169bf7524} +{PR4566}
   • SOF: {mtl-006-drop-stable}, commit f9c5e9d
2. Name of the topology file
   • Topology: {sof-mtl-nocodec-multicore.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {mtl-multicore}
     

dmesg.txt
mtrace.txt

[serhiy-katsyuba-intel]

Looks like this issue was fixed yesterday by this commit fa1572c

Without such commit I also reproduce timeout (due to failed assert in Zephyr scheduler code) on Windows test test_113_02_simple_internal_loopback_run_slave_core_during_transfer[48000Hz_16in16bit_2ch-ssp_0_to_ssp_0] when switching off core 1. That commit fixes the problem.

@keqiaozhang , could you retest once again using latest firmware from mtl-006-drop-stable branch?

cc @tmleman

[fredoh9]

this issue is still easily reproducible with either bba6300c0d33( checked in 8 hours ago) or 202439ebf443 (checked in 1day 8 hours ago)

[mengdonglin]

@fredoh9 Thank you for testing the updates!

@serhiy-katsyuba-intel @tmleman Rander ported 2 multi-core fixes from main branch to mtl-006-drop-stable: #8179 can you please review?

[mengdonglin]

#8155 cannot be reproduced on main branch (IMR context save enabled by default), but can still be reproduced on mtl-006-drop-stable with multi-core IPC time out fixes PR #8179
Please find more info in #8179 (comment)

[keqiaozhang]

@serhiy-katsyuba-intel Confirmed that this issue cannot be reproduced on tip main branch 9ccfbc4 with IMR context save disabled (by setting CONFIG_ADSP_IMR_CONTEXT_SAVE=n in PR #8156)

[abonislawski]

@mengdonglin @keqiaozhang this is timing issue, works fine on HPRO (main & mtl-006) but fails when lowest clock in use, please verify if it works now on mtl-006, based on my tests it should be fixed (commit af4554dfdb66 )

[fredoh9]

We have easy way to reproduce this. yes, it looks working fine with latest mtl-006-stable-drop ( 37bd281 ). Already started longer test plan for mtl-006. Will update when the test is finished

[keqiaozhang]

@abonislawski，this issue cannot be reproduced on tip mtl-006 branch.