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

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

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: {17b5d3eee2c6}
- SOF: {1dd1939f05ef}
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

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

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

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

Reproduced this locally, debug ongoing.

@bardliao

Even simpler test case to cause the fail (with sof-tgl-rt711-4ch.tplg):

bug7759.sh

--cut--
set -x
arecord -Dplughw:0,1 -r48000 -c2 -fS16_LE -i /dev/null -d15 || echo arecord failed with $? &
aplay -Dplughw:0,0 -d2 -r48000 -c2 -fS16_LE -traw /dev/zero
sleep 3
--cut--

Output when running with sof-tgl-rt711-4ch.tplg:

$ ./bug7759.sh
++ aplay -Dplughw:0,0 -d2 -r48000 -c2 -fS16_LE -traw /dev/zero
++ arecord -Dplughw:0,1 -r48000 -c2 -fS16_LE -i /dev/null -d15
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Recording WAVE '/dev/null' : StereoSigned 16 bit Little Endian, 
Rate 48000 Hz, Stereo
++ sleep 3
arecord: pcm_read:2153: read error: Input/output error
++ echo arecord failed with 1
arecord failed with 1

@bardliao @plbossart do you see the same? It seems just stopping playback to codec will kill capture.

Some bisect testing:

test with IPC3 (same kernel version) and SOF2.2 -> error not seen, so kernel soundwire stack seems fine
test IPC4 and SOF2.6.1 -> error not seen!

Will try to do a bisect next based on the SOF FW version.

Bisected to Zephyr update in commit bf6ae6d . Will proceed to bisect the change on Zephyr side.

@kv2019i

@kv2019i is this a TGL-only issue? I can't reproduce the problem on MTL

ubuntu@jf-mtlp-rvp-sdw-2:~$ bash bug7759.sh 
+ aplay -Dplughw:0,0 -d2 -r48000 -c2 -fS16_LE -traw /dev/zero
+ arecord -Dplughw:0,1 -r48000 -c2 -fS16_LE -i /dev/null -d15
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Recording WAVE '/dev/null' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
+ sleep 3

[ 66.398274] sof-audio-pci-intel-mtl 0000:00:1f.3: Booted firmware version: 2.6.99.1

I can reproduce this on ADL - looks like a cAVS 2.5 issue then?

@plbossart

@plbossart Now found the rootcause and have a fix in review. The problem is in code common to all Intel platforms, but for some reason this has triggered only on cAVS2.5 platforms. This is related to configuring SDW I/O pin ownership -> explains why data flow stopped when one ALH stream was closed.

Let's see if the fix passes testing.

drivers: dai: alh: fix refcount logic for ALH ownership

@keqiaozhang

@keqiaozhang @fredoh9 Should be fixed via #8085 now. I've done two test runs with the fix included and both were fine. But please check and close if good.

Confirmed that this issue has been fixed by #8085. Closing this bug.

drivers: dai: alh: fix refcount logic for ALH ownership

Navigation Menu

Repository navigation

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

9 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

fredoh9 commented on Jun 27, 2023

marc-hb commented on Jun 29, 2023

fredoh9 commented on Jul 25, 2023

kv2019i commented on Aug 9, 2023

9 remaining items

kv2019i commented on Aug 17, 2023

kv2019i commented on Aug 17, 2023

kv2019i commented on Aug 17, 2023

plbossart commented on Aug 17, 2023

plbossart commented on Aug 17, 2023

kv2019i commented on Aug 18, 2023

kv2019i commented on Aug 23, 2023

keqiaozhang commented on Aug 25, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions