[BUG][SDW]Arecord shows I/O error after pause and resume.

[YvonneYang2]

Describe the bug
Headset arecord will show I/O error after resume from paused status when pulseaudio is on. Trigger arecord again can recover the issue

To Reproduce
1.Make sure pulseaudio is on
2.Arecord -Dhw:0,1 -r48000 -c2 -fs32_le 1.wav -vv -i
3.Do pause and resume, then wait for 5-10s

frequency
100%

Expected result
Arecord normally after resume

Actual result
Arecord stop and shows IO error after resume.

Environment
Firmware: 0223d94 https://github.com/thesofproject/sof/commits/sdw-001-drop-stable
+PR thesofproject/sof#1781
Kernel: a8f3408 https://github.com/thesofproject/linux/commits/integration/soundwire-alpha
Topology: file: same with firmware branch, sof-icl-rt700.m4
platform: ICL RVP with onboard ALC700 in SDW mode

logger

   0      2          DAI 4.18    225837154.010417         6.822917      src/audio/dai.c:728 	dai_config, config->dmic.pdm[0].enable_mic_a = 1; 
    0      2          DAI 4.18    225837160.416667         6.406250      src/audio/dai.c:732 	dai_config, config->dmic.pdm[0].enable_mic_b = 1; 
    0      2          DAI 4.18    225837166.927083         6.510417      src/audio/dai.c:748 	dai_config(), dd->frame_bytes = 4
    0      2          DMA         225837173.802083         6.875000 src/drivers/dw/dma.c:202 	dw_dma_channel_get(): dma 1 request channel 0
    0      2          IPC         225838086.041667       912.239563    src/ipc/handler.c:985 	ipc: pipe 19 -> complete
    0      2         PIPE 4.19    225838122.135417        36.093750 src/audio/pipeline.c:159 	pipeline_complete()
    0      2          MEM         225838131.250000         9.114583      src/lib/alloc.c:915 	heap: buffer status
    0      2          MEM         225838138.281250         7.031250      src/lib/alloc.c:886 	 heap: 0xbe07e000 size 61440 blocks 1 caps 0x45
    0      2          MEM         225838144.583333         6.302083      src/lib/alloc.c:888 	  used 0 free 61440
    0      2          MEM         225838151.145833         6.562500      src/lib/alloc.c:886 	 heap: 0xbe00c000 size 131072 blocks 1 caps 0x71
    0      2          MEM         225838157.187500         6.041667      src/lib/alloc.c:888 	  used 13440 free 117632
    0      2          MEM         225838164.010417         6.822917      src/lib/alloc.c:886 	 heap: 0xbe812000 size -61440 blocks 1 caps 0x69
    0      2          MEM         225838170.052083         6.041667      src/lib/alloc.c:888 	  used 0 free -61440
    0      2          MEM         225838176.875000         6.822917      src/lib/alloc.c:917 	heap: runtime status
    0      2          MEM         225838183.541667         6.666667      src/lib/alloc.c:886 	 heap: 0xbe070000 size 57344 blocks 5 caps 0x45
    0      2          MEM         225838189.687500         6.145833      src/lib/alloc.c:888 	  used 7680 free 49664
    0      2          MEM         225838196.510417         6.822917      src/lib/alloc.c:899 	  block 1 base 0xbe072000 size 128
    0      2          MEM         225838202.968750         6.458333      src/lib/alloc.c:902 	   count 64 free 54
    0      2          MEM         225838209.895833         6.927083      src/lib/alloc.c:899 	  block 2 base 0xbe074000 size 256
    0      2          MEM         225838216.250000         6.354167      src/lib/alloc.c:902 	   count 128 free 108
    0      2          MEM         225838222.916667         6.666667      src/lib/alloc.c:899 	  block 3 base 0xbe07c000 size 512
    0      2          MEM         225838229.479167         6.562500      src/lib/alloc.c:902 	   count 8 free 8
    0      2          MEM         225838236.093750         6.614583      src/lib/alloc.c:899 	  block 4 base 0xbe07d000 size 1024
    0      2          MEM         225838242.708333         6.614583      src/lib/alloc.c:902 	   count 4 free 4
    0      2          IPC         225838678.385417       435.677094    src/ipc/handler.c:985 	ipc: pipe 15 -> complete
    0      2         PIPE 3.15    225838707.447917        29.062500 src/audio/pipeline.c:159 	pipeline_complete()
    0      2          IPC         225839213.385417       505.937500    src/ipc/handler.c:985 	ipc: pipe 11 -> complete
    0      2         PIPE 2.11    225839235.885417        22.500000 src/audio/pipeline.c:159 	pipeline_complete()
    0      2          IPC         225839769.010417       533.125000    src/ipc/handler.c:985 	ipc: pipe 5 -> complete
    0      2         PIPE 1.5     225839784.062500        15.052083 src/audio/pipeline.c:159 	pipeline_complete()
    0      2          IPC         225840546.614583       762.552063    src/ipc/handler.c:837 	ipc: hdr 0x50010000 tx (108) > rx (92)
    0      2          IPC         225840553.906250         7.291667    src/ipc/handler.c:839 	ipc: comp 7 -> cmd 0
    0      2       VOLUME         225840565.625000        11.718750 udio/volume/volume.c:511 	volume_cmd()
    0      2       VOLUME         225840573.437500         7.812500 udio/volume/volume.c:396 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, cdata->comp_id = 7
    0      2       VOLUME         225840580.572917         7.135417 udio/volume/volume.c:402 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, channel = 0, value = 146723
    0      2       VOLUME         225840588.125000         7.552083 udio/volume/volume.c:402 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, channel = 1, value = 146723
    0      2          IPC         225841460.468750       872.343750    src/ipc/handler.c:837 	ipc: hdr 0x50010000 tx (108) > rx (92)
    0      2          IPC         225841467.968750         7.500000    src/ipc/handler.c:839 	ipc: comp 1 -> cmd 0
    0      2       VOLUME         225841476.354167         8.385417 udio/volume/volume.c:511 	volume_cmd()
    0      2       VOLUME         225841483.645833         7.291667 udio/volume/volume.c:396 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, cdata->comp_id = 1
    0      2       VOLUME         225841490.625000         6.979167 udio/volume/volume.c:402 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, channel = 0, value = 65536
    0      2       VOLUME         225841498.385417         7.760417 udio/volume/volume.c:402 	volume_ctrl_set_cmd(), SOF_CTRL_CMD_VOLUME, channel = 1, value = 65536
    0      2          IPC         225842798.229167      1299.843750    src/ipc/handler.c:630 	ipc: pm -> restore
    0      2          IPC         225907635.885417     64837.656250    src/ipc/handler.c:530 	ipc: dai 4,2 -> config 
    0      2          DAI         225907644.687500         8.802083        src/lib/dai.c:70  	dai_get(), d = 0xbe066728, sref = 2
    0      2          ALH         225907651.927083         7.239583 ers/intel/cavs/alh.c:32  	alh_set_config() config->format = 0x   0
    0      2          DAI         225907659.270833         7.343750        src/lib/dai.c:95  	dai_put(), dai = 0xbe066728, sref = 1
    0      2          DAI         225907669.843750        10.572917      src/audio/dai.c:685 	config comp 4 pipe 1 dai 2 type 4
    0      2          DAI 1.4     225907676.979167         7.135417      src/audio/dai.c:790 	dai_config(), channel = 7
    0      2          IPC         225908653.125000       976.145813    src/ipc/handler.c:223 	ipc: comp 0 -> params
    0      2         PIPE 1.5     225908662.500000         9.375000 src/audio/pipeline.c:329 	pipeline_params()
    0      2         HOST 1.0     225908671.041667         8.541667     src/audio/host.c:566 	host_params()
    0      2          DMA         225908700.052083        29.010416 intel/cavs/hda-dma.c:463 	hda-dmac: 5 channel 0 -> get
    0      2          DMA         225908709.166667         9.114583 intel/cavs/hda-dma.c:688 	hda-dmac: 5 channel 0 -> config
    0      2       VOLUME         225908720.729167        11.562500 udio/volume/volume.c:244 	volume_params()
    0      2          DAI 1.4     225908730.052083         9.322917      src/audio/dai.c:385 	dai_params()
    0      2          DAI 1.4     225908739.322917         9.270833      src/audio/dai.c:254 	dai_playback_params() dest_dev = 22 stream_id = 7 src_width = 4 dest_width = 4
    0      2          DAI 1.4     225908746.510417         7.187500      src/audio/dai.c:280 	dai_playback_params() fifo 7141C
    0      2         PIPE 1.5     225908760.000000        13.489583 src/audio/pipeline.c:393 	pipeline_prepare()
    0      2         HOST 1.0     225908767.500000         7.500000     src/audio/host.c:705 	host_prepare()
    0      2       VOLUME         225908777.604167        10.104167 udio/volume/volume.c:589 	volume_prepare()
    0      2          DAI 1.4     225908790.572917        12.968750      src/audio/dai.c:449 	dai_prepare()
    0      2          IPC         225918823.802083     10033.229492    src/ipc/handler.c:452 	ipc: comp 0 -> trigger cmd 0x40000
    0      2         PIPE 1.5     225918833.177083         9.375000 src/audio/pipeline.c:622 	pipeline_trigger()
    0      2         HOST 1.0     225918841.145833         7.968750     src/audio/host.c:323 	host_trigger()
    0      2          DMA         225918849.322917         8.177083 intel/cavs/hda-dma.c:532 	hda-dmac: 5 channel 0 -> start
    0      2          DMA         225918857.239583         7.916667 intel/cavs/hda-dma.c:354 	hda-dmac: 5 channel 0 -> enable
    0      2       VOLUME         225918921.979167        64.739586 udio/volume/volume.c:531 	volume_trigger()
    0      2          DAI 1.4     225918930.468750         8.489583      src/audio/dai.c:512 	dai_comp_trigger(), command = 1
    0      2          DAI 1.4     225918937.968750         7.500000      src/audio/dai.c:523 	dai_comp_trigger(), START
    0      2          ALH         225919133.854167       195.885422 ers/intel/cavs/alh.c:24  	alh_trigger() cmd 1
    0      2          IPC         238243685.885417  12324552.000000    src/ipc/handler.c:452 	ipc: comp 0 -> trigger cmd 0x50000
    0      2         PIPE 1.5     238243695.208333         9.322917 src/audio/pipeline.c:622 	pipeline_trigger()
    0      2         HOST 1.0     238243703.229167         8.020833     src/audio/host.c:323 	host_trigger()
    0      2          DMA         238243711.302083         8.072917 intel/cavs/hda-dma.c:627 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME         238243719.843750         8.541667 udio/volume/volume.c:531 	volume_trigger()
    0      2          DAI 1.4     238243727.968750         8.125000      src/audio/dai.c:512 	dai_comp_trigger(), command = 0
    0      2          DAI 1.4     238243735.260417         7.291667      src/audio/dai.c:576 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA         238243742.552083         7.291667 src/drivers/dw/dma.c:465 	dw_dma_stop(): dma 0 channel 0 stop
    0      2          ALH         238243767.656250        25.104166 ers/intel/cavs/alh.c:24  	alh_trigger() cmd 0
    0      2          IPC         238244156.875000       389.218750    src/ipc/handler.c:341 	ipc: comp 0 -> free
    0      2         PIPE 1.5     238244165.572917         8.697917 src/audio/pipeline.c:701 	pipeline_reset()
    0      2         HOST 1.0     238244173.385417         7.812500     src/audio/host.c:750 	host_reset()
    0      2       VOLUME         238244188.489583        15.104167 udio/volume/volume.c:675 	volume_reset()
    0      2          DAI 1.4     238244196.614583         8.125000      src/audio/dai.c:490 	dai_reset()
    0      2          IPC         238253656.510417      9459.895508    src/ipc/handler.c:530 	ipc: dai 4,2 -> config 
    0      2          DAI         238253664.739583         8.229167        src/lib/dai.c:70  	dai_get(), d = 0xbe066728, sref = 2
    0      2          ALH         238253671.927083         7.187500 ers/intel/cavs/alh.c:32  	alh_set_config() config->format = 0x   0
    0      2          DAI         238253679.218750         7.291667        src/lib/dai.c:95  	dai_put(), dai = 0xbe066728, sref = 1

headset_arecord_pause_release_PAon_IOerror_dmesg.log
headset_arecord_pause_release_PAon_IOerror_logger.log

[YvonneYang2]

DMIC32(-Dhw0,2) arecord still can reproduce the issue.

[plbossart]

please recheck with recent firmware/kernel. what happened 19 days ago is history.

[plbossart]

please retest with firmware master and kernel integration/soundwire-latest branch

[YvonneYang2]

Whether pulseaudio is on or off, issue can be reproduced with test recipe as below.

Test recipe:
Firmware: 460c41a https://github.com/thesofproject/sof/commits/master
Kernel: 4ac5440 https://github.com/thesofproject/linux/tree/integration/soundwire-latest
tplg: sof-icl-rt711-rt1308-rt715-hdmi.tplg rename sof-icl-rt711-rt1308-rt715.tplg https://github.com/bardliao/sof/blob/fix/soundwire-tplg/tools/topology/
platform: ICL RVP, with codec ALC711 -RT1308, RT715 in SDW mode

error logger

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          DAI 2.10    262603245.572917 262603248.000000      src/audio/dai.c:609 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         262603255.260417         9.687500 of/audio/component.h:758 	comp_overrun() error: dev->comp.id = 10, sink->free = 768, copy_bytes = 0
    0      1         PIPE         262603334.531250        79.270836 src/audio/pipeline.c:801 	pipeline_copy() error: ret = -61, start->comp.id = 10, dir = 0
    0      1         PIPE 2.11    262603346.250000        11.718750 src/audio/pipeline.c:977 	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1         COMP         266002033.489583   3398687.250000 rc/audio/component.c:192 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_RESET

error_logger.log
logger.log
dmesg.log

[plbossart]

ACK, behavior reproduced.
Also doing this with aplay doesn't seem to work.

@bardliao can you look into this? I am not sure it's related to the hw_params/free issue and the unbalanced bandwidth calculation.

[bardliao]

ACK, behavior reproduced.
Also doing this with aplay doesn't seem to work.

@bardliao can you look into this? I am not sure it's related to the hw_params/free issue and the unbalanced bandwidth calculation.

Sure, I will look into it.

[bardliao]

@YvonneYang2 Sorry, I can't reproduce the issue with the same kernel and sof commit on my side.

[YvonneYang2]

Issue can reproduce on ICL RT700 RVP in SDW mode with test recipe below when do arecord via command "arecord -Dhw:0,2 -r48000 -c4 -fs32_le test.wav -vv -i"

Test recipe:
set "options snd_sof_pci sof_debug=1" in /etc/modprobe.d/alsa-base.conf
Firmware: 460c41a https://github.com/thesofproject/sof/commits/master
Kernel: 4ac5440 https://github.com/thesofproject/linux/tree/integration/soundwire-latest
tplg: sof-icl-rt711-rt1308-rt715-hdmi.tplg rename sof-icl-rt711-rt1308-rt715.tplg https://github.com/bardliao/sof/blob/fix/soundwire-tplg/tools/topology/
platform: ICL RT700 RVP in SDW mode

