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

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.

@ClarexZhou

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

@emilchudzik

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.

@emilchudzik

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

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

@lyakh

@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

@wenqingfu

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

@ClarexZhou

@ClarexZhou @lyakh
Tested with:
48e3f0b (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.

@lyakh

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

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.

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.

@kv2019i

@kv2019i this change fixes the issue for me on CML:

diff --git a/sound/soc/sof/pm.c b/sound/soc/sof/pm.c
index 775551106bc9..ba6cd4d85aa8 100644
--- a/sound/soc/sof/pm.c
+++ b/sound/soc/sof/pm.c
@@ -350,11 +350,6 @@ static int sof_suspend(struct device *dev, bool runtime_suspend)
                return ret;
        }
 
-#if IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE)
-       /* cache debugfs contents during runtime suspend */
-       if (runtime_suspend)
-               sof_cache_debugfs(sdev);
-#endif
        /* notify DSP of upcoming power down */
        ret = sof_send_pm_ipc(sdev, SOF_IPC_PM_CTX_SAVE);
        if (ret < 0) {
@@ -364,6 +359,12 @@ static int sof_suspend(struct device *dev, bool runtime_suspend)
                return ret;
        }
 
+#if IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE)
+       /* cache debugfs contents during runtime suspend */
+       if (runtime_suspend)
+               sof_cache_debugfs(sdev);
+#endif
+
        /* power down all DSP cores */
        if (runtime_suspend)
                ret = snd_sof_dsp_runtime_suspend(sdev, 0);

"0x40010000: GLB_PM_MSG: CTX_SAVE" ipc timed out still can be reproduced after disable CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE in kernel config.

Kernel:
https://github.com/lyakh/linux/tree/ipc-timeout
commit 5969756 ASoC: SOF: hda: couple host and link DMA during FE hw_free , PR 895
FW:
https://github.com/lyakh/sof/tree/ipc-timeout
commit: b527fd7 dai: assign/free link DMA channel during dai_config() , PR1354

s3__test_63_dmesg_error .log
s3__test_63_logger_error.log
s3_test_63_logger_all.log

@lyakh

@lyakh @ranj063 @lgirdwood
I today made following experiment. I added following to start of pm.c:sof_suspend():

send CTX_RESTORE ipc at start (no-op on FW side, good tool to check IPC is working)
sleep for 1sec
send another CTX_RESTORE
run existing save debugfs-cache code
send another CTX_RESTORE
send existing CTX_SAVE code and continue

Upon triggering the bug, IPC failure happens systematically at (3).

So that suggests that:

bug is not related specifically to CTX_SAVE (as failure happens already with CTX_RESTORE)
bug is not related to debugfs cache save (as failure happens before save)

Rootcause is still unknown, investigation continues.

Problem now tracked to following upstream patch that went into 5.1:
kv2019i@b5a236c

If reverted, it seems the problem cannot be reproduced with the steps in this bug.

Problem root caused to power recycling the HDA codec while ADSP HDA controller is powered up. A simple IPC test loop (sending any IPC message to ADSP in a loop) stops working immediately when HDA codec power cycle happens. Upstream patch kv2019i@b5a236c itself looks ok, but it starts to cause this problem more often.

PR978 is not a full fix -- it prevents codec-suspend cycle, but it doesn't prevent codec-resume. I have at least one case (with 150+ iterations) that still hits a problem and logs show codec-resume happens in middle of DSP suspend sequence. Reverting kv2019i@b5a236c prevents this as well (but not fool-proof either).

@kv2019i

PR978 is not a full fix -- it prevents codec-suspend cycle, but it doesn't prevent codec-resume. I have at least one case (with 150+ iterations) that still hits a problem and logs show codec-resume happens in middle of DSP suspend sequence. Reverting kv2019i@b5a236c prevents this as well (but not full-proof either).

@kv2019i what do you mean "not full proof?" Do you mean, that also with that revert IPC timeouts can be reproduced?

@lyakh

@lyakh wrote:

@kv2019i what do you mean "not full proof?" Do you mean, that also with that revert IPC timeouts can be reproduced?

Oops, sorry, bad English. Reverting the patch does prevent the IPC timeouts using the reproduction steps of this bug, no failing cases. By fool proof I mean that now that we know the actual mechanism, we can see the revert only addresses one specific case, but there might be many more scenarios where codec runtime PM is triggered, leading to a IPC fault. But true, probably best not to mix things -- for the repro steps of this bug, the revert is good with no failing cases and recent test rounds also point to this.

Update on status of this and different approaches to address this:

kv2019i@577361d -> best known method now
reverting kv2019i@b5a236c -> not ok to push upstream
ASoC: SOF: hda: forbid codec reset while controller is powered #978 -> abandoned

Problem rootcaused to MSI IRQ mode. This bug will be closed by disabling MSI:

[NOT FOR UPSTREAM]ASoC: SOF: Intel: hda: switch to use legacy IRQ mode #1002 -> this be used to close the bug, disable MSI Mode
kv2019i@577361d -> will be submitted to sof-dev also

Keeping open until patch is merged and fix can be validated with sof-dev.

A lot of progress has happened to refine the fixes to something we could merge upstream:

Modified stream interrupt handler. Mimics the legacy interrupt handler #1013 - always wake irq threads
ASoC: SOF: intel: fix issues in hda irq handling #1011 - irq masking based
[Do not merge] V5.0 ipc timeout 2 #1015 - combined the handlers

Plan is to still keep MSI enabled in sof-dev. Keeping open until one of the solutions is merged.

#1013 was now merged and no new sightings -> closing this bug.

Navigation Menu

Repository navigation

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

16 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

kv2019i commented on May 14, 2019

kv2019i commented on May 16, 2019

kv2019i commented on May 17, 2019

wenqingfu commented on May 17, 2019

kv2019i commented on May 20, 2019

kv2019i commented on May 20, 2019

kv2019i commented on May 20, 2019

kv2019i commented on May 20, 2019

kv2019i commented on May 20, 2019

kv2019i commented on May 20, 2019

ranj063 commented on May 20, 2019

16 remaining items

ClarexZhou commented on May 23, 2019

kv2019i commented on May 23, 2019

kv2019i commented on May 23, 2019

kv2019i commented on May 24, 2019

kv2019i commented on May 24, 2019

lyakh commented on May 24, 2019

kv2019i commented on May 24, 2019

kv2019i commented on May 29, 2019

kv2019i commented on Jun 3, 2019

kv2019i commented on Jun 6, 2019

kv2019i commented on Jun 17, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions