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

[ClarexZhou]

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]

@wenqingfu Ack. Not yet working on this, need to acquire some additional equipment to reproduce the scenario.

[wenqingfu]

Thank you very much, @kv2019i ! I move one more issue that looks similar to this one to you.

[kv2019i]

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) = 0

[kv2019i]

A few more observations:

• with enough iterations, the bug does not occur so reproduction rate seems less than 100%
• the error can be caused with different invocation orders
  - hdmi1->hdmi2->headset (original)
  - hdmi1->headset->hdmi2
  - headset->hdmi1->hdmi2
• as it's not specific to one specific route or sequence, it indicates this is a not a driver problem but rather a timing/scheduling issue on FW side
• error occurs at stream start

[mengdonglin]

@kv2019i Can SOF PR thesofproject/sof#1354 fix this issue in your side?

[kv2019i]

@bkokoszx FYI, sounds indeed similar

[kv2019i]

@kv2019i Can SOF PR thesofproject/sof#1354 fix this issue in your side?

I tested but did not help, rather PR1354 created issues even with a single stream. I'll report about this on 1354.

[kv2019i]

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.