Repository navigation
[Bug][CML]Pipeline will interact with each other with 3 aplay #898
Description
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 7, 2019
@wenqingfu Ack. Not yet working on this, need to acquire some additional equipment to reproduce the scenario.
wenqingfu commentedon May 7, 2019
Thank you very much, @kv2019i ! I move one more issue that looks similar to this one to you.
kv2019i commentedon May 9, 2019
Managed to reproduce the error as described on CFL SDP. It would seem problem gets triggers by start of one pipeline, followed by failure to recever from the XRUN. Problem starts with:
0 2 PIPE 1.5 61817040.937500 6.614583 src/audio/pipeline.c:358 pipeline_prepare() 0 2 HOST 61817044.218750 3.281250 src/audio/host.c:635 host_prepare() 0 2 VOLUME 61817057.083333 12.864583 src/audio/volume.c:515 volume_prepare() 0 2 DAI 1.4 61817079.739583 22.656250 src/audio/dai.c:465 dai_prepare() 0 2 DMA 61817083.385417 3.645833 intel/cavs/hda-dma.c:685 hda-dmac: 7 channel 0 -> config 0 2 BUFFER 61818164.947917 1081.562500 src/audio/buffer.c:200 comp_update_buffer_consume(), no bytes to consume 0 1 VOLUME 61818169.791667 4.843750 src/audio/volume.c:474 volume_copy() error: sink component buffer has not enough free bytes for copy 0 2 COMP 61818174.895833 5.104167 of/audio/component.h:718 comp_overrun(), ((dev->comp.id << 16) | sink->free) = 2031616, ((min_bytes << 16) | copy_bytes) = 0kv2019i commentedon May 9, 2019
A few more observations:
- hdmi1->hdmi2->headset (original)
- hdmi1->headset->hdmi2
- headset->hdmi1->hdmi2
mengdonglin commentedon May 13, 2019
@kv2019i Can SOF PR thesofproject/sof#1354 fix this issue in your side?
kv2019i commentedon May 13, 2019
@bkokoszx FYI, sounds indeed similar
kv2019i commentedon May 13, 2019
I tested but did not help, rather PR1354 created issues even with a single stream. I'll report about this on 1354.
kv2019i commentedon May 13, 2019
Based on today's bug scrub, matches case reproduced in python test framework, moving to FW and tracking as thesofproject/sof#1413 . Closing this bug.