[BUG] pipeline will interact with each other in HDA mode

[keqiaozhang]

Describe the bug
This issue can occur when 2 pipeline playback are running in different terminals, terminating one of them will cause another pipeline stop with I/O error.

To Reproduce

1. open two terminals and do playback on each terminal with different pcm device.
   terminal 1 headset playback: aplay -Dhw:0,0 -f dat -c 2 audio.wav
   terminal 2 HDMI playback: aplay -Dhw:0,2 -f dat -c 2 audio.wav
2. press ctl+c to stop HDMI playback, then check the status of the another one.
3. At least use one HDA pcm device to do the playback.

Expected behavior
no interaction between each pipeline.

Impact
terminating one of them will cause another pipeline stop with I/O error.

Environment

1. sof-master: 0c9326
2. tplg: sof-whl-rt5682.tplg
3. kernel-sof-dev: 90860
4. platform: WHL-I2S
5. Reproducibility Rate: 100%

Screenshots or console output
$ aplay -Dhw:0,0 -f dat -c 2 test.wav
Playing WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
underrun!!! (at least 0.047 ms long)
aplay: pcm_write:2011: write error: Input/output error

dmesg
no observes errors.

sof-logger

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1       VOLUME          27044583.385417  27044584.000000   src/audio/volume.c:465    volume_copy() error: source component buffer has not enough data available
    0      1         PIPE          27044804.479167       221.093750 src/audio/pipeline.c:681    pipeline_copy() error: ret = -5, start->comp.id = 1, dir = 1
    0      1         PIPE 1.5      27044811.041667         6.562500 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      1          DMA          27045177.395833       366.354156 intel/cavs/hda-dma.c:279    hda-dmac: 5 wait for buffer full timeout
    0      1         HOST          27045183.958333         6.562500     src/audio/host.c:792    host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE          27045189.947917         5.989583 src/audio/pipeline.c:681    pipeline_copy() error: ret = -62, start->comp.id = 4, dir = 1
    0      1         PIPE 1.5      27045196.562500         6.614583 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      1         COMP          27045209.479167        12.916667 rc/audio/component.c:201    comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE          27045215.364583         5.885417 src/audio/pipeline.c:365    pipeline_prepare() error: ret = -22,dev->comp.id = 0
    0      1         PIPE 1.5      27045221.614583         6.250000 src/audio/pipeline.c:796    pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.5      27045227.239583         5.625000 src/audio/pipeline.c:865    pipeline_task(): xrun recover failed! pipeline will be stopped!

