Repository navigation
[BUG] Various IPC timed out with multi-core run simultaneously #8642
Description
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
- 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}
- Name of the topology file
- Topology: {development/sof-mtl-nocodec.tplg}
- Name of the platform(s) on which the bug is observed.
- Platform: {MTLP_RVP_NOCODEC}
Activity
keqiaozhang commentedon Dec 19, 2023
A new IPC timed out error on ADLP-NOCODEC when checking check-capture-50rounds(Test ID 36111):
RanderWang commentedon Dec 20, 2023
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 commentedon Jan 9, 2024
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: 36618For 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 commentedon Jan 24, 2024
Observed a new IPC error on mtl-007/519c597182ef. Inner test ID:37207.
jsarha commentedon Jan 24, 2024
By removing irrelevant logging from FW I am now sometimes able to seeing the first symptoms of DSP being stuck
lgirdwood commentedon Jan 24, 2024
@kv2019i pls see above info from @jxstelter - is this addressed in your current IDC PR #8753 ?
5 remaining items
soc: xtensa: intel_adsp: restore bootctl with per-core state
soc: xtensa: intel_adsp: restore bootctl with per-core state
marc-hb commentedon Feb 14, 2024
One recent reproduction on the stable-v2.8 branch, internal run:
planresultdetail/37902?model=MTLP_RVP_NOCODEC&testcase=multiple-pipeline-playback-200
This left the device in a bad state which made all consecutive tests fail - very slowly. Not cool. Much worse than a "fail fast" hard crash.
Maybe https://sof-ci.01.org/sofpr/PR8855/build2720/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pause-resume-50 (same branch) had the same cause
soc: xtensa: intel_adsp: restore bootctl with per-core state
soc: xtensa: intel_adsp: restore bootctl with per-core state
wszypelt commentedon Feb 16, 2024
@keqiaozhang Can you check this issue on https://github.com/abonislawski/sof/tree/mtl-008-drop-stable?
keqiaozhang commentedon Feb 19, 2024
Confirmed that this issue cannot be reproduced on https://github.com/abonislawski/sof/tree/mtl-008-drop-stable.
Test report: https://sof-ci.ostc.intel.com/#/result/planresultdetail/38079.
soc: xtensa: intel_adsp: restore bootctl with per-core state
soc: xtensa: intel_adsp: restore bootctl with per-core state
kv2019i commentedon Mar 6, 2024
Adding @lyakh you as bug owner as well to track merging of zephyrproject-rtos/zephyr@792a569 (or equivalent) to SOF main.
kv2019i commentedon Mar 22, 2024
All fixed merged, closing.
Update zephyr 3 6 (#13)
soc: xtensa: intel_adsp: restore bootctl with per-core state