Repository navigation
[BUG]underrun due to no data available when multiple-pipeline on CML_HEL_RT5682 #4560
Description
Describe the bug
in inner daily 5539?model=CML_HEL_RT5682&testcase=multiple-pipeline-all
underrun happened when multiple pipeline and xrun recovery failed
can reproduce it
To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt1011-rt5682.tplg ~/sof-test/test-case/multiple-pipeline.sh -f p -c 20
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 85bfa34a
SOF Branch: main
SOF Commit: 9a7a5ce
Topology:sof-cml-rt1011-rt5682.tplg
Platform:CML_HEL_RT5682
Screenshots or console output
[etrace]
[ 412591.494022] ( 412591.500000) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
[ 412670.660685] ( 79.166664) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
[ 412758.473182] ( 87.812500) c0 dma-trace src/drivers/dw/dma.c:1102 ERROR dw_dma_get_data_size(): xrun detected
[ 412772.223181] ( 13.749999) c0 dma-trace src/audio/dai.c:886 ERROR dai_report_xrun(): underrun due to no data available
[ 412786.025264] ( 13.802083) c0 dma-trace src/audio/dai.c:675 ERROR comp_underrun(): dev->comp.id = 4, source->avail = 192, copy_bytes = 0
[ 412799.566930] ( 13.541666) c0 dma-trace ....../pipeline-stream.c:307 ERROR pipeline_trigger_run(): ret = -22, host->comp.id = 0, cmd = 8
[ 412812.900263] ( 13.333333) c0 dma-trace ......../pipeline-xrun.c:159 ERROR pipeline_xrun(): Pipelines notification about XRUN failed, ret = -22
[ 412842.796095] ( 29.895832) c0 dma-trace ....../pipeline-stream.c:194 ERROR pipeline_copy(): ret = -61, start->comp.id = 4, dir = 1
[ 412855.921095] ( 13.124999) c0 dma-trace ..../pipeline-schedule.c:95 ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[ 412930.191925] ( 74.270828) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
[ 413212.691914] ( 282.500000) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
[ 413291.025244] ( 78.333328) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
[ 413367.275241] ( 76.250000) c0 dma-trace ..../intel/hda/hda-dma.c:861 ERROR hda_dma_link_check_xrun(): underrun detected
Activity
ranj063 commentedon Jul 29, 2021
the problem was introduced by 9a7a5ce17dcb
@lyakh FYI
plbossart commentedon Jul 29, 2021
https://sof-ci.sh.intel.com/#/result/planresultdetail/5568?model=CML_HEL_RT5682&testcase=multiple-pipeline-all
dmesg.txt
slogger.txt
lgirdwood commentedon Jul 29, 2021
@lyakh from the logs above pasted by @plbossart it looks like we get stuck somewhere for ~10ms after starting SSP1
This also causes the agent to be late, so it seems we are spinning somewhere with IRQs OFF.
plbossart commentedon Jul 29, 2021
One possible reason why we only see this problem on Helios is the topology:
The code now explicitly does
Is this a valid assumption when there are split/joins in pipelines?
lyakh commentedon Jul 30, 2021
@plbossart the loop topology is a great tip, thanks! Wondering what other devices have similar ones and particularly which of them I have available for testing...
UPDATE 1: but looking through the trace those pipelines 8 and 9 aren't used. Confused.
bardliao commentedon Jul 30, 2021
I don't know if this helps. I print
p->trigger.cmdinpipeline_taskAnd it seems no
WARN pipeline_task(): bard: p->trigger.cmd 1beforeERROR hda_dma_link_check_xrun(): underrun detectedtrace.txt
plbossart commentedon Jul 30, 2021
Indeed it seems this loop needs to be handled, but it's unlikely to be the cause of this issue: we don't actually test the 16kHz input !!
This is a gap in our coverage, so we need to change the tests and be ready for new bugs to pop-up...
lyakh commentedon Jul 30, 2021
@plbossart @lgirdwood I think I have a trace. What that my patch does is move "trigger START" to task context. What that means, is that when the host sends a "trigger START" the firmware will get the IPC, and schedule its processing in the pipeline's LL scheduling task. Next scheduling tick the scheduler begins scheduling tasks. I.e. it runs a loop over its list of scheduled tasks. One of those tasks is executing the "trigger START" from the last IPC. So far so good. But I've just caught a case where this START processing for pipeline 7 (SSP1 out) took more than 10ms on Helios. Everybody dies (TM)
UPDATE: and it's the
dai_comp_trigger()running for the SSPlyakh commentedon Jul 30, 2021
we have a problem with Helios speakers:
i.e. all other DAIs initialise in under 100us, and the speaker DAI takes more than 10ms
2 remaining items
lyakh commentedon Aug 2, 2021
@lgirdwood I think I know why, because of this line
in platform/intel/cml.m4 which sets
SOF_TKN_INTEL_SSP_BCLK_DELAYfor SSP1 to 10 which then is used inin ssp.c. Any idea why that is needed?
bardliao commentedon Aug 2, 2021
Some codecs need BCLK enabled while configuring their registers. With SET_SSP1_CONFIG_DATA sets BCLK will start a provided delay before SSP data start and the codecs can configure their registers in the time. Using SSP_CC_BCLK_ES (BCLK early start) may also work now. See
32d04e9
lgirdwood commentedon Aug 2, 2021
Ok, this is broken. @lyakh so this will need reflected in the LL PR. i.e. we will need to
early_trigger()and call this at LL tick 0. (this starts the SSP BCLK)This means we can remove the busy wait in ssp.c
plbossart commentedon Aug 2, 2021
Not following @lgirdwood
Yes there is a 10ms delay that looks like a copy-paste mistake, it's not really necessary here.
But is it wrong? Is there any assumption that the trigger completes immediately, and if yes what did change in @lyakh's update?
We have a couple of wait_delay() calls in the SSP, and it'd be useful to clarify the rules/expectations on when a wait is tolerated.
XiaoyunWu6666 commentedon Aug 3, 2021
Close it now since relevant feature was reverted in #4578
lyakh commentedon Aug 3, 2021
@plbossart my PR moved the trigger:START processing from the IPC thread context to the pipeline task context. And when you busy-loop for 10ms in a LL task you block all other LL tasks for that time.
lyakh commentedon Aug 3, 2021
@lgirdwood yes, this is a possibility. And you're proposing to keep the order of component triggering otherwise the same? Maybe it would be more like a late trigger, than an early trigger. I.e. in the loop where all START triggers are called, a component can return a status, that tells the caller, that the component needs a delay. The loop would then break. 10 ticks later the
trigger_late()callback from the delayed component would be called, after which thepipeline_for_each_comp()loop would resume from the next component? Hopefully no components need more than one delay...lgirdwood commentedon Aug 3, 2021
So the delay is fine as it's needed by the codec, but its how we are delaying that is an issue. @lyakh will update FW so we can do any codec required delay and add this to pipeline state machine i.e. we will probably have a 2 internal TRIGGER_START commands that can be used internally (no change for host).
I think a rough rule of thumb is probably less than 100uS in total for DAI state transitions (since copy() is not performed on the same LL tick)
lyakh commentedon Sep 6, 2021
@XiaoyunWu6666 @lgirdwood @plbossart Can this be closed now that #4559 has been merged?
XiaoyunWu6666 commentedon Sep 6, 2021
@lyakh hi , for me it's good to close since it haven't happened in daily tests for almost more than two weeks
keyonjie commentedon Sep 6, 2021
I am still seeing this with my debugging today, but not sure if it is introduced by my local change.
Can we leave this open for some more days?
XiaoyunWu6666 commentedon Jan 24, 2022
haven't seen it in CI for over 3 months