IPC RX error after DSP suspend

[lyakh]

When unloading SOF kernel modules, the normal case looks approximately like this:

[24230.561920] [92038] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[24230.561983] [92038] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[24230.562012] [92038] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[24230.562129] [92038] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[24230.562198] [92038] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[24230.601148] snd_hda_codec_realtek ehdaudio0D0: ALC3204: Apply fix-func for (null)
[24230.601266] snd_hda_codec_realtek ehdaudio0D0: ALC3204: Apply fix-func for (null)
[24230.647975] [92038] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[24230.647982] [92038] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[24230.647985] [92038] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[24230.647993] [92038] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[24230.648000] [92038] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful

whereas sometimes after CTX_SAVE the kernel detects an incoming IPC message, which is then recognised as corrupt with multiple 0xff bytes and an error is issued. This failure has been observed on CML RVP and on Mantis in a daily test of 30-31.07.2020 but I was unable to reproduce it locally. When such an error occurs the test script aborts execution and doesn't re-load the modules, thus, no further testing is possible. Two examples of corrupt IPC messages:

ipc rx: 0xffffffff: unknown GLB command
error: unknown DSP message 0xf0000000

and

ipc rx: 0x90020000: GLB_TRACE_MSG
error: DSP trace buffer overflow 4294967295 bytes, total messages -1

[plbossart]

@lyakh can you add a pointer to the failed CI tests, and/or attach the dmesg trace?

[lyakh]

@lyakh can you add a pointer to the failed CI tests, and/or attach the dmesg trace?

@plbossart sorry, cannot link, they aren't accessible from the public internet. Attaching dmesg

unknown.txt
overflow.txt

[plbossart]

Thanks @lyakh the overflow case is interesting, never seen this one. This seems to happen exactly while a trace is flushed during the CTX_SAVE, that looks like a firmware issue.
The unknown GLB command looks more hardware-related to me.

[lyakh]

@plbossart aren't they the same? They happen at the same time, after suspend, and they show up as corrupted IPC with many oxff bytes. Just one of them had the command overwritten to 0xffffffff and the other one had the command still containing a meaningful value, but 0xffffffff in later fields

[plbossart]

@plbossart aren't they the same? They happen at the same time, after suspend, and they show up as corrupted IPC with many oxff bytes. Just one of them had the command overwritten to 0xffffffff and the other one had the command still containing a meaningful value, but 0xffffffff in later fields

maybe. I am just making the hypothesis that there could be transitions where the hardware isn't in a valid state, while the trace could be more of a race condition.

[mengdonglin]

This issue is observed in CI daily test randomly on CML RVP and CML Mantis, but cannot be reproduced locally. It doesn't impact audio functionality.

[lyakh]

Update: this issue isn't present in the latest daily tests either. But it is unclear from the daily results, whether re-loading the drivers recovers after this error since the testing stops with drivers unloaded.