Repository navigation
[BUG] check-playback.sh sof-test fails on TGL in native Zephyr build with IPC4 #6535
Description
Describe the bug
Following sof-test fails:
~/sof-test/test-case/check-playback.sh -d 1 -l 100 -r 1
To Reproduce
Build SOF with IPC4 and native Zephyr drivers for Intel TGL and run the sof-test
Reproduction Rate
100% (per sof-test)
Expected behavior
Test passes
Impact
Basic functionality is blocked. Test is part of SOF CI.
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: f4aba46e67cacc3e16808e0df97babc47b69bd72
- SOF: native drivers test #6438
- Name of the topology file
- Topology: sof-tgl-nocodec.tplg
- Name of the platform(s) on which the bug is observed.
- Platform: Intel TGL
Screenshots or console output
Activity
kv2019i commentedon Nov 4, 2022
FYI @juimonen @ranj063
Test done:
Observations of crash
lgirdwood commentedon Nov 4, 2022
@kv2019i which pipeline state transition, are we starting or stopping a pipeline or does it not matter ?
kv2019i commentedon Nov 4, 2022
Typical failure is when starting the DAI pipeline:
[ 1727.742542] sof-audio-pci-intel-tgl 0000:00:1f.3: Create widget copier.SSP.6.1 instance 1 - pipe 6 - core 0
[ 1727.742545] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x40010004|0x10029: MOD_INIT_INSTANCE [data size: 164]
[ 1727.743257] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x60000000|0x10029: MOD_INIT_INSTANCE
[ 1727.743283] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x40010004|0x10029: MOD_INIT_INSTANCE [data size: 164]
[ 1727.743287] sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.SSP.6.1 setup complete
[ 1727.743290] sof-audio-pci-intel-tgl 0000:00:1f.3: bind copier.host.5.1:0 -> copier.SSP.6.1:0
[ 1727.743293] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x45000004|0x10004: MOD_BIND
[ 1727.743732] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x65000000|0x10004: MOD_BIND
[ 1727.743765] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x45000004|0x10004: MOD_BIND
[ 1727.743963] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 1
[ 1727.744484] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x14001e successful
[ 1727.744496] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 1727.744882] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 1727.745009] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 1727.745028] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 1727.746925] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 1727.747034] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 1728.857699] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 0
[ 1728.857712] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 1729.361527] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000003|0x1
[ 1729.361542] sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
ranj063 commentedon Nov 6, 2022
@kv2019i can you try #6540? This seems to fix the issue for me
kv2019i commentedon Nov 7, 2022
@ranj063 @juimonen Yes, I think this is clearly it. I took @btian1 's PR on heap usage #6525 and run experiments with and without your fixes:
With #6540, after 50 rounds of check-playback test:
--cut--
[ 60.641000] pipe: comp:1 0x40001 connect buffer 0 as source
[ 60.642000] zephyr: heap allocated: 1ff0 free: 130b38 max allocated: 2ec0
[ 60.642000] zephyr: heap allocated: 22f0 free: 130828 max allocated: 2ec0
--cut--
Without #6540, after 50 rounds:
--cut--
[ 59.382000] zephyr: heap allocated: e638 free: 123af0 max allocated: f230
[ 59.383000] zephyr: heap allocated: e650 free: 123ac8 max allocated: f230
[ 59.383000] zephyr: heap allocated: e710 free: 1239f8 max allocated: f230
[ 59.383000] zephyr: heap allocated: ea10 free: 1236e8 max allocated: f230
--cut--
So we are clearly leaking heap and slowly running out of memory.
It is still suprising that this leads to system becoming unresponsive without any explicit error message (no ISRs firing, no OS panic). Will continue to debug this is a bit without the fixes to see what happens "just before the end".