Repository navigation
[BUG][mtl-006] ipc timed out for 0x47000000|MOD_SET_DX on MTL secondary cores #8155
Description
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
- 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
- Name of the topology file
- Topology: {sof-mtl-nocodec-multicore.tplg}
- Name of the platform(s) on which the bug is observed.
- Platform: {mtl-multicore}
- Platform: {mtl-multicore}
Activity
[-][BUG][mtl-006] ipc timed out for 0x47000000|MOD_SET_DX on MTL multicore platform[/-][+][BUG][mtl-006] ipc timed out for 0x47000000|MOD_SET_DX on MTL secondary cores[/+]serhiy-katsyuba-intel commentedon Sep 6, 2023
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 commentedon Sep 7, 2023
this issue is still easily reproducible with either bba6300c0d33( checked in 8 hours ago) or 202439ebf443 (checked in 1day 8 hours ago)
mengdonglin commentedon Sep 8, 2023
@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 commentedon Sep 8, 2023
#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 commentedon Sep 11, 2023
@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 commentedon Sep 18, 2023
@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 commentedon Sep 18, 2023
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 commentedon Sep 19, 2023
@abonislawski，this issue cannot be reproduced on tip mtl-006 branch.