[BUG] PM / Firmware boot failure due to timeout after resume from hibernate on linux kernel 5.18

[mofrim]

Describe the bug

I am running NixOS x86_64 Linux on a Dell XPS9310 with Intel Tiger Lake Sound. Just upgraded to most recent NixOS-version (22.05) which includes kernel upgrade from 5.17.11 to 5.18.
After the upgrade i came across following problematic behaviour:

• when I boot to console, login and invoke systemctl hibernate hibernation works only one time because when i resume from hibernate i get the following log message:

[   41.583553] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   41.583557] sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware boot failure due to timeout
[   41.583558] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[   41.583651] sof-audio-pci-intel-tgl 0000:00:1f.3: invalid header size 0xffffffff. FW oops is bogus
[   41.583652] sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00000000
[   41.583652] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   41.583653] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to boot DSP firmware after resume -5
[   41.583654] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: dpm_run_callback(): pci_pm_restore+0x0/0xe0 returns -5
[   41.583664] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: failed to restore async: error -5

and after that hibernation or suspend is not possible anymore.

• when i boot to sway / wayland and invoke systemctl hibernate from terminal there, screen freezes and i have to hard reset my computer in order to reboot. hibernation seems to take place in the background successfully though, because resume from hibernate succeeds but dmesg shows the same errors as above.

When i switched back to linux 5.17.11 the problem is gone again.

To Reproduce

Boot system with kernel 5.18 and sof-bin 2.1.1, invoke systemctl hibernate from console or wayland

Reproduction Rate

10/10

Expected behavior

Hibernation and resume do not produce errors and can be repeated as often as you want.

Impact

Just forces me to use older kernel version which isn't a problem so far.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: 5.18
   • SOF: sof-bin v2.1.1
2. Name of the platform(s) on which the bug is observed.
   • Platform: x86_64 Linux

[plbossart]

Thanks for the report @friedelino, much appreciated.

This looks like a regression, my money would be on the change we added for IMR support between 5.17 and 5.18
5fb5f51185126 ('ASoC: SOF: Intel: hda-loader: add IMR restore support')

Could you
a) attach the result of 'alsa-info' so that we know what device you have
b) try to use 'systemctl suspend' instead?
c) disable the IMR boot by setting this bit
sof-priv.h:#define SOF_DBG_IGNORE_D3_PERSISTENT BIT(7) /* ignore the DSP D3 persistent capability

add this in /etc/modprobe.d/alsa-base.conf

options snd-sof sof_debug=0x41

reboot, re-run 'systemctl hibernate' and share the full dmesg log in attachment (not copy-paste please!).

Thanks for your help in root-causing this problem.

[plbossart]

@ranj063 @ujfalusi @kv2019i @bardliao FYI

[ujfalusi]

@friedelino would it be possible to attach the full kernel log?
Since this happens after hibernate, it certainly looks like IMR boot issue.
We have a followup patch for IMR boot which adds recovery for the IMR failure (but that showed rare sideffect for which we have another patch, not yet upstream).
What is strange in the error is that we don't have any meaningful reason code from the DSP, 0xffffffff and 0x00000000. There might be something else happening, other than IMR.

IMR boot: is a way to skip firmware re-loading, re-validating. To speed up resume time.

Btw: does runtime resume works? Boot up, play audio, stop it, wait 7 sec, do another playback. That should also trigger IMR booting.

[mofrim]

Could you a) attach the result of 'alsa-info' so that we know what device you have

http://alsa-project.org/db/?f=4342d05ad4716decacf2320f2038192a758fabff

this is the alsa-info output from my system booted with linux 5.18.0 after i did a couple of hibernate/suspend tries which are also logged in the alsa-dmesg log at the end of the file

b) try to use 'systemctl suspend' instead?

yes i tried it. it's almost the same behaviour again with one difference: when i boot a fresh system (with no anterior hibernation tries or anything) the first systemctl suspend succeeds and after wakeup there are no dsp-dump errors but after this first suspend systemctl suspend keeps failing without any logged error as you can see in this

dmesg1.txt

dmesg-log of several consecutive tries.

c) disable the IMR boot by setting this bit sof-priv.h:#define SOF_DBG_IGNORE_D3_PERSISTENT BIT(7) /* ignore the DSP D3 persistent capability

i've done that. after rebooting i did a sequence of

• suspend (succeeds)
• 2nd suspend (fails without error)
• hibernation (succeeds until error after wakeup)

the corresponding dmesg-log:

dmesg2.txt

[plbossart]

@friedelino I don't understand the comments with 'systemctl suspend', you only added a truncated dmesg log with zero information so it's hard to understand what happens.

please add this file
sof-dyndbg.conf.txt as /etc/modprobe.d/sof-dyndbg.conf (the extension matters), reboot, redo this step b) and attach the entire dmesg log (from the start and a couple of iterations). Thanks!

[mofrim]