logger-t :

   0      2       BUFFER          27043352.395833      1244.635376   src/audio/buffer.c:127    comp_update_buffer_produce(), no bytes to produce
    0      2          DMA          27043357.031250         4.635417 intel/cavs/hda-dma.c:627    hda-dmac: 5 channel 0 -> stop
    0      1       VOLUME          27044583.385417      1226.354126   src/audio/volume.c:465    volume_copy() error: source component buffer has not enough data available
    0      2         COMP          27044589.270833         5.885417 of/audio/component.h:700    comp_underrun(), ((dev->comp.id << 16) | source->avail) = 65536, ((min_bytes << 16) | copy_bytes) = 0
    0      2         PIPE 1.5      27044593.281250         4.010417 src/audio/pipeline.c:540    pipeline_trigger()
    0      2         HOST          27044597.447917         4.166667     src/audio/host.c:283    host_trigger()
    0      2          DMA          27044602.083333         4.635417 intel/cavs/hda-dma.c:627    hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME          27044606.562500         4.479167   src/audio/volume.c:434    volume_trigger()
    0      2          DAI 1.4      27044610.729167         4.166667      src/audio/dai.c:528    dai_comp_trigger(), command = 8
    0      2          DAI 1.4      27044614.635417         3.906250      src/audio/dai.c:586    dai_comp_trigger(), XRUN
    0      2          DAI 1.4      27044618.125000         3.489583      src/audio/dai.c:592    dai_comp_trigger(), PAUSE/STOP
    0      2          DMA          27044621.770833         3.645833 src/drivers/dw/dma.c:456    dw_dma_stop(): dma 0 channel 0 stop
    0      2          SSP          27044630.520833         8.750000 ers/intel/cavs/ssp.c:812    ssp_trigger() cmd 0
    0      2          SSP          27044793.333333       162.812500 ers/intel/cavs/ssp.c:793    ssp_stop(), TX stop
    0      2          SSP          27044798.177083         4.843750 ers/intel/cavs/ssp.c:802    ssp_stop(), SSP port disabled
    0      1         PIPE          27044804.479167         6.302083 src/audio/pipeline.c:681    pipeline_copy() error: ret = -5, start->comp.id = 1, dir = 1
    0      1         PIPE 1.5      27044811.041667         6.562500 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      2         PIPE 1.5      27044816.197917         5.156250 src/audio/pipeline.c:358    pipeline_prepare()
    0      2         HOST          27044820.312500         4.114583     src/audio/host.c:635    host_prepare()
    0      2         COMP          27044824.166667         3.854167 rc/audio/component.c:136    comp_set_state(), state already set to 3
    0      2         PIPE 1.5      27044828.333333         4.166667 src/audio/pipeline.c:540    pipeline_trigger()
    0      2         HOST          27044832.395833         4.062500     src/audio/host.c:283    host_trigger()
    0      2          DMA          27044836.562500         4.166667 intel/cavs/hda-dma.c:533    hda-dmac: 5 channel 0 -> start
    0      2          DMA          27044840.625000         4.062500 intel/cavs/hda-dma.c:369    hda-dmac: 5 channel 0 -> enable
    0      2       VOLUME          27044898.958333        58.333332   src/audio/volume.c:434    volume_trigger()
    0      2          DAI 1.4      27044902.916667         3.958333      src/audio/dai.c:528    dai_comp_trigger(), command = 1
    0      2          DAI 1.4      27044906.770833         3.854167      src/audio/dai.c:539    dai_comp_trigger(), START
    0      1          DMA          27045177.395833       270.625000 intel/cavs/hda-dma.c:279    hda-dmac: 5 wait for buffer full timeout
    0      1         HOST          27045183.958333         6.562500     src/audio/host.c:792    host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE          27045189.947917         5.989583 src/audio/pipeline.c:681    pipeline_copy() error: ret = -62, start->comp.id = 4, dir = 1
    0      1         PIPE 1.5      27045196.562500         6.614583 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      2         PIPE 1.5      27045201.718750         5.156250 src/audio/pipeline.c:358    pipeline_prepare()
    0      2         HOST          27045205.729167         4.010417     src/audio/host.c:635    host_prepare()
    0      1         COMP          27045209.479167         3.750000 rc/audio/component.c:201    comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE          27045215.364583         5.885417 src/audio/pipeline.c:365    pipeline_prepare() error: ret = -22,dev->comp.id = 0
    0      1         PIPE 1.5      27045221.614583         6.250000 src/audio/pipeline.c:796    pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.5      27045227.239583         5.625000 src/audio/pipeline.c:865    pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      2          IPC          29281219.739583   2235992.500000    src/ipc/handler.c:480    ipc: comp 0 -> trigger cmd 0x50000
    0      2         PIPE 1.5      29281224.739583         5.000000 src/audio/pipeline.c:540    pipeline_trigger()
    0      2         HOST          29281229.322917         4.583333     src/audio/host.c:283    host_trigger()
    0      2          DMA          29281234.010417         4.687500 intel/cavs/hda-dma.c:627    hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME          29281238.854167         4.843750   src/audio/volume.c:434    volume_trigger()
    0      2          DAI 1.4      29281243.177083         4.322917      src/audio/dai.c:528    dai_comp_trigger(), command = 0
    0      2          DAI 1.4      29281247.083333         3.906250      src/audio/dai.c:592    dai_comp_trigger(), PAUSE/STOP
    0      2          DMA          29281251.041667         3.958333 src/drivers/dw/dma.c:456    dw_dma_stop(): dma 0 channel 0 stop
    0      2          SSP          29281257.760417         6.718750 ers/intel/cavs/ssp.c:812    ssp_trigger() cmd 0
    0      2          SSP          29281421.354167       163.593750 ers/intel/cavs/ssp.c:802    ssp_stop(), SSP port disabled
    0      2          IPC          29281749.166667       327.812500    src/ipc/handler.c:369    ipc: comp 0 -> free
    0      2         PIPE 1.5      29281753.802083         4.635417 src/audio/pipeline.c:583    pipeline_reset()
    0      2         HOST          29281757.968750         4.166667     src/audio/host.c:699    host_reset()
    0      2          DMA          29281762.135417         4.166667 intel/cavs/hda-dma.c:627    hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME          29281769.322917         7.187500   src/audio/volume.c:601    volume_reset()

