[BUG] I/O error when testing multiple pause/resume, XRUN nothing to copy

[keqiaozhang]

Describe the bug
Observed this issue in CI tests, it happens on ADL/TGL IPC4 platform. But there're no errors in dmesg or mtrace. The reproduce rate is about 50%.

To Reproduce
~/sof-test/test-case/multiple-pause-resume.sh -r 50

Reproduction Rate
50%

mtrace

[  111.337111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.337125] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.338111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.338146] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.339111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.339133] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.340113] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.340128] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.341111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.341146] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.342111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.342133] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy
[  111.343111] <err> dma_dw_common: dw_dma_get_status: xrun detected
[  111.343125] <wrn> dai_comp: dai_common_copy: comp:1 0x40001 dai_zephyr_copy(): nothing to copy

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).

   • Kernel: {17b5d3eee2c6}
   • SOF: {1dd1939f05ef}

2. Name of the platform(s) on which the bug is observed.

   • Platform:TGLU_UP_HDA_IPC4ZPH TGLU_RVP_SDW_IPC4ZPH ADLP_SKU0B00_SDCA_IPC4ZPH

Screenshots or console output

#+                                                 | 00%
(49/50) pcm'HDMI3' cmd'aplay' id'2': Wait for 43 ms before pause

=== PAUSE ===                                                             
(49/50) pcm'HDMI3' cmd'aplay' id'2': Wait for 25 ms before resume
                                                                           

#+                                                 | 00%
(50/50) pcm'HDMI3' cmd'aplay' id'2': Wait for 25 ms before pause
 
#+                                                 | 00%
(50/50) pcm'HDMI3' cmd'aplay' id'2': Wait for 29 ms before pause

=== PAUSE ===                                                             
(50/50) pcm'HDMI3' cmd'aplay' id'2': Wait for 22 ms before resume

2023-06-05 22:45:44 UTC [REMOTE_INFO] pipeline: HDMI1 with aplay
2023-06-05 22:45:44 UTC [REMOTE_INFO] pipeline: HDMI3 with aplay
2023-06-05 22:45:44 UTC [REMOTE_INFO] Check expect exit status
declare -- cmd="journalctl_cmd --since=@1686005122"
2023-06-05 22:45:45 UTC [REMOTE_ERROR] pause resume PID 37566 had non-zero exit status
2023-06-05 22:45:45 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2023-06-05 22:45:45 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2023-06-05 22:45:45 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pause-resume.sh:191
2023-06-05 22:45:46 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2023-06-05 22:45:46 UTC [REMOTE_INFO] ktime=4293 sof-test PID=36343: ending
2023-06-05 22:45:46 UTC [REMOTE_INFO] Test Result: FAIL!

dmesg.txt

mtrace.txt

[fredoh9]

For today, TGLU_RVP_SDW_IPC4ZPH and TGLU_RVP_SDW_IPC4ZPH reproduced this issue. Truely P1.
Intel internal daily test: planresultdetail/28251

[marc-hb]

Still happening with a very high reproduction rate, I see it in about 1/2 or 1/3 of the test results I look at. For instance this one: https://sof-ci.01.org/sofpr/PR7878/build10245/devicetest

[fredoh9]

This is not 100% but It happens with really high reproduction rate, almost daily