[Bug][WHL] ipc timed out after S3 after '0x40010000: GLB_PM_MSG: CTX_SAVE'

[kv2019i]

Summary:
'ipc timed out for for '0x40010000: GLB_PM_MSG: CTX_SAVE' after stop aplay or system reboot.

To reproduce
Set up: Mantis WHL, no peripherals connected excepte USB etherner card for remote ssh.
Boot Mantis WHL device.
Log in.
Open shell and force S3 with:
sudo rtcwake -m mem -s 3

Actual result
error: ipc timed out for 0x40010000: GLB_PM_MSG: CTX_SAVE

Reproduce rate:
+20% (typically happens after three S3 tries after boot)

Test recipe
Kernel repo: 9d424352fe4 (sof/topic/sof-dev)
- same results also with f19ab80 (sof/topic/sof-dev) + #895
Firmware repo: 42390011 (master)
- same results also with 4f239dea (HEAD -> dai-channel-fix, ranjani/fix/link-dma-allocation) of thesofproject/sof/pull/1354
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

Dmesg log

[  141.785846] OOM killer enabled.
[  141.785847] Restarting tasks ... done.
[  141.833840] PM: suspend exit
[  141.855839] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  142.163915] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  142.163934] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  142.164207] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  142.164221] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  142.164225] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110

Notes:
Similar to #934 but the fix (PR936) does not help in this case.

[kv2019i]

@ClarexZhou FYI ... this is similar to #919 but this specifically appens with the S3 routine. Let's track separately as the steps to reproduce are different.

[kv2019i]

Assigning for myself as I can reproduce this easily.

To exclude possible compiler impact, tested this scenario today with both GCC built image and XT-CC built image from @emilchudzik and outcome and repro rates are the same.

[kv2019i]

Log with some additional debugs (FYI @emilchudzik and @lyakh), comments with KV:

May 17 13:10:52 rukoilijasirkka kernel: [   96.488640] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40020000: GLB_PM_MSG: CTX_RESTORE
May 17 13:10:52 rukoilijasirkka kernel: [   96.960199] sof-audio-pci 0000:00:1f.3: IRQ!
***KV: added a trace to irq_thread to see when the thread is kicked
May 17 13:10:52 rukoilijasirkka kernel: [   96.960214] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x90020000 mask 0x00000003
May 17 13:10:52 rukoilijasirkka kernel: [   96.960232] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
May 17 13:10:52 rukoilijasirkka kernel: [   96.960256] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
May 17 13:10:52 rukoilijasirkka kernel: [   96.960265] sof-audio-pci 0000:00:1f.3: IRQ!
May 17 13:10:52 rukoilijasirkka kernel: [   96.960270] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
May 17 13:10:52 rukoilijasirkka kernel: [   97.460071] sof-audio-pci 0000:00:1f.3: IRQ!
May 17 13:10:52 rukoilijasirkka kernel: [   97.460086] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x90020000 mask 0x00000003
May 17 13:10:52 rukoilijasirkka kernel: [   97.460105] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
May 17 13:10:52 rukoilijasirkka kernel: [   97.460129] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
May 17 13:10:52 rukoilijasirkka kernel: [   97.460138] sof-audio-pci 0000:00:1f.3: IRQ!
May 17 13:10:52 rukoilijasirkka kernel: [   97.460146] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
May 17 13:10:52 rukoilijasirkka kernel: [   97.527407] OOM killer enabled.
May 17 13:10:52 rukoilijasirkka kernel: [   97.527407] Restarting tasks ... done.
May 17 13:10:52 rukoilijasirkka kernel: [   97.571340] PM: suspend exit
May 17 13:10:52 rukoilijasirkka kernel: [   97.602254] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
May 17 13:10:52 rukoilijasirkka kernel: [   97.612964] sof-audio-pci 0000:00:1f.3: KV: IPC round 1 ret 0
May 17 13:10:52 rukoilijasirkka kernel: [   97.612966] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
***KV: I added polling to driver side to observe status before the full IPC timeout elapses... no new info, but there are some more traces 
May 17 13:10:52 rukoilijasirkka kernel: [   97.612982] sof-audio-pci 0000:00:1f.3: unknown ROM status value 0000000c
May 17 13:10:52 rukoilijasirkka kernel: [   97.613250] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000081 trace 0x00000081
***KV: I'm using the debugs from 'debug-ipc-timeout' branch ... counter value of 81 has increased since 80, so based on thsi logs, DSP did reply to CTX_SAVE
***KV: no IRQ trace, so host side does not get the IRQ
May 17 13:10:52 rukoilijasirkka kernel: [   97.613258] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003

[wenqingfu]

what about if you don't apply 1354 and 895?

[kv2019i]

@lyakh Here's the full dmesg with unpatched SW+FW from the IPC timeout branches. In this log, FW load failed on 4th iteration.

Linux: 29fbf66 (sof/topic/ipc)
FW: 7330436e (debug-ipc-timeout)

dmesg-20190520-i.txt

[kv2019i]

@wenqingfu wrote:

what about if you don't apply 1354 and 895?

1354+895 is not applied in the IPC branch. I did earlier test with the patches applied as well, but no difference. I'll next test the 5.0 release branch as Claire reported different results with that.

[kv2019i]

@ClarexZhou @lyakh
Tested with:
48e3f0b1b6be (sof/topic/ipc-v5.0)
... and I get the same result as Clare, no IPC timeout. Did stress runs 0/500 and 0/100 iterations (a full system reboot in between). The patch delta between v5.0 branches and latest sof-dev is of course rather massive, but it's either an issue in upstream suspend code or in our rebase.

[kv2019i]

@lyakh noticed that there is a 20sec gap in timestamps just before the error in dmesg-20190520-i.txt

I now took two more logs (with same 5.2-rc linux+fw as with previous log) and in these new logs, there is no 20sec gap visible:
dmesg-20190520-iii-s3-stress-fails.txt
dmesg-20190520-i.txt

So best lead seems to be to bisect what happened between 5.0 and 5.2-rc as timeouts disappear if we go back to 5.0 integration branch.

[kv2019i]

Hmm, I made an experiment and tried this scenario on sof/topic/sov-dev-rebase, then rebased the series back to 5.1 and back to 5.0. Results the following:

Branch	Test result	Comments
sof/topic/sof-dev	FAIL	5.2-rc
sof/topic/sov-dev-rebase	FAIL	5.2-rc
above rebased to 5.1	FAIL	https://github.com/kv2019i/linux/tree/topic/gh959-rebase-5.1-fails
above rebased to 5.0	OK	https://github.com/kv2019i/linux/tree/topic/gh959-rebase-5.0-ok
topic/ipc-v5.0	OK	5.0 integration branch plus IPC debug patch

FAIL = at least one IPC timeout in 100 iterations of S3 suspend/resume, with 5sec duty cycles and no audio playback during test

The patch delta is still large, so rootcausing is probably easier by other means than bisect.

[kv2019i]

The problem always occurs when runtime PM suspend is triggered for the first time after a S3 resume.

Disabling runtime PM seems to avoid the problem and failures cannot be triggered.