Repository navigation
Simultaneous playback and capture will cause IPC timed out #266
Description
This issue happens when running playback and capture at same time. Possibility: 5%~10%.
How to reproduce:
- repeat run: aplay -Dhw:0,1 test.wav -d 5 & arecord -Dhw:0,1 -f dat -c 2 test9.wav -d 5
Error log:
chronos@localhost ~ $ aplay -Dhw:0,1 /root/100sine.wav -d 5 & arecord -Dhw:0,1 -f dat -c 2 test9.wav -d 5
[1] 2489
Recording WAVE 'test9.wav' : Signed 16 bit Little Endian, Playing WAVE '/root/100sine.wav' : Rate 48000 Hz, Signed 16 bit Little Endian, StereoRate 48000 Hz,
Stereo
overrun!!! (at least 0.111 ms long)
aplay: pcm_write:2051: write error: Input/output error
[1]+ Exit 1 aplay -Dhw:0,1 /root/100sine.wav -d 5
Activity
mengdonglin commentedon Nov 9, 2018
Comments by Jakub:
"we always are missing FW traces from faulty iteration and there are no more traces afterwards.
Look at attached fw trace and dmesg logs and count ipc_glb_stream_message trigger start and ipc_glb_stream_message trigger stop pairs – there are two starts and two stops per iteration and in logs attached there were 10 iterations (tenth being faulty) but start and stop trigger pairs count is 9.
You can find fw build I used attached in zip (it has clearer ipc triger presentation in fw logs so counting is easier). "
log_trace_fw.txt
log_trace_dmsg.txt
sof-apl.zip
dabekjakub commentedon Nov 9, 2018
Comment to missing traces - @keqiaozhang did not see this issue and provided fw traces.
In traces provided by him there was no timeout on FW side and every ipc was handled and responded to in time.
Kernel side log on the other hand states that ipc replay was not sent in time. (inline)
[ 92.037887] sof-audio sof-audio: pcm: trigger stream 1 dir 1 cmd 1
[ 92.038044] sof-audio sof-audio: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 92.038115] sof-audio sof-audio: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 92.039410] sof-audio sof-audio: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 92.040194] sof-audio sof-audio: pcm: trigger stream 1 dir 0 cmd 1
[ 92.040217] sof-audio sof-audio: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START - ipc sent on kernel side
[ 92.344431] sof-audio sof-audio: error: ipc timed out for 0x60040000 size 0xc
[ 92.344460] sof-audio sof-audio: status: fw entered - code 00000005
[ 92.344606] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 92.344611] sof-audio sof-audio: error: waking up any trace sleepers
[ 92.344643] Headset: ASoC: trigger FE failed -110
[ 92.344672] sof-audio sof-audio: pcm: trigger stream 1 dir 0 cmd 0
[ 92.344758] sof-audio sof-audio: error: rx list empty but received 0x0 fw response recived for the ipc that timed out
[ 92.344763] sof-audio sof-audio: error: can't find message header 0x60040000
keyonjie commentedon Nov 15, 2018
I can still see this issue with latest codes.
keyonjie commentedon Nov 15, 2018
@dabekjakub from the logs you pasted, looks FW received the trigger start msg, but handle/schedule too late?
libinyang commentedon Nov 16, 2018
Interesting bug.
Let me keep an eye on it...
BTW: Do you guys know how to watch an issue without send any message to others? Sorry for the garbage message.
dabekjakub commentedon Nov 16, 2018
I investigated the FW logs and every trigger was handled in the same time @keyonjie and there were no indications of timeout on FW side that is why i need someone from kernel to look at it. I am 99.99% sure that we write response correctly and in time.
keyonjie commentedon Nov 22, 2018
it looks there is extra delay on some part:
[ 92.040217] sof-audio sof-audio: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START - ipc sent on kernel side
[ 92.344758] sof-audio sof-audio: error: rx list empty but received 0x0 fw response recieved for the ipc that timed out
the response is too late, longer than 300ms.
keyonjie commentedon Nov 22, 2018
it is not easy for me to reduplicate it now, with SOF glk-004-drop-stable and linux topic/cros-sof-v4.14-rebase, I tried the step #1 for more than 100 times, but no ipc timeout or xrun happens.
dabekjakub commentedon Nov 22, 2018
As i said before - i know that there is a timeout in log that points to fw. But when it comes to FW ipc handling i saw no delay in response in fw traces. So FW handled ipc (we handle it as IRQ) as fast as it was possible it was not even close to 300ms. That is why i ask for kernel dev to check it out. Maybe the response is already there but system has some kind of hickup on reading the memory window. So simply trace time between sending and reading response. If You try to read it many times during this 300ms then it means that fw either didn't recive or respond to in time and i can continiue.
Overal really inprobable since in our python tests we never had a timeout issue on ipc.
keyonjie commentedon Nov 23, 2018
we miss an interrupt here on driver side, under investigation about why this happens.
keyonjie commentedon Nov 26, 2018
4 remaining items
keyonjie commentedon Dec 10, 2018
@ranj063 so for this kind of ipc timeout, we need to confirm what stage we actually failed：
host not sent?
host sent but fw not recieved?
host sent, fw recieved, fw handled but not acked?
host sent, fw recieved, fw handled and acked, but host didn't get the ack?
keyonjie commentedon Dec 12, 2018
I found that sometimes scheduler crash before Xrun happens(looks like copy task is not scheduled then xrun happens), there might be scheduler bug.
keyonjie commentedon Dec 15, 2018
I have done several optimizations, now it can pass 200 (2playback+1capture+1dma-trace) iterations.
Still hit several corner cases after long enough try, e.g. 300 or 500 iterations, one classical one as below:
keyonjie commentedon Dec 18, 2018
as this issue mostly happens in FW side now(e.g. FW hang, FW panic, FW can't get IPC interrupts, ...), let me duplicate this in sof issue.
plbossart commentedon Feb 8, 2019
@mengdonglin is this still open or can we close?
plbossart commentedon Mar 24, 2019
last call @mengdonglin I will close at the end of the week if there is no update.
keqiaozhang commentedon Mar 25, 2019
Confirmed that this issue is fixed on GLK.
@stevyan ,please help to check on APL and close it if you cannot reproduce it.
stevyan commentedon Mar 28, 2019
Summary
Issue cannot be reproduced with daily build version after executed more than 800 times based on APL UP2 nocodec.
Test Env
sof master: 742f83b
kernel sof-dev: 0367002
tplg: sof-apl-nocodec.tplg
Merge pull request thesofproject#266 from TheSven73/rust-for-linux-fr…
selftest/bpf: Add various selftests for program limits
selftests/bpf: Test bpf_mprog query API via libbpf and raw syscall
selftests/bpf: Test query on empty mprog and pass revision into attach
f2fs: fix null-ptr-deref in f2fs_get_dnode_of_data
selftests/bpf: Add additional mprog query test coverage