[BUG][SDW]Switch foreground from background on aplay 0,0 will cause I/O error when do headset playback and headset at the same time

[YvonneYang2]

Describe the bug
aplay 0,0/2/3 + arecord 0,4--> ctrl+z and fg on arecord 0,4 --> I/O error
arecord 0,1 and arecord 0,4 --> pause/release --> I/O error
arecord 0,1 + aplay 0,0/2/3 aplay --> I/O error

error log seems same as thesofproject/sof#1578

To Reproduce
1.open terminal A to run command "time aplay -Dhw:0,0 -f dat wav/48California_Dreaming.wav -vv -i"
2.open another terminal B to run command "arecord -Dhw:0,4 -r 48000 -c2 -f s32_le test.wav -vv -i"
3.Ctrl+Z to background arecord in terminal B, then fg to foreground.

frequency
100%

Expected result
Aplay and arecord work normally.

Actual result
aplay and arecord stop, and shows I/O error.

Environment
Firmware: c7d0149 https://github.com/thesofproject/sof/commits/master
Kernel: e7fb5a5 https://github.com/thesofproject/linux/tree/integration/soundwire-latest
tplg: sof-icl-rt711-rt1308-rt715-hdmi.tplg rename sof-icl-rt711-rt1308-rt715.tplg path same as FW branch
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 5.28    318102259.270833 318102272.000000      src/audio/dai.c:593 	dai_check_for_xrun() error: overrun due to no data available
    0      1         COMP         318102269.062500         9.791667 of/audio/component.h:759 	comp_overrun() error: dev->comp.id = 28, sink->free = 768, copy_bytes = 0
    0      1         PIPE         318102334.427083        65.364586 src/audio/pipeline.c:854 	pipeline_copy() error: ret = -61, start->comp.id = 28, dir = 0
    0      1         PIPE 5.29    318102346.093750        11.666667 src/audio/pipeline.c:1037	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1         COMP         319120822.656250   1018476.562500 rc/audio/component.c:192 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_RESET

fg_error_logger.log
fg_logger.log
fg_dmesg.log

[plbossart]

No, the patch ASoC: SOF: Intel: hda: Disable DMI L1 entry during capture is absolutely in integration/soundwire-latest. You must have a bad configuration or a different bug appeared. Please recheck, thanks.

[bardliao]

@YvonneYang2 I can't reproduce the issue with the same kernel and FW as yours.

[YvonneYang2]

Issue is caused by commit 71d9ee4(master branch)

@tlauda Could you have a look? Thanks a lot.

[tlauda]

Please provide full FW logs. Current log file is empty.

[YvonneYang2]

Aplay 0,0 + arecord 0,4 --> ctrl+z and fg on arecord 0,4 --> I/O error

All logs is as below:
logger_error.log
dmesg.log
logger.log

[tlauda]

@YvonneYang2 Normal log is still empty. I don't want to be rude, but could you actually check the content before upload?

[YvonneYang2]

Aplay 0,0 + arecord 0,4 --> ctrl+z and fg on arecord 0,4 --> I/O error

Sorry, I cannot catch the sof error log and normal log at the same time because of the sof-logger bug. So upload the all logs I can catch.

all_logger.log
dmesg.log

[plbossart]

Confirmed on my side even without all the Ctrl-z. As soon as record starts on terminal B, playback stops on terminal A, and I also see an error on terminal B

terminal A:

root@jf-icl-rvp-hda-8:~# speaker-test -Dhw:0,0 -c2 -r48000

speaker-test 1.1.3

Playback device is hw:0,0
Stream parameters are 48000Hz, S16_LE, 2 channels
Using 16 octaves of pink noise
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 96 to 16368
Period size range from 48 to 4080
Using max buffer size 16368
Periods = 4
was set period_size = 3312
was set buffer_size = 16368
 0 - Front Left
 1 - Front Right
Time per period = 5.592194
 0 - Front Left
 1 - Front Right
Time per period = 5.934904
 0 - Front Left
 1 - Front Right
Time per period = 5.999813
 0 - Front Left
 1 - Front Right
Time per period = 5.866118
 0 - Front Left
 1 - Front Right
Time per period = 5.999929
 0 - Front Left
 1 - Front Right
Write error: -5,Input/output error
xrun_recovery failed: -5,Input/output error
Transfer failed: Input/output error
root@jf-icl-rvp-hda-8:~# 

terminal B:

root@jf-icl-rvp-hda-8:~# arecord -Dhw:0,4 -c2 -r48000 -fdat
Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
RIFF$�WAVEfmt ���data�arecord: pcm_read:2103: read error: Input/output error
root@jf-icl-rvp-hda-8:~# 

dmesg_arecord.log

arecord_logger.txt

[plbossart]

I double-checked that aplay/arecord work separately, it's when either is started while the other is already streaming that we see IPC issues

console log:

root@jf-icl-rvp-hda-8:~# dmesg -C
root@jf-icl-rvp-hda-8:~# modprobe snd-sof-pci
root@jf-icl-rvp-hda-8:~# speaker-test -Dhw:0,0 -c2 -r48000

speaker-test 1.1.3

Playback device is hw:0,0
Stream parameters are 48000Hz, S16_LE, 2 channels
Using 16 octaves of pink noise
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 96 to 16368
Period size range from 48 to 4080
Using max buffer size 16368
Periods = 4
was set period_size = 3312
was set buffer_size = 16368
 0 - Front Left
 1 - Front Right
Time per period = 5.592017
 0 - Front Left
 1 - Front Right
^CTime per period = 3.673565
root@jf-icl-rvp-hda-8:~# 
root@jf-icl-rvp-hda-8:~# 
root@jf-icl-rvp-hda-8:~# 
root@jf-icl-rvp-hda-8:~# arecord -Dhw:0,4 -r48000 -c2 -f dat 
Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
RIFF$�WAVEfmt ���data�^CAborted by signal Interrupt...
root@jf-icl-rvp-hda-8:~# speaker-test -Dhw:0,0 -c2 -r48000

speaker-test 1.1.3

Playback device is hw:0,0
Stream parameters are 48000Hz, S16_LE, 2 channels
Using 16 octaves of pink noise
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 96 to 16368
Period size range from 48 to 4080
Using max buffer size 16368
Periods = 4
was set period_size = 3312
was set buffer_size = 16368
 0 - Front Left
 1 - Front Right
Time per period = 5.592182
 0 - Front Left
^C 1 - Front Right
Time per period = 0.079813
root@jf-icl-rvp-hda-8:~# arecord -Dhw:0,4 -r48000 -c2 -f dat 
Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
RIFF$�WAVEfmt ���data�arecord: pcm_read:2103: read error: Input/output error
root@jf-icl-rvp-hda-8:~# dmesg > dmesg_arecord.log

dmesg_arecord.log

icl-logger.txt

[plbossart]

Solved for me by thesofproject/sof#1935

@YvonneYang2 please double-check.

[tlauda]

@YvonneYang2 Could you check if master + thesofproject/sof#1935 + thesofproject/sof#1946 + #1277 fixes this and other recent SDW issues?

Edit: Actually thesofproject/sof#1935 + linux#1277 should be enough for this particular problem, but thesofproject/sof#1946 improves it even more, due to the steady processing periods. Seems that ALSA has a problem, when we process too fast.

[YvonneYang2]

Only test it with master + thesofproject/sof#1935 + #1277 since has conflicts when merge thesofproject/sof#1946. Issue cannot reproduce on icl 3-in1 rvp.

[YvonneYang2]

Test it with latest master (#1935 and thesofproject/sof#1946 have been merged) and integration/soundwire-latest (29debf8) + PR1277, issue hasn't been all fixed.
Aplay 0,0 +Arecord 0,1 --> background and foreground on arecord 0,1 --> I/O error

Logs:
logger.log
dmesg.log

[YvonneYang2]

Check it with test recipe as below (linux#1277 has been merged) , below scenario can still reproduce the issue.

Aplay 0,0 +Arecord 0,1 --> background and foreground on aplay 0,0 --> I/O error

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 7c85d69
FW: https://github.com/thesofproject/sof/commits/master commit: 8b059f6
tplg: Same with FW branch, sof-icl-rt711-rt1308-rt715-hdmi.tplg rename to sof-icl-rt711-rt1308-rt715.tplg
platform: ICL RVP, with codec ALC711 -RT1308, RT715 in SDW mode

logs:
dmesg.log
logger.log