Repository navigation
[Bug][CML] Pipeline will interact with each other with 3 aplay #1413
Description
**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
- 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 - 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!
Activity
kv2019i commentedon May 13, 2019
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 commentedon May 13, 2019
@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 commentedon May 13, 2019
This sounds interesting, can anyone print out dma channel indices for both host DMA and link DMA for those streams?
kv2019i commentedon May 13, 2019
Ok, it seems with the sof+linux fix for channel allocation, this issue is fixed -> #1354
ClarexZhou commentedon May 14, 2019
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 commentedon May 17, 2019
@kv2019i can we close ?
kv2019i commentedon May 20, 2019
@lgirdwood I was waiting for 1354+895 to be actually merged before closing.
kv2019i commentedon May 29, 2019
Patch merged to Linux now - thesofproject/linux#895 Closing bug once FW side is merged as well.
lgirdwood commentedon May 29, 2019
@kv2019i FW #1354 merged when CI completes today.
kv2019i commentedon May 29, 2019
Ack, closing.