[BUG] [TGL] XRUN on speaker/headset path with the IGO integrated firmware while starting the PCM99 capture

[RDharageswari]

Describe the bug
With the IGO integrated firmware and topology, XRUN is observed in the playback pipeline, be it headset/the speaker path with DSM module.

To Reproduce
Start playback on one terminal(speaker with DSM or the headset pipeline)
localhost ~ # aplay -Dhw:0,0 Titanium_low1.wav -c2 -r48000 -fs24_le
start capture on other terminal:
localhost ~ # arecord -Dhw:0,99 try.wav -c4 -r48000 -fs32_le -d60 &
The moment the capture stream is opened
Playback returns I/O error:
aplay: pcm_write:2059: write error: Input/output error

Reproduction Rate
Always.
Very easy to repro.

Expected behavior
playback is on core 0 and IGO module runs on core 1.
The moment capture stream is started the playback on core 0 stalls.
Is it that core 0 is blocked here?

Impact
blocker for IGO integration

Environment
Tgl_13release + private patches in google repo+ Intelligo module(
have shared all the binaries through email as they are closed source.
Please let me know if you need more details.

Screenshots or console output
localhost ~ # ./sof-logger -l sof-tgl.ldc
TIMESTAMP (us) DELTA C# COMPONENT LOCATION CONTENT ktime=75.835s @ 2021-06-21 18:39:54 -0700 PDT
[ 105098936.344577] ( 0.000000) c0 dma-trace src/trace/dma-trace.c:335 ERROR FW ABI 0x3012001 DBG ABI 0x5003000 tag v1.8-rc2-45-gd143acb3ece8 src hash 0x38d78a96 (ldc hash 0x38d78a96)
[ 20826327.349519] ( 20826328.000000) c0 dw-dma src/drivers/dw/dma.c:1100 ERROR dw_dma_get_data_size(): xrun detected
[ 20826344.641185] ( 17.291666) c0 dai 1.5 src/audio/dai.c:1069 ERROR dai_report_xrun(): underrun due to no data available
[ 20826361.984935] ( 17.343750) c0 dai 1.5 src/audio/dai.c:686 ERROR comp_underrun(): dev->comp.id = 5, source->avail = 384, copy_bytes = 0
[ 20826481.412013] ( 119.427078) c0 pipe 1.6 ....../pipeline-stream.c:168 ERROR pipeline_copy(): ret = -61, start->comp.id = 5, dir = 1
[ 20826500.422429] ( 19.010416) c0 pipe 1.6 ..../pipeline-schedule.c:63 ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!

[slawblauciak]

Here are my observations:

I was successfully able to reproduce the issue. At the point of problem occurring (I/O error in aplay) I could see an xrun in the FW trace logs, followed by a constant flow of warnings from the system agent, which shows a consistent problem in the DSP core taking too long to process.

[ 11611479.642768] ( 31989.634766) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 370857

I can get the same warnings to appear without aplay, just arecord running.

@RDharageswari
Reading the logs, it appears the period for this pipeline is 16 ms. Is that correct?

---

Performance counters show that the IGO component takes upwards of 3.8M cycles to complete a copy. Now, if one would assume that each instruction takes exactly one cycle, that'd make it 9.5 ms, which is well below 16 ms. The problem is that very assumption however, since various instructions take different amounts of cycles to complete and it all depends on the state of the DSP pipeline.
If we were to assume 1.5 cycles per instruction, that's already over 14 ms.

This finding in conjunction with the agent constantly complaining every other period reinforces my suspicion that the IGO simply takes too long to complete, as a result making the DSP core unable to respond to various events properly, such as IDC communication, which in turn causes other cores trying to communicate with it to stall, in the end, manifesting itself as this xrun.

I will continue debugging this, to ensure that the initial measurements are correct, this time using alternative method.

[fuyuntsuo]

Thanks @slawblauciak . Your observation is correct that IGO component takes about 9.5 ms to complete. That's why we moved it to Core 1 (c32a0e0) so that other components and IDC shouldn't be affected by IGO's long computing time. We just don't understand why IDC (on Core 0) still complains and why smart-amp (on Core 0) turns out to be xrun even in this case.

Here is a information might help. Before moving IGO to Core 1, we used to extend smart-amp period to 16ms (7769778), prolonging buffer so that no xrun occurs. Now since IGO is running on Core 1, there should be no need to apply such patch.

To my surprise, this patch is still working after IGO moved to Core 1.

I am working on integrating IGO component on SOF. Please ping me if needed. Thanks.

[fuyuntsuo]

Another question: does the performance counter count cycle or instruction? If cycle then 3.5M cycles should be okay. If instruction, then cycle-per-instruction does matter as you pointed out.

[keyonjie]

@fuyuntsuo it's big information that the IGO component takes about 9.5 ms to complete each iteration, this will for sure blocks other tasks (e.g. 1ms SA task) regular runs.

[ranj063]

@fuyuntsuo it's big information that the IGO component takes about 9.5 ms to complete each iteration, this will for sure blocks other tasks (e.g. 1ms SA task) regular runs.

@keyonjie SA is disabled in the chrome prpducts.

[keyonjie]

@fuyuntsuo it's big information that the IGO component takes about 9.5 ms to complete each iteration, this will for sure blocks other tasks (e.g. 1ms SA task) regular runs.

@keyonjie SA is disabled in the chrome prpducts.

Okay, I see that from @slawblauciak 's comment:

[ 11611479.642768] ( 31989.634766) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 370857

Anyway, we still have bunch of pipelines scheduled in 1ms period.

@fuyuntsuo how could it happen to takes 9.5ms for each IGO .copy()? it's ~40 times of DSM or GHD!

[fuyuntsuo]

Hi @keyonjie, let's make this assumption here if the answer is not blocking this issue. We could discuss why IGO takes much cycles via email since Intel has signed NDA with us. Can anyone from Intel bridge us?

[fuyuntsuo]

May I know what does SA stand for? And why it is affected given IGO is running on Core 1.

[ranj063]

May I know what does SA stand for? And why it is affected given IGO is running on Core 1.

@fuyuntsuo SA is the system agent. It is not enabled in the chrome product FW. So its not a concern