Repository navigation
[BUG][SDW]Headset aplay with suspend & resume stress test output "Program params failed: -61" error. #1344
Description
Describe the bug
Headset aplay with suspend & resume stress test output "Program params failed: -61" error.
To Reproduce:
run command: aplay -Dhw:0,0 -r48000 -c2 -fs16_le /dev/zero & sudo ./stress-s3.sh 50 1 1
frequency
first try reproduce at 15th.
second try reproduce at first time.
third try reproduce at 8th.
Expected result:
No error should output during headset suspend & resume stress test .
Actual result:
Headset aplay with suspend & resume stress test output "Program params failed: -61" error.
[ 688.078012] acpi LNXPOWER:09: Turning OFF
[ 688.078879] acpi LNXPOWER:08: Turning OFF
[ 688.081071] OOM killer enabled.
[ 688.081071] Restarting tasks ...
[ 688.082362] SDW1-speakers: ASoC: prepare FE SDW1-speakers
[ 688.082364] SDW1-Playback: ASoC: prepare BE SDW1-Playback
[ 688.082367] intel-sdw sdw-master-1: intel_prepare: SDW1 Pin2: start
[ 688.082376] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 688.085134] done.
[ 688.085556] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 688.085557] sdw_prepare_stream: SDW1 Pin2-Playback start
[ 688.085650] intel-sdw sdw-master-1: Msg Ack not received
[ 688.085651] intel-sdw sdw-master-1: Msg ignored for Slave 1
[ 688.085653] rt700 sdw:1:25d:700:0:0: DPN_PortCtrl register write failed for port 1
[ 688.085656] intel-sdw sdw-master-1: Program transport params failed: -61
[ 688.085657] intel-sdw sdw-master-1: Program params failed: -61
[ 688.085658] Prepare for stream:SDW1 Pin2-Playback failed: -61
[ 688.085659] sdw_prepare_stream: SDW1 Pin2-Playback: done
[ 688.085660] intel-sdw sdw-master-1: intel_prepare: SDW1 Pin2: done
[ 688.085661] intel-sdw sdw-master-1: ASoC: cpu DAI prepare error: -61
[ 688.085662] SDW1-Playback: ASoC: backend prepare failed -61
[ 688.085763] SDW1-speakers: ASoC: hw_free FE SDW1-speakers
[ 688.085767] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 688.085773] SDW1-Playback: ASoC: hw_free BE SDW1-Playback
[ 688.085777] intel-sdw sdw-master-1: intel_hw_free: SDW1 Pin2: start
[ 688.085778] sdw_deprepare_stream: SDW1 Pin2-Playback: start
[ 688.086172] sdw_deprepare_stream: SDW1 Pin2-Playback: done
[ 688.086181] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 688.086280] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 688.086282] intel-sdw sdw-master-1: intel_hw_free: SDW1 Pin2: done
[ 688.086306] SDW1-Playback: ASoC: close BE SDW1-Playback
[ 688.086308] intel-sdw sdw-master-1: intel_shutdown: SDW1 Pin2: start
[ 688.086310] intel-sdw sdw-master-1: intel_shutdown: SDW1 Pin2: done
[ 688.086337] SDW1-speakers: ASoC: close FE SDW1-speakers
[ 688.086341] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 688.086344] SDW1-Playback: ASoC: BE SDW1-Playback event 2 dir 0
[ 688.087094] intel-sdw sdw-master-1: Msg Ack not received
[ 688.087096] intel-sdw sdw-master-1: Msg ignored for Slave 1
[ 688.087300] SDW1-speakers: ASoC: BE playback disconnect check for SDW1-Playback
[ 688.087303] SDW1-speakers: freed DSP playback path SDW1-speakers -> SDW1-Playback
[ 688.130566] PM: suspend exit
[ 689.025612] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 689.025683] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
s3_test_8_logger_all.log
s3_test_8_logger_error.log
test_8.log
Environment
Firmware: 3d5d314 https://github.com/thesofproject/sof/commits/master
kernel: 29debf8 https://github.com/thesofproject/linux/tree/integration/soundwire-latest
tplg: sof-cml-rt700.tglg
platform: CML RVP with codec ALC700 in SDW mode
Activity
sinahuang commentedon Oct 21, 2019
this is split from bug #1311
YvonneYang2 commentedon Oct 22, 2019
Issue can also reproduce on ICL RVP, with codec ALC711 -RT1308, RT715 in SDW mode.
YvonneYang2 commentedon Oct 24, 2019
Issue reproduced on CML RVP with codec ALC700 in SDW mode.
Failed at 38th time.
Logs:
s3_test_38_logger_all.log
test_38.log
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: sof-cml-rt700.tplg
dengyangchao commentedon Oct 24, 2019
issue also reproduced on TGL RVP with codec ACL711, ALC1308 in SDW mode
Failed at 6th time
log:
s3_test_6_logger_all.log
test_6.log
Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 15f27d8
FW: https://github.com/thesofproject/sof/commits/master commit: f277189
tplg: Same with TGL FW branch commit: sof-tgl-rt711-rt1308-nohdmi.tplg rename to sof-tgl-rt711-
rt1308.tplg
plbossart commentedon Oct 24, 2019
Seems like a problem with the codec trying to write registers before we complete the enumeration
@bardliao can you look into this with @shumingfan?
bardliao commentedon Oct 25, 2019
Sure
bardliao commentedon Oct 25, 2019
@sinahuang Could you share
stress-s3.sh?YvonneYang2 commentedon Oct 25, 2019
Script:
stress-s3.sh.txt
bardliao commentedon Oct 25, 2019
@sinahuang Could you retest it with #1370? It works on my side.
19 remaining items
bardliao commentedon Nov 8, 2019
[ 196.135457] rt1308 sdw:1:25d:1308:0: Initialization not complete, timed outI think it is the problem. I will look into it.
YvonneYang2 commentedon Nov 8, 2019
@bardliao
Same dmesg log shows when run aplay0,0 (RT711) stop/restart stress test. Failed at 199th time.
Original issue reproduced steps cannot be tested since suspend with s2idle mode is blocked by #1387 ,
aplay_error_199_dmesg.log
aplay_error_199_logger_all.log
bardliao commentedon Nov 8, 2019
@plbossart Somehow there is no intel_resume_runtime around the "Initialization not complete, timed out" (rt1308_dev_resume)
The following trace is from aplay_error_14_dmesg.log
bardliao commentedon Nov 8, 2019
@plbossart I think the reason why there is no intel_resume_runtime around rt1308_dev_resume is that
we call pm_runtime_mark_last_busy() in intel_shutdown(), but not in codec's shutdown dai ops. I tried to do the same on rt1308-sdw.c but it doesn't solve the issue. On second thought, I think we can't assume that master is always suspended when a slave is suspended. For example, master will be active if there are two slaves on the same sdw bus, one is suspended and the other is active. So probably we need to find a way to know if we have to wait for initialization_complete in codec resume or not.
plbossart commentedon Nov 8, 2019
tthanks @bardlio, good analysis
so the sequence is
(1) resume, playback, stop
(2) intel_shutdown() gets called, we call put_autosuspend()
(3) timeout in rt1308_dev_resume()
(4)playback restarts, we call intel_startup() and call pm_runtime_get()
I guess what happens is that the DAIs are released, so the codec suspends, but the master does not suspend so as a result we will not force the codec to be tagged as unattached and we don't call complete(), ever.
what we'd need to have is something like is_bus_suspended() to figure out if the context was lost or not.
For now, can we try the stress test with a longer interval between each playback (make that 10s) to make sure the master will suspend?
plbossart commentedon Nov 8, 2019
@bardliao @YvonneYang2 PR #1459 should solve this bug, please double-check.
bardliao commentedon Nov 11, 2019
@plbossart I tested ./sof-test-playback.sh and it passed for 500 times
plbossart commentedon Nov 11, 2019
@sinahuang @mengdonglin integration/soundwire-latest now has all the known fixes for suspend/resume please retry (along with the latest firmware)
YvonneYang2 commentedon Nov 12, 2019
Error not seen in 500 times aplay stress test.
Original steps suspend/resume stress test in MSI mode is still on going.
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
YvonneYang2 commentedon Nov 13, 2019
Original issue cannot be reproduced in 300 times suspend/resume with playback stress test. But occurred "IO transfer timed out" at 125th/126th/138/139th time.
Besides, some error info when do s2idle suspend with aplay is same as #1387 (comment), but aplay function will not be effected.
IO transfer timed out
error info
Logs:
s3_test_125_logger_all.log
test_125.log
s3_test_126_logger_all.log
test_126.log
Script:
stress-s3.sh.txt
Run with command "aplay -Dhw:0,0 -r48000 -c2 -fs16_le /dev/zero & sudo ./stress-s3.sh 300 1 1 "
bardliao commentedon Nov 13, 2019
I did the same test, but didn't see IO transfer timed out on my side. I tested it on fb40b85
YvonneYang2 commentedon Nov 13, 2019
Run 300 times aplay+suspend/resume stress test with MSI IRQ mode, IO transfer timed out still can be reproduced on my side. Tested it on fb40b85
YvonneYang2 commentedon Nov 14, 2019
Since original issue cannot be reproduced, close it and track IO transfer timed out issue in #1482