[BUG] ipc timeout in suspend stress test

[aiChaoSONG]

Describe the bug
ipc timeout error when run stress S0ix check.

To Reproduce

1. reboot.
2. run suspend stress test script.
3. 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

1. Kernel: topic/sof-dev fa20ceba
2. SOF: master 596f761b
3. Topology: sof-cml-rt5682-max98357a.tplg
4. 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

[dengyangchao]

issue also can reproduce on CML and CFL
and CFL test in deep mode
CML test in s2idle

to reproduce

1. reboot via"sudo reboot"
2. Run with command aplay -Dhw:0,0 -r48000 -c2 -fs16_le /dev/zero & sudo ./stress-s3.sh 300 1 1

reproduce rate

1/143

dmesg

[ 3292.415850] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[ 3292.923340] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x30130000 size 12
[ 3292.923345] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 3292.923439] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 3292.923445] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 3292.923445] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3292.923449] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 3292.923449] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 3292.923451] sof-audio-pci 0000:00:1f.3: tplg: complete pipeline PIPELINE.10.DMIC0.IN id 67
[ 3292.923453] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[ 3293.427735] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x30130000 size 12
[ 3293.427740] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 3293.427812] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 3293.427817] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 3293.427817] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3293.427821] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 3293.427822] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 3293.427824] sof-audio-pci 0000:00:1f.3: tplg: complete pipeline PIPELINE.9.HDA6.OUT id 58
[ 3293.427826] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE

dmesg.log

[wwittbrx]

Please include firmware logs when the error occurs.

[dengyangchao]

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]

1. the issue first time observed in ww37.1, commit: master 92b23fa , but is low reproduce rate
2. change to ww36.5 commit: master ba32f4a, test 2000 times issue not occur
3. in ww37.2, commit: master 596f761, the reproduce rate add to about 1/150

step 1-3 kernel are topic/sof-dev fa20ceb

[dengyangchao]

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

[  163.000376] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  163.000403] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  163.500737] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  163.500770] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  163.505856] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x30130000 size 12
[  163.505869] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  163.506175] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  163.506184] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  163.506186] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  163.506192] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  163.506194] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  163.506213] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50030000: GLB_COMP_MSG: SET_DATA
[  164.001217] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  164.001259] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  164.009883] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x50030000 size 212
[  164.009910] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  164.010255] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  164.010281] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  164.010283] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  164.010306] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  164.010308] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  164.010312] sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 70
[  164.010314] sof-audio-pci 0000:00:1f.3: error: failed kcontrol value set for widget: 70
[  164.010316] sof-audio-pci 0000:00:1f.3: error: restoring kcontrols after resume
[  164.010319] sof-audio-pci 0000:00:1f.3: error: failed to restore pipeline after resume -110
[  164.010741] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  164.010961] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[  164.010992] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[  164.010999] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1

boot_fail.log

[wwittbrx]

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]

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

[aiChaoSONG]

issue reproduction becomes really low with kernel 6fc7eb300 and sof 0ba3fec5. Run 3 times of S0 stress test on CML:

• Without playback/capture, reproduced in iteration 249
• Without playback/capture, 300 iterations no reproduction
• With headset playback, 300 iteraitons no reproduction

500 iteration with playback via speaker, not reproduced

[dengyangchao]

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]

@dengyangchao is it survivavable ? i.e. is everything OK and working if kernel modules are reloaded ?

[dengyangchao]

@dengyangchao is it survivavable ? i.e. is everything OK and working if kernel modules are reloaded ?

@lgirdwood when issue occur, then use sof_remove.sh andsof_insert.sh, it back to normal