Repository navigation
[BUG] ipc timed out for 0x13000004|0x1 GLB_SET_PIPELINE_STATE on IPC4 NOCODEC and SDW platforms #6864
Description
Describe the bug
We observed this issue in daily test, it seems that this issue only happens on IPC4 NOCODEC and SDW platforms, we didn't observe this issue on HDA platform. DSP dead after ipc timed out, so there're no useful error logs in mtrace.
The reproduction rate is about 20%. but I'm not sure if it's a regression or not, will do more tests to confirm it.
dmesg
[ 5182.381164] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 4 state: 4
[ 5182.381751] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 5182.381849] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 5182.381895] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 5182.382154] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[ 5182.382214] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 4
[ 5182.382238] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
[ 5182.382244] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 4 state: 4
[ 5182.887226] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000004|0x1
[ 5182.887243] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 5182.887248] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5182.887283] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000180 rirb 00
[ 5182.887291] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5182.887330] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000004|0x1|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 5182.887338] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5182.887343] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5182.887347] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5182.887352] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5182.887372] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 5182.887423] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status: 0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 5182.887429] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5182.887435] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 5182.887449] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 5182.887458] kernel: Deepbuffer Port0: ASoC: trigger FE cmd: 4 failed: -110
To Reproduce
20%
Reproduction Rate
~/sof-test/test-case/multiple-pause-resume.sh -r 50
Environment
Kernel Branch: topic/sof-dev
Kernel Commit:
c41b1735d3da
SOF Branch: main
SOF Commit:
80adcdf36a1d
Zephyr Commit:
zephyr-v3.2.0-2606-gc5b270e7b003
Reacted by Marc Herbert
Activity
bardliao commentedon Dec 21, 2022
It usually failed when I run
~/sof-test/test-case/multiple-pause-resume.sh -r 50twice. I can reproduce it even with-r 20. It is hard to reproduce if I run~/sof-test/test-case/multiple-pause-resume.sh -r 50only once. And increate-rnumber will not increase the reproduce rate.juimonen commentedon Dec 21, 2022
Can you see anything in mtrace if the test is run manually and it fails... I mean starting mtrace before the test?
bardliao commentedon Dec 21, 2022
@juimonen mtrace log and kernel log are attached.
out.txt
dmesg.txt
keqiaozhang commentedon Feb 1, 2023
Observed a similar error on TGLU_UP_HDA_IPC4ZPH.
https://sof-ci.sh.intel.com/#/result/planresultdetail/20379?model=TGLU_UP_HDA_IPC4ZPH&testcase=multiple-pipeline-all-25
lyakh commentedon Feb 2, 2023
Enabled
CONFIG_ASSERTwhich immediately began triggering assertions inmixin_process(). After I've converted those to error prints (I'm really unsure they should be fatal), the test ran for a while, then triggered this:The back-trace points to
module_adapter_copy()->comp_update_buffer_produce()->audio_stream_produce()->audio_stream_wrap(). Investigatinglyakh commentedon Feb 6, 2023
Here's what I've found out so far:
What's the right way to solve this?
keqiaozhang commentedon Feb 13, 2023
This issue is similar with #6734 on MTL.
Please someone help to check if it's a duplicate.
lyakh commentedon Feb 14, 2023
After merging #7052 yesterday's daily test failed a "multiple pause-resume" test again (test result ID 20907) and the CI guessed that it was the same bug again, but this time the kernel error is "FW reported error: 3 - Not enough space in the IPC reply buffer to complete the request" and mtrace contains "pipe: pipeline_new(): Out of Memory" so that looks like a different problem to me
kv2019i commentedon Feb 15, 2023
@lyakh I got now one DSP oops in this test case:
http://sof-ci.sh.intel.com/storage/sofci/generic_test/20966/ADLP_RVP_NOCODEC_IPC4ZPH/multiple-pause-resume-50/mtrace.txt
... and this had #7052 included. On kernel side, first error was:
mengdonglin commentedon Feb 16, 2023
Fixed by #7099
lyakh commentedon Feb 16, 2023
@mengdonglin I'm very skeptical about that. That PR only addresses cases when a pipeline has a component inside with more than one sink or source buffer, whereas that was only merged on Jan. 31 and this bug was opened on Dec. 21 2022. It's possible of course that this bug had several reasons and other reasons were fixed before, but it's not quite certain. I also still can easily reproduce assertion failures in my local tests which I thought were related to this bug. Anyway, we can keep it closed for now, but keep an eye on them...
lyakh commentedon Feb 16, 2023
I was wrong, smart amp was only enabled yesterday in #6996, i.e. on the same day as #7099, so #7099 cannot be a fix for this bug. I expect this bug to be reopened very soon.
miRoox commentedon Feb 17, 2023
This issue still happened today.
lyakh commentedon Feb 17, 2023
@miRoox I retain my opinion, that #7099 isn't a fix for this but, OTOH the failure today isn't this bug either: this bug is an IPC timeout, likely caused by a firmware crash, whereas today's failure is an out of memory allocation failure in the firmware
keqiaozhang commentedon Feb 20, 2023
@lyakh thanks for the confirmation. I have filed #7123 to track this new IPC issue.
This bug can be closed now.