[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

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

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.

@YvonneYang2

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

@tlauda

Issue is caused by commit 71d9ee4(master branch)

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

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

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

@YvonneYang2

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

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

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

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

@YvonneYang2

Solved for me by thesofproject/sof#1935

@YvonneYang2 please double-check.

@YvonneYang2

@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.

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.

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

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

@slawblauciak

@slawblauciak I haven't had time to drill down further. I still think it's a kernel bug with the wrong data port settings applied, that's the only rational explanation for the bus clash
I plan to try with fixed settings, e.g. initialize all ports on startup and just play with enable/disable to confirm my theory.
It's a difficult one to debug indeed.

@slawblauciak

@slawblauciak @tlauda @bardliao I have traced and double checked all ports, alternate banks and can't find a bad configuration or smoking gun.

At this point my hypotheses as to what the root cause might be:

a) a misunderstanding on what happens in the hw_free case. the configuration I end-up sending is this

	memset(&config, 0, size);
	config.hdr.size = size;
	config.hdr.cmd = SOF_IPC_GLB_DAI_MSG | SOF_IPC_DAI_CONFIG;
	config.type = SOF_DAI_INTEL_ALH;
	config.dai_index = (link_id << 8) | d->id;
	config.alh.stream_id = 0xFFFF; /* invalid value on purpose */

When I look at the firmware code, it's unclear to me if this value is used for anything? alh_get_handshake() and alh_get_fifo don't really perform any reset and for the get_fifo case there's not even a range check. Likewise in dai.c it's not clear to me that the value 0xFFFF is actually used

		/* As with HDA, the DMA channel is assigned in runtime,
		 * not during topology parsing.
		 */
		channel = config->alh.stream_id;
		dd->stream_id = config->alh.stream_id;

b) Currently we release this ALH stream only when there is a hw_free. But in the case of the underflow, the hw_free is not called, so the ALH configuration is not reset. This could maybe be an issue for your DMA management?

c) a problem with ALH/SHIM registers. Currently the host sets up the values on resume, and we never modify the settings. Maybe we have to disable the ALH mappings on TRIGGER_STOP? I didn't see such a requirement but that could very well be a miss in the programming sequence.

Comments welcome.

Latest trace attached for reference. No trace of problems with port configurations.

dmesg7.log

@tlauda

@tlauda @slawblauciak @bardliao :

I got it. This was option c).

the following change in intel_prepare() fixes this specific issue

#if 0
	intel_pdi_shim_configure(sdw, sdw->pdi);
	intel_pdi_alh_configure(sdw, sdw->pdi);
	sdw_cdns_config_stream(cdns, ch, dir, sdw->pdi);

	/* Inform DSP about PDI stream number */
	ret = intel_params_stream(sdw, substream, dai, sdw->hw_params,
				  sdw->instance,
				  sdw->pdi->intel_alh_id);
	if (ret)
		goto err;
#endif

This was added to make sure that on resume, where all context was lost, we reconfigure ALH/SHIM/firmware.

But when intel_prepare() is called because of an underflow, with a running stream, then this violates one of the explicit requirements in the cAVS Programming reference.

eg for STRMxCFG.CHAN and STRMxCFG.DMAT: The value should be programmed before enabling the Audio Link Hub stream transfer by setting PTEN or GPDMA / DSP Link DMA enable.

So what we have to do is revisit my brilliant simplification that we didn't need a state variable to figure out if we are resuming or just handing with underflows. Gah.

@bardliao

@bardliao can you try the branch fix/sdw_dai_prepare on my GitHub, it's a POC on how we could keep track of the suspend information. there is no .suspend for the dai ops, but there is one for the dai_driver, so that might work for us.

I couldn't make it work on the laptop, looks like deep sleep is not supported, and I have no time left to test on RVP, hopefully you can take a look early next week. Thanks!

@bardliao

@bardliao can you try the branch fix/sdw_dai_prepare on my GitHub, it's a POC on how we could keep track of the suspend information. there is no .suspend for the dai ops, but there is one for the dai_driver, so that might work for us.

I couldn't make it work on the laptop, looks like deep sleep is not supported, and I have no time left to test on RVP, hopefully you can take a look early next week. Thanks!

@plbossart It works on my side. :)

@YvonneYang2

@YvonneYang2 @mengdonglin integration/soundwire-latest now has all the known fixes for suspend/resume please retry (along with the latest firmware)

Issue cannot be reproduced.

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 2933f73
FW: https://github.com/thesofproject/sof/commits/master commit: d1dcdfe
tplg: same path as FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML SDW Laptop with ALC711+ ALC1308+ ALC715

Close it since issue not reproduced.

Navigation Menu

Repository navigation

[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 #1460

41 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[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 #1460

Description

Activity

plbossart commented on Oct 12, 2019

bardliao commented on Oct 14, 2019

YvonneYang2 commented on Oct 14, 2019

tlauda commented on Oct 14, 2019

YvonneYang2 commented on Oct 14, 2019

tlauda commented on Oct 14, 2019

YvonneYang2 commented on Oct 14, 2019

plbossart commented on Oct 14, 2019

plbossart commented on Oct 14, 2019

plbossart commented on Oct 14, 2019

tlauda commented on Oct 15, 2019

YvonneYang2 commented on Oct 16, 2019

YvonneYang2 commented on Oct 21, 2019

YvonneYang2 commented on Oct 23, 2019

41 remaining items

plbossart commented on Nov 6, 2019

plbossart commented on Nov 7, 2019

plbossart commented on Nov 7, 2019

plbossart commented on Nov 8, 2019

plbossart commented on Nov 9, 2019

bardliao commented on Nov 11, 2019

plbossart commented on Nov 11, 2019

YvonneYang2 commented on Nov 12, 2019

YvonneYang2 commented on Nov 12, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions