Repository navigation
[BUG] xrun on multiple NOCODEC platforms when multiple pause release #4996
Description
Describe the bug
When running multiple pause release ,dai_report_xrun(): underrun due to no data available happened with xrun recovery failed and pipeline stopped.
This happened on multiple nocodec platforms including CML_RVP_NOCODEC , JSL_RVP_NOCODEC , TGLU_RVP_NOCODEC ,APL_UP2_NOCODEC , ADLP_RVP_NOCODEC ,etc , since 2021-11-13 (inner daily result 8155)
To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-cnl-nocodec.tplg MODEL=CML_RVP_NOCODEC ~/sof-test/test-case/multiple-pause-resume.sh -r 25
Reproduction Rate
Not 100% but can be seen on more than 2 platforms in every daily result after Nov 13
BTW , increase the parameter -r from 25 to 100 may increase the reproduction rate
Environment
Start Time: 2021-11-12 21:26:21 UTC
End Time: 2021-11-13 00:01:58 UTC
Kernel Branch: topic/sof-dev
Kernel Commit: 66bd4e2a
SOF Branch: main
SOF Commit: 9451716
Zephyr Branch: main
Zephyr Commit: 6aa783ed6ac2
Screenshots or console output
Take CML_RVP_NOCODEC as an example
[console]
(22/25) pcm'Port0' cmd'aplay' id'2': Wait for 41 ms before resume
aplay: pcm_write:2061: aplay: pcm_write:2061: write error: Input/output error
write error: Input/output error
2021-11-12 22:32:24 UTC [REMOTE_INFO] pipeline: Port0 with aplay
2021-11-12 22:32:24 UTC [REMOTE_INFO] pipeline: Port0 Deep Buffer with aplay
2021-11-12 22:32:24 UTC [REMOTE_INFO] Check expect exit status
[etrace]
[ 374022631.908509] ( 3783752.750000) c0 dma-trace src/lib/wait.c:51 ERROR poll timeout reg 487496 mask 63 val 0 us 937
[ 377827749.413557] ( 3805117.500000) c0 dma-trace src/lib/wait.c:51 ERROR poll timeout reg 487496 mask 63 val 0 us 937
[ 377866378.734939] ( 38629.320312) c0 dma-trace src/lib/wait.c:51 ERROR poll timeout reg 488520 mask 63 val 0 us 937
[ 381656506.969750] ( 3790128.250000) c0 dma-trace src/lib/wait.c:51 ERROR poll timeout reg 487496 mask 63 val 0 us 937
[ 385007707.722002] ( 3351200.750000) c0 dma-trace src/drivers/dw/dma.c:1114 ERROR dw_dma_get_data_size(): xrun detected
[ 385007726.367834] ( 18.645832) c0 dma-trace src/audio/dai.c:879 ERROR dai_report_xrun(): underrun due to no data available
[ 385007739.180334] ( 12.812499) c0 dma-trace src/audio/dai.c:727 ERROR comp_underrun(): dev->comp.id = 2, source->avail = 768, copy_bytes = 0
[ 385007785.482415] ( 46.302082) c0 dma-trace ....../pipeline-stream.c:134 ERROR pipeline_copy(): ret = -61, start->comp.id = 2, dir = 1
[ 385007798.659498] ( 13.177083) c0 dma-trace ..../pipeline-schedule.c:160 ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[ 385770207.327119] ( 762408.687500) c0 dma-trace src/drivers/dw/dma.c:1114 ERROR dw_dma_get_data_size(): xrun detected
[ 385770226.233368] ( 18.906250) c0 dma-trace src/audio/dai.c:879 ERROR dai_report_xrun(): underrun due to no data available
[ 385770239.150035] ( 12.916666) c0 dma-trace src/audio/dai.c:727 ERROR comp_underrun(): dev->comp.id = 2, source->avail = 768, copy_bytes = 0
[ 385770273.629200] ( 34.479164) c0 dma-trace ....../pipeline-stream.c:134 ERROR pipeline_copy(): ret = -61, start->comp.id = 2, dir = 1
[ 385770286.962533] ( 13.333333) c0 dma-trace ..../pipeline-schedule.c:160 ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
Activity
XiaoyunWu6666 commentedon Nov 17, 2021
@lyakh
FYI , @keyonjie run with the PR #4893 that reverted ]PR #4960, result : inner result 8207 The only one failure here is because of trigger release, no xrun happen.
For double confirm , I run another multiple pause release 100 test for multiple nocodec platform with PR #4893 , inner result 8251 no xrun happen.
lyakh commentedon Nov 17, 2021
I've looked at the latest daily result on APL nocodec, and I think I have an idea why this can be happening. The reason might be, that now that we handle STOP and PAUSE in pipeline tasks, we often have to stop several pipelines in cases, like a topology with a mixer, where the host and the DAI belong to different pipelines, and each of them has its own task. So the order might be important and where to send the reply from too... I'll investigate more.
lgirdwood commentedon Nov 17, 2021
I think the general robustness fix here is that when we have connected pipeline they are allowed to overrun and underrun without it being fatal. i.e.
lgirdwood commentedon Nov 17, 2021
Btw, this wont stop rc1, we can fix for v2.0 final though.
plbossart commentedon Nov 17, 2021
ALL the default topologies moving forward will have mixers and connected pipelines, not sure there's any merit in defining what we should do in a xrun. What we need to do is avoid the xrun in the first place. I've honestly NEVER seen this sort of concealment provide any benefit, in fact more often than not you end-up with worse problems such as channel swaps, etc.
keyonjie commentedon Nov 18, 2021
If there is no simple/quick fix for it, I would suggest to revert PR #4960 for the release, and add back new version which verified pass the multi-core stressful CI later.
1 remaining item
lyakh commentedon Nov 19, 2021
#5000 now fixes this. See internal test result number 8332.
miRoox commentedon Nov 30, 2021
After #5000 merged, this issue seems to happen only on Zephyr nocodec platforms.
lgirdwood commentedon Dec 1, 2021
@lyakh the pipeline simplification and ref counting updates after your vacation will really help this.
XiaoyunWu6666 commentedon Feb 14, 2022
haven't seen this for long time in daily tests , close it
marc-hb commentedon Feb 16, 2022
https://sof-ci.01.org/sofpr/PR5192/build12056/devicetest/?model=APL_UP2_NOCODEC_ZEPHYR&testcase=multiple-pause-resume-5
Similar to #5257?
lyakh commentedon Feb 17, 2022
@marc-hb are you sure it's the correct place to put this? Isn't your log pointing towards #4414 ?
marc-hb commentedon Feb 17, 2022
I don't remember seeing any xrun message in #4414 reproductions, is there? It's also a different test.
EDIT: at least not recently, maybe #4414 has been tracking different bugs over time.
miRoox commentedon Feb 25, 2022
In today's daily test (10509), a very similar xrun error happened on TGLU_RVP_NOCODEC and ADLP_RVP_NOCODEC when running multiple pipelines in parallel, but I cannot reproduce it. I guess it's the same as this issue, but just keep an eye on it.
miRoox commentedon Mar 17, 2022
This issue is out-of-date, now #5469 is used to track such xrun on TGLU_RVP_NOCODEC and ADLP_RVP_NOCODEC.