error logger

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1       VOLUME         817914108.020833 817914112.000000 udio/volume/volume.c:274 	volume_set_chan: Limited request 0 to VOL_MIN.
    0      1       VOLUME         817915070.104167       962.083313 udio/volume/volume.c:274 	volume_set_chan: Limited request 0 to VOL_MIN.
    0      1       VOLUME         817915087.187500        17.083334 udio/volume/volume.c:274 	volume_set_chan: Limited request 0 to VOL_MIN.
    0      1       VOLUME         820021065.520833   2105978.250000 udio/volume/volume.c:274 	volume_set_chan: Limited request 0 to VOL_MIN.
    0      1          DAI 3.14    1222608655.572917 402587584.000000      src/audio/dai.c:609 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         1222608665.104167         9.531250 of/audio/component.h:758 	comp_overrun() error: dev->comp.id = 14, sink->free = 1536, copy_bytes = 0
    0      1         PIPE         1222608760.312500        95.208336 src/audio/pipeline.c:801 	pipeline_copy() error: ret = -61, start->comp.id = 14, dir = 0
    0      1         PIPE 3.15    1222608772.291667        11.979167 src/audio/pipeline.c:977 	pipeline_task(): xrun recover failed! pipeline will be stopped!

error_logger.log
logger.log
dmesg.log

[YvonneYang2]

@YvonneYang2 Sorry, I can't reproduce the issue on my side with the same kernel and sof commit on my side.

On ICL RT700, only DMIC01, 4CH can reproduce the issue.
On ICL RVP, with codec ALC711 -RT1308, RT715 in SDW mode, both 2CH and 4CH can reproduce the issue.