dmesg.log
logger.log
logger-t.log

[keqiaozhang]

@Jiangxinx @ClarexZhou
Could you please help to verify this issue on other HDA platform?

[ClarexZhou]

Behavior is different on CML.
No interaction between Dhw:0,0 and Dhw:0,3
Only no audio output when start aplay on Dhw:0,1 during playing on Dhw:0,0.
No interaction when press ctl+c to stop one.

Environment
Kernel Repo: https://github.com/RanderWang/linux/commits/cml-validation-20190422
Made from: RanderWang/linux@9086043 [thesofproject/linux: topic/sof-dev]
+RanderWang/linux@c105b1b
+RanderWang/linux@ffecddc
+RanderWang/linux@3b917aa
+RanderWang/linux@6f928a3
+RanderWang/linux@a916d2d
+RanderWang/linux@694599b
+RanderWang/linux@a43379d
+RanderWang/linux@d36ed40
+RanderWang/linux@9b3bd71
+RanderWang/linux@e852311
+RanderWang/linux@8f30111
+RanderWang/linux@95cd082

Firmware Repo :https://github.com/bardliao/sof/tree/whl-daliy-20190422
Made from: bardliao/linux@0c93261

• bardliao/linux@35fbf79
• bardliao/linux@3f91567

Topology: Same as above SOF repo

[wenqingfu]

@keqiaozhang can you please help to verify if this issue can be reproduced on I2S platform? thanks!

[keqiaozhang]

@keqiaozhang can you please help to verify if this issue can be reproduced on I2S platform? thanks!

@wenqingfu , I tried to reproduce this issue on GLK before, but it's blocked by #828 , HDMI is not working.
I just tested it again with PR #834 on GLK, this issue can be reproduced. The reproducibility rate is about 20% and IPC timed out when TRIG_START, but audio is still working in the next run.

[  339.892580] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 1 dir 0 cmd 1
[  339.892585] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  340.197136] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60040000 size 12
[  340.197142] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  340.197180] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  340.197182] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  340.197184]  Headset: ASoC: trigger FE failed -110
[  340.197186] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 1 dir 0 cmd 0
[  340.197212] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP

trace log:

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1       VOLUME           9387949.166667   9387949.000000   src/audio/volume.c:465    volume_copy() error: source component buffer has not enough data available
    0      1         PIPE           9388138.125000       188.958328 src/audio/pipeline.c:681    pipeline_copy() error: ret = -5, start->comp.id = 9, dir = 1
    0      1         PIPE 2.13      9388144.427083         6.302083 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      1          DMA           9388437.291667       292.864594 intel/cavs/hda-dma.c:279    hda-dmac: 5 wait for buffer full timeout
    0      1         HOST           9388443.541667         6.250000     src/audio/host.c:792    host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE           9388449.166667         5.625000 src/audio/pipeline.c:681    pipeline_copy() error: ret = -62, start->comp.id = 12, dir = 1
    0      1         PIPE 2.13      9388455.520833         6.354167 src/audio/pipeline.c:789    pipeline_xrun_recover()
    0      1         COMP           9388468.072917        12.552083 rc/audio/component.c:201    comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE           9388473.854167         5.781250 src/audio/pipeline.c:365    pipeline_prepare() error: ret = -22,dev->comp.id = 8
    0      1         PIPE 2.13      9388479.791667         5.937500 src/audio/pipeline.c:796    pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 2.13      9388485.104167         5.312500 src/audio/pipeline.c:865    pipeline_task(): xrun recover failed! pipeline will be stopped!

dmesg.log
logger.log
logger-t.log

Test recipe:
kernel: sof-dev/2e9456 +PR #834
sof/tplg: master/e4c1651

[stevyan]

Summary
Not reproduce on APL UP2 pcm512x

Step

1. aplay -Dhw:0,0 -f s16_le -r 48000 -c 2 /dev/zero
2. aplay -Dhw:0,2 -f s16_le -r 48000 -c 2 /dev/zero (HDMI)

Actual Result
No error occurred.

Test recipe
Date: 2019-04-24
sof (master): e4c1651
kernel (topic/sof-dev): 2e94569
topology: sof-apl-pcm512x.tplg