I truncated the first log because the relevant information is shown in the truncated Version (there are No Error messages). The 2nd (dmesg2.txt) Log is a full dmesg Log as you requested. Still, i can submit another one tomorrow.

[plbossart]

@friedelino The suspend case is a lot more worrying and should be our first priority. This is what we test on a regular basis and SHOULD work. Hibernate is one step further, more complicated. Let's fix the 'simple' case first, shall we?

[ujfalusi]

@friedelino, please try to attach full logs as hints might be visible outside of the 'interest area'. Can you check simple runtime suspend resume as well (aplay, wait, aplay, wait, ...)?
Please also add the sof-dyndbg.conf so we can see more debug messages to help us rootcause and fix the issue.

It looks to me that the DSP boot sequence was OK (IMR boot is suspected, which does not have much way to fail) but the firmware ready message is not received and that is printing the timeout error. The DSP registers are not telling much which might be an indication of non proper power up of the DSP.

[Noammac]

Hello, I seem to be having the same issue. I installed the sof-dyndbg.conf file and found that even repeated systemctl suspend s would result in a working configuration, but a single systemctl hibernate would break sound and require removing the DSP and rescanning.
Attached are two logs confirming this. It would appear that the problem arises when recovering from RAM image, at least in my experience.
dmesg_log.txt
dmesg_log2.txt

[plbossart]

@Noammac are the two logs both with the hibernate option?

If yes, can you add add this in /etc/modprobe.d/alsa-base.conf

options snd-sof sof_debug=0x41

reboot and re-check, thanks!

[Noammac]

Both logs had attempted a systemctl suspend and then a systemctl hibernate.
New log
new_dmesg_log.txt

[plbossart]

Is the new log with the option above @Noammac ? I still see 'booting from IMR directly'. It could also be that the option is incorrect...

[plbossart]

sorry, my bad @Noammac @friedelino, the command should be

options snd-sof sof_debug=0x81

One day I'll learn how to count to 7.

[Noammac]

Ah lol
Changed setting, and can report that there's no error after hibernation. Log's attached.
another_dmesg_log.txt

[plbossart]

Thanks @Noammac, I am glad this chicken bit added "just in case" solves your problem. Only the paranoid survive, etc.
Just to be clear, can you confirm that you ONLY had a problem with 'systemctl hibernate', and 'systemctl suspend' worked fine for you?

[Noammac]

Can confirm, tried multiple suspends with no issue, and it only became a problem once I attempted to hibernate.

[mofrim]

I also did some more testing. the first round is with sof_debug=0x81 set:

directly after boot: dmesg-afterboot.txt
1st try suspend: dmesg-1st-suspend-try.txt
2nd suspend: dmesg-2nd-suspend-try.txt
1st hibernate: dmesg-hibernate.txt
2nd hibernate: dmesg-hibernate-hibernate.txt

result with 0x81 set -> everything works fine! even hibernation!

the second round is without 0x81:

directly after boot: dmesg-without-0x81.txt
1st try suspend: dmesg-without-0x81-suspend.txt
2nd try suspend dmesg-without-0x81-suspend-suspend.txt

result for suspend without 0x81 -> screen goes blank for a second then on again. suspend does not happen.

then i rebooted and tried hibernation:

1st try: dmesg-without-0x81-hibernate.txt
2nd try: dmesg-without-0x81-hibernate-hibernate.txt

result -> hibernation succeeds 1st try (with error message in dmesg) but not after that.

a little side-note: for the testing i also deactivated my audio-server (pipe-wire atm) in my system config to have only alsa running. i thought maybe this issue could also have something to do with an audio server trying to suspend devices.

[plbossart]

@friedelino I have no explanation for your second results, the IMR boot decision is made on the resume path, there's nothing related to IMR that would prevent the suspend from happening. Wow, that's very very odd.

[plbossart]

@Noammac @friedelino Are you familiar or comfortable with compiling your own kernel? I don't have any devices on which hibernate works, so will have to rely on crowd-sourcing for tests. We have instructions here https://thesofproject.github.io/latest/getting_started/setup_linux/install_locally.html is this helps.

[plbossart]

Tentative fix at thesofproject/linux#3687, test reports welcome.

[mofrim]

@plbossart I managed to compile the thesofproject/linux kernel-fork with your fix thesofproject/linux#3687 and booted it again with dyndbg. I can confirm that hibernate and suspend now function normally. Here are my logs:

1. boot then suspend:
   dmesg-withpatch-suspend.txt

2. boot then hibernate:
   dmesg-withpatch-hibernate.txt

btw: i also was able to pin down the cause for the weird suspend behavior on my laptop i mentioned earlier. it definitely originates from my bluetooth device. when i disabled acpi-wakeup for it, suspend functioned normally.

[plbossart]

Awesome, thanks @friedelino for testing!

[mofrim]

Thanks a lot for your quick response and your fix @plbossart!