[BUG] Xrun on ADP_RVP_NOCODEC

[plbossart]

Describe the bug

https://sof-ci.01.org/linuxpr/PR3338/build7261/devicetest/?model=ADLP_RVP_NOCODEC&testcase=multiple-pause-resume-5

(4/5) pcm'Port0' cmd'aplay' id'2': Wait for 22 ms before resume
                                                                           
                                                                            
 aplay: pcm_write:2086: write error: Input/output error

#+                                                 | 00%
=== PAUSE ===                                                            
(5/5) pcm'Port0 Deep Buffer' cmd'aplay' id'8': Wait for 39 ms before pause

(5/5) pcm'Port0 Deep Buffer' cmd'aplay' id'8': Wait for 47 ms before resume

2022-03-03 20:13:04 UTC [REMOTE_INFO] pipeline: Port0 with aplay
2022-03-03 20:13:04 UTC [REMOTE_INFO] pipeline: Port0 Deep Buffer with aplay
2022-03-03 20:13:04 UTC [REMOTE_INFO] Check expect exit status
declare -- cmd="journalctl_cmd --since=@1646338352"
2022-03-03 20:13:04 UTC [REMOTE_ERROR] pause resume PID 6074 had non-zero exit status
2022-03-03 20:13:04 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-03-03 20:13:04 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2022-03-03 20:13:04 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pause-resume.sh:191
2022-03-03 20:13:04 UTC [REMOTE_INFO] Starting /usr/local/bin/sof-logger -l /etc/sof/sof-adl.ldc -o /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-03-03-20:12:40-25145/etrace.txt
2022-03-03 20:13:07 UTC [REMOTE_INFO] pkill -TERM sof-logger
Terminated
2022-03-03 20:13:08 UTC [REMOTE_INFO] nlines=47 /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-03-03-20:12:40-25145/etrace.txt
2022-03-03 20:13:08 UTC [REMOTE_INFO] Test Result: FAIL!

To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-adl-nocodec.tplg MODEL=ADLP_RVP_NOCODEC ~/sof-test/test-case/multiple-pause-resume.sh -l 3 -r 5

Reproduction Rate
unclear, just observed this issue.

Expected behavior
No Xrun

Impact
showstopper.

Environment
Linux: 2528d9538dfd ASoC: SOF: sof-client: Allow the message injector for IPC4 as well
SOF: c42ede6 topology: sof-adl-max98360a-rt5682-waves: add new topology

2. Name of the topology file
   • Topology: sof-adl-nocodec.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: ADL_RVP_NOCODEC

@keqiaozhang @XiaoyunWu6666 FYI

[plbossart]

@lgirdwood this needs to be on your radar for 2.1

[marc-hb]

P1 because it was one of the most common failures in daily run 10879, reproduced on 3 ADL and 1 TGL system (10879?model=TGLH_RVP_NOCODEC_ZEPHYR&testcase=multiple-pause-resume-50)

There were a number of underruns in that test run, see example below.

[    20564241.578684] (        1349.218750) c0 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 6
[    20564268.974516] (          27.395832) c0 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 5
[    20566392.776515] (        2123.802002) c0 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[    20566552.620259] (         159.843750) c0 dai          1.2            src/audio/dai.c:879  ERROR dai_report_xrun(): underrun due to no data available
[    20566744.182751] (         191.562500) c0 dai          1.2            src/audio/dai.c:748  ERROR comp_underrun(): dev->comp.id = 2, source->avail = 756, copy_by
[    20566990.641075] (         246.458328) c0 pipe         1.3   ....../pipeline-stream.c:261  INFO pipe trigger cmd 6
[    20567028.661906] (          38.020832) c0 pipe         1.3   ....../pipeline-stream.c:134  ERROR pipeline_copy(): ret = -61, start->comp.id = 2, dir = 1
[    20567238.036898] (         209.374985) c0 pipe         1.3   ..../pipeline-schedule.c:183  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[    20567446.995223] (         208.958328) c0 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe07d0c0 pipe-task
[    20567464.807722] (          17.812500) c0 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 5 total_num_tasks 5
[    20568122.463946] (         657.656250) c0 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe07e740 pipe-task
[    20568141.266029] (          18.802082) c0 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 4 total_num_tasks 4
[    20584130.327893] (       15989.061523) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20586129.963231] (        1999.635376) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20588130.171485] (        2000.208252) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20590129.702655] (        1999.531128) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20592129.858826] (        2000.156128) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20594129.285829] (        1999.427002) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[    20596129.910750] (        2000.624878) c0 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA

I noticed a mixer in the middle of a pipeline on all failing systems. Is this an unsupported configuration and problem similar to this?

• [FEATURE] Skip PAUSE/RELEASE test on Smart Amp playback and capture pipelines sof-test#866

Should some pipelines be skipped like this?

• skip the test on Echo Reference pipeline  sof-test#871

[mengdonglin]

Comments by @keqiaozhang "this issue has affected all ADLP and TGLU/H nocodec platforms. The reproduction rate has become extremely high now. " on 2022-03-09 UTC, report ID 10879. Both XTOS and Zephyr can reproduce this issue.

[lgirdwood]

@keqiaozhang is there a bisect ? I'm trying to think of any recent pipeline or DMA changes, but it could be something else unrelated.

[kv2019i]

I now reproduced this once. Seems like the mixer is not working properly after a paused->active transition. We can see components both side of the mixer complaining that data is not moving although mixer is in active state:

[      220042.074590] (        1113.281250) c2 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 6
[      220072.439172] (          30.364582) c2 mixer        1.0      src/audio/component.c:64   INFO comp_set_state(), state already set to 5
[      222040.043260] (        1967.604126) c2 host         7.36          src/audio/host.c:475  INFO no bytes to copy, 0 free in buffer, 384 available in DMA
[      222109.470341] (          69.427078) c2 dw-dma                 src/drivers/dw/dma.c:1093 INFO dw_dma_free_data_size() size is 0!
[      222133.220340] (          23.750000) c2 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[      222154.470339] (          21.250000) c2 dai          1.2            src/audio/dai.c:879  ERROR dai_report_xrun(): underrun due to no data available