[BUG]underrun and IO error when aplay with Speaker twice on TGLH_0A5E_SDW and TGLU_SKU0A32_SDCA #5038
Description
Describe the bug
xrun and IO error happened when playing with Speaker
on TGLH_0A5E_SDW and TGLU_SKU0A32_SDCA
This issue has happened in recent daily test results since 11/26/2021 [ inner daily 8502 ]
The last safe daily testresult id is 8479
To Reproduce
Run 'aplay -Dhw:0,2 -r 48000 -c 2 -f S24_LE -d 3 /dev/zero -v -q ' twice
and it should happen at the second time
For your convenience, you can run below commands to observe the issue
for i in {1..3}; do ./sof-test/tools/kmod/sof_remove.sh ; sudo ./sof-test/tools/kmod/sof_insert.sh ; sleep 1 ; aplay -Dhw:0,2 -r 48000 -c 2 -f S24_LE -d 3 /dev/zero -v -q; aplay -Dhw:0,2 -r 48000 -c 2 -f S24_LE -d 3 /dev/zero -v -q; done
Reproduction Rate
100%
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 76583781
SOF Branch: main
SOF Commit: 3ffeb87
Zephyr Commit: f1f0dadad33c
platforms: TGLU_SKU0A32_SDCA（sof-tgl-rt711-rt1316-rt714.tplg） and TGLH_0A5E_SDW（sof-tgl-rt711-rt1308-rt715.tplg）
Topology: sof-tgl-rt711-rt1308-rt715.tplg
Screenshots or console output
Take TGLU_SKU0A32_SDCA as an example:
[dmesg]
[ 324.942186] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 0
[ 324.942203] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 325.169063] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 325.169115] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 325.443097] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)
[ 325.443114] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 325.443119] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 325.443133] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 325.443139] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 325.443155] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 325.443160] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 325.443164] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 325.443168] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware exception
[ 325.443173] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[ 325.443184] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[ 325.443551] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[ 325.443556] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 325.443577] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[ 325.443584] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 325.443593] kernel: Speaker: ASoC: trigger FE cmd: 0 failed: -110
[ 325.443629] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: trace IO error
[ 325.443631] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 2 dir 0
[ 325.443642] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 325.669066] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 325.669104] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 325.947106] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60030000 (msg/reply size: 12/12)
[ 325.947122] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware exception
[ 325.947156] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110
[ 325.950118] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 326.451146] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[ 326.451163] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware exception
[ 326.451171] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed resetting DAI config for ALH258.OUT
[ 326.451207] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 326.955164] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[ 326.955182] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware exception
[ 326.955190] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed resetting DAI config for ALH514.OUT
[sof-logger]
[ 25146177.959114] ( 18.802082) c0 ll-schedule ./schedule/ll_schedule.c:455 INFO task params pri 0 flags 0 start 0 period 1000
[ 25146203.115363] ( 25.156248) c0 ll-schedule ./schedule/ll_schedule.c:357 INFO new added task->start 487172566 at 487151086
[ 25146221.917446] ( 18.802082) c0 ll-schedule ./schedule/ll_schedule.c:360 INFO num_tasks 4 total_num_tasks 4
[ 25147407.438232] ( 1185.520752) c0 demux 3.14 src/audio/mux/mux.c:701 INFO mux_trigger(), command = 9
[ 25147434.625731] ( 27.187498) c0 alh-dai 4.258 src/drivers/intel/alh.c:29 INFO alh_trigger() cmd 9
[ 25147456.604897] ( 21.979166) c0 alh-dai 4.514 src/drivers/intel/alh.c:29 INFO alh_trigger() cmd 9
[ 25147494.729895] ( 38.125000) c0 demux 3.14 src/audio/mux/mux.c:701 INFO mux_trigger(), command = 1
[ 25147525.511144] ( 30.781248) c0 alh-dai 4.258 src/drivers/intel/alh.c:29 INFO alh_trigger() cmd 1
[ 25147557.073643] ( 31.562498) c0 alh-dai 4.514 src/drivers/intel/alh.c:29 INFO alh_trigger() cmd 1
[ 25149699.156891] ( 2142.083252) c0 ll-schedule ./schedule/ll_schedule.c:142 INFO task complete 0xbe1d0180 pipe-task
[ 25149717.281890] ( 18.125000) c0 ll-schedule ./schedule/ll_schedule.c:145 INFO num_tasks 3 total_num_tasks 3
[ 25157447.906583] ( 7730.624512) c0 dai 3.18 src/audio/dai.c:951 WARN dai_copy(): nothing to copy
[ 25159445.979420] ( 1998.072876) c0 dai 3.18 src/audio/dai.c:951 WARN dai_copy(): nothing to copy
[ 25161403.375176] ( 1957.395752) c0 host 3.12 src/audio/host.c:464 INFO no bytes to copy, 0 free in buffer, 768 available in DMA
[ 25161453.896007] ( 50.520832) c0 dai 3.18 src/audio/dai.c:943 WARN dai_copy(): Copy_bytes 0 + avail bytes 128 < period bytes 384, possible glitch
[ 25161471.864756] ( 17.968750) c0 dai 3.18 src/audio/dai.c:951 WARN dai_copy(): nothing to copy
[ 25163405.666763] ( 1933.802002) c0 host 3.12 src/audio/host.c:464 INFO no bytes to copy, 0 free in buffer, 768 available in DMA
**[ 25163459.104261] ( 53.437496) c0 dw-dma src/drivers/dw/dma.c:1143 ERROR dw_dma_get_data_size(): xrun detected
[ 25163482.073010] ( 22.968750) c0 dai 3.18 src/audio/dai.c:881 ERROR dai_report_xrun(): underrun due to no data available
[ 25163503.479259] ( 21.406250) c0 dai 3.18 src/audio/dai.c:732 ERROR comp_underrun(): dev->comp.id = 18, source->avail = 0, copy_bytes = 0
[ 25163520.145925] ( 16.666666) c0 pipe 3.19 ....../pipeline-stream.c:261 INFO pipe trigger cmd 8
[ 25163564.729256] ( 44.583332) c0 pipe 3.19 ....../pipeline-stream.c:134 ERROR pipeline_copy(): ret = -61, start->comp.id = 18, dir = 1
[ 25163586.552172] ( 21.822916) c0 pipe 3.19 ..../pipeline-schedule.c:180 ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.**
[ 25163605.979255] ( 19.427082) c0 ll-schedule ./schedule/ll_schedule.c:142 INFO task complete 0xbe1d0140 pipe-task
[ 25163623.479254] ( 17.500000) c0 ll-schedule ./schedule/ll_schedule.c:145 INFO num_tasks 2 total_num_tasks 2
[ 28599601.155221] ( 3435977.750000) c0 ipc src/ipc/ipc3/handler.c:1576 INFO ipc: new cmd 0x60050000
[ 28599634.280219] ( 33.125000) c0 pipe 3.19 ....../pipeline-stream.c:261 INFO pipe trigger cmd 0