[libinyang]

Clair's bug is narrowed down to codec issue. As per discussion we can lower its priority.
It is different from Keqiao's bug. Clair, could you please open a new issue for it?

[stevyan]

Summary
"write error: Input/output error" occurred on APL UP2 pcm512x

Step

1. playback HDMI firstly at Terminal A. aplay -Dhw:0,2 -f s16_le -r 48000 -c 2 /dev/zero
2. Terminal B: aplay -Dhw:0,0 -f s16_le -r 48000 -c 2 /dev/zero

Actual Result

1. Terminal A: write error: Input/output error
2. Terminal B: underrun, and then "write error: Input/output error"

Test recipe
Date: 2019-04-24
sof (master): e4c1651
kernel (topic/sof-dev): 2e94569
topology: sof-apl-pcm512x.tplg

dmesg log

[25672.069244] sof-audio-pci 0000:00:0e.0: pcm: free stream 2 dir 0
[25672.069252] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[25672.069461] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[25672.069544] sof-audio-pci 0000:00:0e.0: pcm: close stream 2 dir 0
[25672.069560] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[25672.069576] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[25672.069810] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[25672.085975] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 1
[25672.085997] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[25672.388744] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60040000 size 12
[25672.388762] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[25672.388808] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[25672.388815] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[25672.388825]  Port5: ASoC: trigger FE failed -110
[25672.388842] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[25672.388858] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[25672.692703] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60050000 size 12
[25672.692721] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[25672.692766] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[25672.692773] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[25672.692784]  Port5: ASoC: trigger FE failed -110
[25673.300849] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[25673.300867] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[25673.604500] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[25673.604510] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[25673.604549] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[25673.604551] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[25673.618544] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0
[25675.766250] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[25676.068721] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x40010000 size 76
[25676.068739] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[25676.068784] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[25676.068793] sof-audio-pci 0000:00:0e.0: error: ctx_save ipc error during suspend -110
[25676.068813] sof-audio-pci 0000:00:0e.0: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)

[plbossart]

Can we have confirmation that the two outputs work in isolation and the issues only show up when the two outputs are used concurrently.

[keqiaozhang]

Can we have confirmation that the two outputs work in isolation and the issues only show up when the two outputs are used concurrently.

Yes, the two outputs work in isolation and the issue only can be reproduced when two outputs are used concurrently.
I also tested the following scenario on GLK, there're two TYPE-C connectors, so we can do playback on these 2 ports via the converters.

Steps:

1. Terminal A: do playback on HDMI (type-c to HDMI).
2. Terminal B: do playback on DP (type-c to DP), at this time, both of them stop immediately with I/O error.
   Dmesg:

[  566.305205] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  566.605311] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60040000 size 12
[  566.605317] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  566.605354] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  566.605356] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  566.605359]  HDMI1: ASoC: trigger FE failed -110
[  566.605361] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 5 dir 0 cmd 0
[  566.605365] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  566.605385] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  566.605390] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[  566.605397] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  567.213480] sof-audio-pci 0000:00:0e.0: pcm: free stream 5 dir 0
[  567.213483] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  567.517308] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[  567.517311] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  567.517348] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  567.517350] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  567.517393] sof-audio-pci 0000:00:0e.0: pcm: close stream 5 dir 0
[  567.541767] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[  567.541772] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  567.541792] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG

trace:

    0      2          SSP           5646528.177083         4.791667 ers/intel/cavs/ssp.c:802    ssp_stop(), SSP port disabled
    0      2          IPC           5646675.625000       147.447922    src/ipc/handler.c:369    ipc: comp 1 -> free
    0      2         PIPE 1.6       5646680.625000         5.000000 src/audio/pipeline.c:583    pipeline_reset()
    0      2         HOST           5646684.687500         4.062500     src/audio/host.c:699    host_reset()
    0      2          DMA           5646688.697917         4.010417 intel/cavs/hda-dma.c:627    hda-dmac: 5 channel 0 -> stop
    0      1         PIPE           5646695.468750         6.770833 src/audio/pipeline.c:681    pipeline_copy() error: ret = -5, start->comp.id = 28, d 1

dmesg.log
logger-t.log

Test recipe:
kernel: sof-dev/2e9456 +PR #834 (to fix the HDMI/DP playback issue)
sof/tplg: master/e4c1651