[Bug][CML] Pipeline will interact with each other with 3 aplay

[kv2019i]

**Cloned and moved bug from Linux to SOF, original bug thesofproject/linux#898 **

Describe the bug
This issue can occur when 3 pipeline playback are running in different terminals, when trigger the 3rd will cause HDMI playback stop with I/O error.

To Reproduce

1. open two terminals and do playback on each terminal with different pcm device.
   terminal 1 DP playback: aplay -Dhw:0,4 -f dat -c 2 audio.wav
   terminal 2 HDMI playback: aplay -Dhw:0,3 -f dat -c 2 audio.wav
2. Start 3rd headset playback
   terminal 3 headset playback: aplay -Dhw:0,0 -f dat -c 2 audio.wav

Expected behavior
no interaction between each pipeline.

Impact
Trigger headset as 3rd pipeline will cause HDMI playback stop with I/O error.

Environment
sof-master: de5bba4
tplg: sof-hda-generic-2ch.tplg
kernel-release/sof-v5.0: c99938c
platform: CML laptop
Reproducibility Rate: 100%

dmesg

[ 445.472555] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 1
[ 445.472560] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 445.472859] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 445.472861] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 445.961876] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 445.961909] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 446.461839] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 446.461875] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 450.324552] sof-audio-pci 0000:00:1f.3: pcm: open stream 3 dir 0
[ 450.324554] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 450.324556] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 450.324556] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 450.324725] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 450.324732] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 3 dir 0
[ 450.324733] sof-audio-pci 0000:00:1f.3: generating page table for 0000000094b04b98 size 0xffc0 pages 16
[ 450.324756] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 450.324757] sof-audio-pci 0000:00:1f.3: periods:4
[ 450.324768] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 450.324773] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 450.324956] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 450.324959] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[ 450.961867] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 450.961908] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 451.329438] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 0 cmd 1
[ 451.329467] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 451.329674] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 451.329686] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 451.961905] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 451.961941] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 456.527798] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 456.527805] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 456.527809] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 456.527813] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 456.528539] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 456.528565] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 456.528575] sof-audio-pci 0000:00:1f.3: generating page table for 0000000013ae9f4a size 0xffc0 pages 16
[ 456.528628] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 456.528631] sof-audio-pci 0000:00:1f.3: periods:4
[ 456.528659] sof-audio-pci 0000:00:1f.3: stream_tag 3
[ 456.528679] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 456.528973] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 456.528985] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790680
[ 456.534974] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[ 456.534983] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 456.535194] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 456.535199] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 457.462054] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 457.462084] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 458.247949] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 3 dir 0 cmd 0
[ 458.247968] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 458.248225] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 458.248240] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 458.248272] sof-audio-pci 0000:00:1f.3: pcm: free stream 3 dir 0
[ 458.248280] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 458.248469] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 458.248599] sof-audio-pci 0000:00:1f.3: pcm: close stream 3 dir 0
[ 458.961913] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 458.961954] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 462.755043] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 462.755072] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 462.755235] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 462.755245] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 462.755430] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 462.755442] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 462.755697] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 462.755883] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 463.462052] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 463.462086] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG

sof-logger

 CORE LEVEL COMP_ID TIMESTAMP DELTA FILE_NAME	CONTENT
 0 1 VOLUME 13966829.270833 13966829.000000 src/audio/volume.c:474 	volume_copy() error: sink component buffer has not enough free bytes for copy
 0 1 PIPE 13966877.656250 48.385418 src/audio/pipeline.c:736 	pipeline_copy() error: ret = -5, start->comp.id = 31, dir = 1
 0 1 PIPE 7.35 13966884.479167 6.822917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
 0 1 DMA 13968323.802083 1439.322876 intel/cavs/hda-dma.c:279 	hda-dmac: 5 wait for buffer full timeout
 0 1 HOST 13968330.364583 6.562500 src/audio/host.c:792 	host_copy() error: dma_copy() failed, ret = 4294967234
 0 1 PIPE 13968336.666667 6.302083 src/audio/pipeline.c:736 	pipeline_copy() error: ret = -62, start->comp.id = 34, dir = 1
 0 1 PIPE 7.35 13968343.333333 6.666667 src/audio/pipeline.c:844 	pipeline_xrun_recover()
 0 1 COMP 13968356.875000 13.541667 rc/audio/component.c:204 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
 0 1 PIPE 13968362.916667 6.041667 src/audio/pipeline.c:365 	pipeline_prepare() error: ret = -22,dev->comp.id = 30
 0 1 PIPE 7.35 13968369.375000 6.458333 src/audio/pipeline.c:851 	pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
 0 1 PIPE 7.35 13968375.208333 5.833333 src/audio/pipeline.c:920 	pipeline_task(): xrun recover failed! pipeline will be stopped!

pipleline_dmesg.log
logger.log

[kv2019i]

Moved the bug here as this seems to be a firmware side issue (please see the the Linux side issue, there are a couple of logs and comments that might be useful). @bkokoszx ok for you to be in the initial assignee? I can help to run test with the Linux scenario and can help with the debug.

[tlauda]

@kv2019i To be honest, it looks more like kernel issue than FW issue. What is happening is that right after receiving params for the third stream, the Host DMA and Link DMA for the second stream stop transmitting data. Xrun is reported on the second stream, because Link DMA pointer hasn't increased, so we try to recover, but also Host DMA isn't moving (hence buffer full timeout).

[keyonjie]

@kv2019i To be honest, it looks more like kernel issue than FW issue. What is happening is that right after receiving params for the third stream, the Host DMA and Link DMA for the second stream stop transmitting data. Xrun is reported on the second stream, because Link DMA pointer hasn't increased,

This sounds interesting, can anyone print out dma channel indices for both host DMA and link DMA for those streams?

so we try to recover, but also Host DMA isn't moving (hence buffer full timeout).

[kv2019i]

Ok, it seems with the sof+linux fix for channel allocation, this issue is fixed -> #1354

[ClarexZhou]

Error Not seen on CML laptop with #1354 and PR #895
Environment
platform: CML laptop with ALC3204 codec
Rander UCM https://github.com/RanderWang/intel-UCM
Kernel repo：9494607 https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: https://github.com/bardliao/sof/tree/dell-test Which is commit id b73b9a6 + PR #1354
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

[lgirdwood]

@kv2019i can we close ?

[kv2019i]

@lgirdwood I was waiting for 1354+895 to be actually merged before closing.