Repository navigation
[BUG] ipc timeout in suspend stress test #1812
Description
Describe the bug
ipc timeout error when run stress S0ix check.
To Reproduce
- reboot.
- run suspend stress test script.
- error will occur in some iteration.
Note that in which iteration this error occur is not sure, so you may rerun script several times, and make sure there is enough iteration in each run (eg. 200 iterations).
Reproduction Rate
75%
Expected behavior
suspend stress test should run successfuly
Environment
- Kernel:
topic/sof-dev fa20ceba - SOF:
master 596f761b - Topology:
sof-cml-rt5682-max98357a.tplg - Platform: CML Chrome
[ 1914.277412] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1914.777564] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 1914.777598] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1914.782600] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x30130000 size 12
[ 1914.782615] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1914.782948] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1914.782964] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 1914.782967] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1914.782978] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1914.782980] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1914.783001] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50030000: GLB_COMP_MSG: SET_DATA
[ 1915.277529] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 1915.277563] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1915.286647] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x50030000 size 136
[ 1915.286661] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1915.286995] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1915.287011] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 1915.287013] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1915.287024] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1915.287027] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1915.287031] sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 51
[ 1915.287034] sof-audio-pci 0000:00:1f.3: error: failed kcontrol value set for widget: 51
[ 1915.287036] sof-audio-pci 0000:00:1f.3: error: restoring kcontrols after resume
[ 1915.287038] sof-audio-pci 0000:00:1f.3: error: failed to restore pipeline after resume -110
[ 1915.287048] PM: dpm_run_callback(): pci_pm_resume+0x0/0xa0 returns -110
[ 1915.287057] PM: Device 0000:00:1f.3 failed to resume: error -110
[ 1915.292621] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[ 1915.292631] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[ 1915.292637] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:2
[ 1915.292641] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 7:0
[ 1915.293595] OOM killer enabled.
[ 1915.293597] Restarting tasks ... done.
[ 1915.301022] PM: suspend exit
[ 1915.305437] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 5:0
[ 1915.306165] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 7:0
[ 1915.306418] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 5:1
[ 1915.307144] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 5:2
[ 1915.307852] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 7:2
Activity
dengyangchao commentedon Sep 10, 2019
issue also can reproduce on CML and CFL
and CFL test in deep mode
CML test in s2idle
to reproduce
reproduce rate
1/143
dmesg
dmesg.log
wwittbrx commentedon Sep 10, 2019
Please include firmware logs when the error occurs.
dengyangchao commentedon Sep 11, 2019
issue still occur on CFL
recipe
Firmware: 09a44ab https://github.com/thesofproject/sof/commits/master
Kernel: fa20ceb https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-hda-generic-4ch.tplg same as firmware
s3_test_114_logger_all.log
s3_test_114_logger_error.log
test_114.log
dengyangchao commentedon Sep 16, 2019
step 1-3 kernel are topic/sof-dev fa20ceb
dengyangchao commentedon Sep 16, 2019
issue can reproduce on ICL-RVP, when doing module unload/reload
reproduce rate
1/5
Environment
Firmware: 2bd725d https://github.com/thesofproject/sof/commits/master
Kernel: 6cf9ef0 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-hda-generic-4ch.tplg same as firmware
platform：ICL-RVP
dmesg
boot_fail.log
wwittbrx commentedon Sep 16, 2019
What platform/OS/coreboot are you using? I tried to reproduce this issue but my system reboots on rtcwake command. I'm testing on CML laptop with Ubuntu 19.04 with kernel 6cf9ef0.
aiChaoSONG commentedon Sep 16, 2019
@wwittbrx I think CML not support S3 yet, you can test this with S0, run
echo s2idle > /sys/power/mem_sleep, rtcwake now will sleep to S0 instead of rebootaiChaoSONG commentedon Sep 17, 2019
issue reproduction becomes really low with kernel
6fc7eb300and sof0ba3fec5. Run 3 times of S0 stress test on CML:500 iteration with playback via speaker, not reproduced
dengyangchao commentedon Sep 17, 2019
use two ICL-RVP run 200times, issue can not reproduce when doing module unload/reload
Firmware: 0ba3fec https://github.com/thesofproject/sof/commits/master
Kernel: 6fc7eb3 https://github.com/thesofproject/linux/commits/topic/sof-dev
lgirdwood commentedon Sep 17, 2019
@dengyangchao is it survivavable ? i.e. is everything OK and working if kernel modules are reloaded ?
dengyangchao commentedon Sep 18, 2019
@lgirdwood when issue occur, then use
sof_remove.shandsof_insert.sh, it back to normalaiChaoSONG commentedon Sep 19, 2019
I have encountered ipc timeout in basic tests several times, but ipc timeout occur very randomly(not able to predict which test case cause it, and it may occur in any test case after running test for a while), so I think recent ipc timeout issue (#1812, #1830 and #1839) is not caused by suspend, module reload or multi-pipeline aplay. And recent changes to sof may introduce some accumulated errors, like renewed scheduler, which should be responsible for these issues. @lgirdwood
lgirdwood commentedon Sep 23, 2019
@aiChaoSONG thanks, can you work more on root causig this with a reproducable test. We can then re-prioritize if it turns out to be something not related to context save.
dengyangchao commentedon Sep 27, 2019
issue can be reproduced on GLK-chrome when run aplay+suspend stress test
test recipe
Firmware: 7046e84 https://github.com/thesofproject/sof/commits/master
Kernel: 578ff8d https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-glk-da7219.tplg same as firmware
logger-log
s3_test_194_logger_all.log
s3_test_194_logger_error.log
test_194.log
stress-s3.txt
wenqingfu commentedon Sep 27, 2019
thanks. @aiChaoSONG ! #1830 points to PR #1797. Can you please try if this issue is also related with patch? unfortunately, we step into the deep water that only rounds of stress testing can prove something is truly fixed... @ClarexZhou to help
tlauda commentedon Sep 29, 2019
@wenqingfu I'm already working on it. Should have potential fix tomorrow.
aiChaoSONG commentedon Sep 30, 2019
@tlauda I have run some tests on different commits, and now I can conclude that commit edf_schedule: implement the new version of EDF scheduler introduces this ipc timeout issue. Is your fix related to the newly implemented scheduler? If not, please look into this commit and see if there is any flaw in it
lgirdwood commentedon Sep 30, 2019
@aiChaoSONG good work to root cause this. It's a blocker now for v1.4
wwittbrx commentedon Oct 1, 2019
I cannot reproduce this issue with #1887 applied. Please check it on your side.
aiChaoSONG commentedon Oct 8, 2019
1000 times no reproduction on CML Chrome, Please verify on your side, if issue cannot be reproduced either, please help to close this issue @dengyangchao
dengyangchao commentedon Oct 8, 2019
issue can not reproduce on CFL, CML, ICL-RVP and GLK-Chrome, so close the issue