System hangs during S3 on WHL

[keqiaozhang]

This issue happens on WHL-RVP. It run to system hangs during the S3 stress test and no logs or traces are available after this issue.
This issue cannot be reproduced after audio is removed form kernel. So I think this is a sof issue.

Test recipe:
Kernel: sof-dev/08d3631c
Firmware: master/96a544
Platform: WHL-rvp

[ranj063]

@keqiaozhang I think this might be related to #1050

[ranj063]

could you please also check if there's anything in kern.log?

[fredoh9]

Good news and bad news. I tried on daily build of 20190621. I couldn't reproduce the problem.
linux: topic/sof-dev 08d3631
sof: master 333f15f3

I ran S3 manual testing with playback and without playback. but no luck.

I ran sanity-test suite with only pm-s3-10.sh and pm-s3-without-playing-10.sh. I tried two times, meaning 2x10 S3 each case.

[fredoh9]

After discussing with @ranj063, All WHL/CFL/ICL RVPs in my side are running SOF HDA mode. We don't have I2S codec. Not sure WHL in this thread are I2S or not but #1050 is I2S mode. So she wanted to debug more in I2S mode.

Not to lose the status of my testing. I build sathya's chrome kernel and test same thing. this kernel is based on 4.19.48 whereas sof-linux is 5.2.0 RC3.
https://github.com/sathyap-chrome/linux/tree/gtot_sofv3

I don't see system hung but i found ipc timeout issue which i believe already fixed.
[ 224.594174] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 timedout
[ 224.594183] sof-audio-pci 0000:00:1f.3: error: load fw failed ret: -110
[ 224.594207] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
[ 224.594212] sof-audio-pci 0000:00:1f.3: error: status = 0x00000000 panic = 0x00000000
[ 224.594216] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
[ 224.594219] sof-audio-pci 0000:00:1f.3: error: failed to reset DSP
[ 224.594222] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
[ 224.594258] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 224.900297] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[ 224.900306] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 224.900311] sof-audio-pci 0000:00:1f.3: error: status = 0x001c003c panic = 0x00000000
[ 224.900315] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 224.900322] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040001 mask 0x00000000
[ 224.900326] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[ 224.900340] pci_pm_suspend(): snd_sof_suspend+0x0/0x10 [snd_sof] returns -110
[ 224.900350] dpm_run_callback(): pci_pm_suspend+0x0/0x120 returns -110
[ 224.900356] PM: Device 0000:00:1f.3 failed to suspend: error -110
[ 224.900359] PM: Some devices failed to suspend, or early wake event detected

[wenqingfu]

could you please also check if there's anything in kern.log?

ping, @keqiaozhang. @RanderWang knows how to setup a kernel serial console, it can help you capture the console output from the kernel from another machine in kernel panic.

[RanderWang]

(1) Connect com port to host machine by a usb-com line.

(2) add the following lines in /etc/default/grub on target machine( whiskylake RVP)
GRUB_CMDLINE_LINUX="console=tty0 console=ttyS0,115200n8"
GRUB_TERMINAL=serial
GRUB_SERIAL_COMMAND="serial --speed=115200 --unit=0 --word=8 --parity=no --stop=1"

(3) install minicom in host machine and setup minicom to connect target machine
->Serial port setup
---------> Serial Device : /dev/ttyUSB0 // please check by /dev/ttyUSBx
-> Modem and dialing
---------> Modem has DCD line ... no

[ranj063]

@mengdonglin @keqiaozhang if this is a regression caused by #1018 , it should be fairly easy to do a git bisect and determine which commit is the culprit. Can someone help with that?

Also, is this issue seen with nocodec as well?

[keqiaozhang]

@ranj063
Looks like HDA mode is more stable than I2S mode. I have got 300+ iterations pass, test is ongoing.
On WHL-I2S, usually it fails at ~100 iterations. I enabled the serial port, but no useful logs are captured after system hang.
Serial port final output:

[ 1182.785290] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 1182.792111] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1182.799415] acpi LNXPOWER:07: Turning OFF
[ 1182.804306] OOM killer enabled.
[ 1182.807461] Restarting tasks ... done.
[ 1182.810105] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[ 1182.819334] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1182.831843] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1182.840255] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[ 1182.847679] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[ 1182.855085] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 1182.862193] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 1182.868979] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
[ 1182.916388] video LNXVIDEO:00: Restoring backlight state
[ 1182.921710] PM: suspend exit
[ 1186.954610] PM: suspend entry (deep)
[ 1186.959180] Filesystems sync: 0.000 seconds
[ 1186.963596] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 1186.972064] OOM killer disabled.
[ 1186.975291] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 1186.984040] printk: Suspending console(s) (use no_console_suspend to debug)

I will enable more PM debug messages and test it again.

[ranj063]

@keqiaozhang thanks!
could you please try reverting this patch ASoC: rt5682: Check JD status when system resume
and trying S3 stress test again. The jack detection work seems interfere with the suspend sequence

[keqiaozhang]

@ranj063
This issue is still there after reverting the above patch, test failed at 242nd. also no useful log in serial port output.

[ranj063]

@keqiaozhang can we please try with the nocodec mode and see if this issue still exists?