Simultaneous playback and capture will cause IPC timed out

[mengdonglin]

This issue happens when running playback and capture at same time. Possibility: 5%~10%.

How to reproduce:

1. 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

[mengdonglin]

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]

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]

I can still see this issue with latest codes.

[keyonjie]

@dabekjakub from the logs you pasted, looks FW received the trigger start msg, but handle/schedule too late?

[libinyang]

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]

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]

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]

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]

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]

we miss an interrupt here on driver side, under investigation about why this happens.