Repository navigation
[BUG][Zephyr] ipc tx error for 0x30100000(PIPE_NEW) on ADLP Zephyr platform #5554
Description
Describe the bug
We detected this issue in CI when testing multiple-pipeline-all on ADLP_RVP_NOCODEC_ZEPHYR platform.
[ 1339.280533] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1339.280770] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1339.280773] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Core 2 powered up
[ 1339.280778] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[ 1339.281319] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x30100000 (msg/reply size: 48/20): -12
[ 1339.281421] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to setup widget PIPELINE.7.SSP0.OUT
[ 1339.281426] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1339.281501] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1339.281527] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1339.281678] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1339.281686] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Core 2 powered down
[ 1339.281687] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set up connected widgets
[ 1339.281692] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: stream_tag 1
To Reproduce
$ ~/sof-test/test-case/multiple-pipeline.sh -f p -c 20 -l 50
Reproduction Rate
Hard to tell, unable to reproduce this issue manually.
Expected behavior
NO ipc error
Environment
Kernel: sof-dev/d2937505b7b5
SOF : main/51e7c6180141
Zephyr Commit: fc4016a113dc
trace
[ 182248316.560186] ( 383.750000) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x40070000
[ 182248330.883102] ( 14.322916) c0 ipc src/ipc/ipc3/handler.c:696 INFO ipc: pm core mask 0x1 -> enable
[ 182248542.758094] ( 211.874985) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x60010000
[ 182254155.934954] ( 5596.770508) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x30100000
[ 182254172.497453] ( 16.562500) c0 pipe ......./pipeline-graph.c:114 INFO pipeline new pipe_id 6 priority 0
[ 182254804.997428] ( 340.885406) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x60010000
[ 184231227.835559] ( 1976406.125000) c0 zll-schedule src/schedule/zephyr_ll.c:142 INFO ll task 0x9e07cb98 agent-work
[ 182143238.022695] ( 16.197916) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 46 not found
[ 182149768.282852] ( 14.999999) c2 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182149892.866180] ( 124.583328) c2 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182150044.376591] ( 151.510406) c2 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 11 creation failed -12
[ 182150792.293228] ( 16.302082) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 51 not found
[ 182225634.946504] ( 15.312499) c1 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182225761.196499] ( 126.249992) c1 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182225912.811076] ( 151.614578) c1 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 20 creation failed -12
[ 182227134.477694] ( 16.770832) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 56 not found
[ 182232862.862883] ( 15.572916) c0 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182232987.550378] ( 124.687492) c0 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182233138.956622] ( 151.406250) c0 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 21 creation failed -12
[ 182233693.748267] ( 16.770832) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 64 not found
[ 182239965.570934] ( 14.843749) c2 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182240090.206346] ( 124.635414) c2 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182240241.560507] ( 151.354156) c2 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 2 creation failed -12
[ 182241046.091725] ( 17.031250) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 6 not found
[ 182247656.924795] ( 14.999999) c3 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182247781.351874] ( 124.427078) c3 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182247932.810201] ( 151.458328) c3 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 4 creation failed -12
[ 182248559.164343] ( 16.406250) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 18 not found
[ 182254188.018286] ( 15.520833) c0 pipe ......./pipeline-graph.c:122 ERROR pipeline_new(): Out of Memory
[ 182254312.497448] ( 124.479164) c0 ipc src/ipc/ipc3/helper.c:343 ERROR ipc_pipeline_new(): pipeline_new() failed
[ 182254464.112025] ( 151.614578) c0 ipc src/ipc/ipc3/handler.c:1325 ERROR ipc: pipe 6 creation failed -12
[ 182254821.664094] ( 16.666666) c0 ipc src/ipc/ipc3/handler.c:205 ERROR ipc: comp 30 not found avg 55, max 68
[ 184231270.491807] ( 42.656250) c0 zll-schedule ......../zephyr_domain.c:89 INFO ll timer avg 415, max 1024, overruns 0
[ 184284233.927202] ( 52963.433594) c0 zll-schedule src/schedule/zephyr_ll.c:142 INFO ll task 0x9e07c430 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690> avg 29, max 365
[ 186226117.183372] ( 1941883.250000) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x90040000
[ 186226128.745872] ( 11.562500) c0 ipc src/ipc/ipc3/handler.c:921 INFO ipc: debug cmd 0x40000
[ 186226139.214621] ( 10.468750) c0 ipc src/ipc/ipc3/handler.c:891 INFO ipc: trace_filter_update received, size 2 elems
[ 186226156.662537] ( 17.447916) c0 ipc src/ipc/ipc3/handler.c:908 INFO trace_filter_update for UUID key 0x20780, comp -1.-1 affected 1 components
[ 186235890.620484] ( 9733.958008) c0 ipc src/ipc/ipc3/handler.c:1585 INFO ipc: new cmd 0x90040000
[ 186235901.610067] ( 10.989583) c0 ipc src/ipc/ipc3/handler.c:921 INFO ipc: debug cmd 0x40000
[ 186235912.235066] ( 10.625000) c0 ipc src/ipc/ipc3/handler.c:891 INFO ipc: trace_filter_update received, size 2 elems
[ 186235929.630899] ( 17.395832) c0 ipc src/ipc/ipc3/handler.c:908 INFO trace_filter_update for UUID key 0x20780, comp -1.-1 affected 1 components
[ 186320027.856724] ( 84098.226562) c0 zll-schedule src/schedule/zephyr_ll.c:142 INFO ll task 0x9e07cb98 agent-work avg 55, max 60
[ 186320070.408806] ( 42.552082) c0 zll-schedule ......../zephyr_domain.c:89 INFO ll timer avg 414, max 1016, overruns 0
TPLG
Activity
[-][BUG] ipc tx error for 0x30100000(PIPE_NEW) on ADLP Zephyr platform[/-][+][BUG][Zephyr] ipc tx error for 0x30100000(PIPE_NEW) on ADLP Zephyr platform[/+]keqiaozhang commentedon Mar 18, 2022
Observed another IPC timed out(PIPE_FREE) in daily test 11164.
** dmesg **
lgirdwood commentedon Mar 18, 2022
@keqiaozhang can you log the IPC timeout as a separate issue.
@kv2019i are we able to dump the Zephyr stack dump yet from SRAM to Linux dmesg. Is this something for@ujfalusi to check ?
lgirdwood commentedon Mar 18, 2022
@keqiaozhang are we using dynamic pipelines without FW reboot ? Could we be leaking memory ?
keqiaozhang commentedon Mar 21, 2022
ACK, let's track the IPC timeout issue in #5573
keqiaozhang commentedon Mar 21, 2022
Yes, we are using the dynamic pipelines, I have attached the tplg graph in bug description.
kv2019i commentedon Mar 25, 2022
It is highly likely that #5588 will fix this as well. It has a clear impact to #5556 when I run experiements with very high amount of test iterations with both with and without the patch.
kv2019i commentedon Mar 29, 2022
No errors in Intel daily plan 11433, so potentially fixed by the fix to #5556.
kv2019i commentedon Apr 1, 2022
@keqiaozhang Can we close. Not seen in Intel daily testing for multiple days.
keqiaozhang commentedon Apr 1, 2022
Yes, let's close this bug.