[BUG][MTL] S0ix long run failure, Firmware boot failure due to timeout (ROM status: 0x50000005, ROM error: 0x0)

[RDharageswari]

EDIT: the kernel part of this issue has been transferred to newer:

• https://github.com/thesofproject/linux/issues/4608

---

We see this error reported in multiple scenario: One was long run S0ix testing.

[  352.971033] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[  352.979537] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  352.988991] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[  353.001735] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  353.010979] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  353.020423] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[  353.026868] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[  353.035552] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
[  353.045287] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[  353.055497] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled
[  353.063477] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  353.072721] sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
[  689.764439] sof-audio-pci-intel-mtl 0000:00:1f.3: GAIN (UUID: 61BCA9A8-18D0-4A18-8E7B-2639219804B7): No CPC match in the firmware file's manifest (ibs/obs: 768/768)
[  692.922594] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[  692.931113] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  692.940571] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[  692.953325] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  692.962576] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]---------

cc:

• thesofproject/sof#7990
• thesofproject/sof#8007
• thesofproject/sof#8019
• thesofproject/sof#8028
• https://github.com/thesofproject/linux/issues/4608

[marc-hb]

@RDharageswari can you please not ignore the entire bug template? It has a number of specific and important fields.

[RDharageswari]

Hi Marc, Sure.I am trying to get the exact scenario, hence did not update it right.Will update the entire configuration once available

[mengdonglin]

@RDharageswari Can you still reproduce this issue with mtl-005.0.3 (Hot Fix 3) release?

[RDharageswari]

@mengdonglin: No reports of this in the recent days..But @yongzhi1 was able to repro this issue in the PnP set up with mtl-005-hotfix3 release

[macchian]

@mengdonglin , I also found the ipc time out during suspend resume test on customer MTL board. The issue can be reproduced on fw branch mtl-005-drop-stable and mtl-005-hotfix3 as well.

@yongzhi1 , I saw that your linux PR about page fault ASoC: SOF: Intel: MTL: catch invalid IRQ IP ptr thesofproject/sof#4344 Is it relative to this?

...
<3>[  124.809909] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
<3>[  124.818406] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
<3>[  124.830259] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0xe7000000|0x0|0x0, ctl: 0x3
<3>[  124.856211] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
<3>[  124.874460] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
<3>[  124.893443] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
<3>[  124.906717] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
<3>[  124.924700] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
<3>[  124.944330] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
<3>[  124.966038] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled
<3>[  124.982946] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
<4>[  125.001601] sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
<1>[  125.199974] BUG: unable to handle page fault for address: ffffbffbcb40001f
<1>[  125.207668] #PF: supervisor read access in kernel mode

[macchian]

attach the crash logs. kernel.20230815.094120.64594.txt

[mengdonglin]

@macchian @RDharageswari @yongzhi1 This issue seems similar to thesofproject/sof#7990 and thesofproject/sof#8028 that happens with mtl-005.0.3 when CPC-based clock selection and IMR context save are both enabled.

Now for main branch, IMR context save is already enabled and PR of CPC-based clock selection is under review https://github.com/thesofproject/sof/pull/8019

We found on main branch, with both IMR context save and CPC-based clock selection (PR) enabled, we cannot reproduce thesofproject/sof#7990 and thesofproject/sof#8028. Please find details and recipe in https://github.com/thesofproject/sof/issues/7990#issuecomment-1676755248

Maybe you can try this FW recipe of main branch as well?

Or you may try this kernel test PR https://github.com/thesofproject/sof/pull/8007 with MTL-005.0.3 FW? This kernel PR will make FW always run at highest clock by always sending ZERO CPC values to FW?

[macchian]

We found on main branch, with both IMR context save and CPC-based clock selection (PR) enabled, we cannot reproduce thesofproject/sof#7990 and thesofproject/sof#8028. Please find details and recipe in #7990 (comment)

Maybe you can try this FW recipe of main branch as well? @mengdonglin, thanks for your suggestions. Yes, I provided a test mtl fw with PRs thesofproject/sof#8019 on mtl-005-hotfix3 branch. So far the result is positive! The suspend test has run 600+ times until now. Afterwards ODM will run more DUTs when other devices are available.

Or you may try this kernel test PR thesofproject/sof#8007 with MTL-005.0.3 FW? This kernel PR will make FW always run at highest clock by always sending ZERO CPC values to FW? Just a thought, Is thesofproject/sof#8007 a desired fix by always sending ZERO CPC values to FW ?

[lrudyX]

@macchian Could you provide some more information how to reproduce the issue?

[macchian]

@macchian Could you provide some more information how to reproduce the issue?

@lrudyX , the suspend_stress_test tool is specific ChromeOS test tool. I am not sure if the CI relevant check-suspend-resume-with-* can isolate the issue or not.

#suspend_stress_test -c 1500 --record_dmesg_dir=/usr/local/agingLogs --suspend_min=15 --suspend_max=20"

[macchian]

We found on main branch, with both IMR context save and CPC-based clock selection (PR) enabled, we cannot reproduce thesofproject/sof#7990 and thesofproject/sof#8028. Please find details and recipe in #7990 (comment) Maybe you can try this FW recipe of main branch as well? @mengdonglin, thanks for your suggestions. Yes, I provided a test mtl fw with PRs thesofproject/sof#8019 on mtl-005-hotfix3 branch. So far the result is positive! The suspend test has run 600+ times until now. Afterwards ODM will run more DUTs when other devices are available.

@mengdonglin, from latest report, one DUT reproduce it highly reproducible rate. Attach the logs.

kernel.20230815.205835.87076.0.txt

[mengdonglin]

@macchian Thank you for testing the main branch! @abonislawski confirmed that main branch will always run at highest clock as it lack rimage update for CPC values as mtl-005.0.3. Can we say that except for the specific DUT, the reproduce rate of this issue is lower with main branch FW than mtl-005.0.3? And what's the approximate reproduction rate for this specific DUT?

[macchian]

@macchian Thank you for testing the main branch! @abonislawski confirmed that main branch will always run at highest clock as it lack rimage update for CPC values as mtl-005.0.3. Can we say that except for the specific DUT, the reproduce rate of this issue is lower with main branch FW than mtl-005.0.3? And what's the approximate reproduction rate for this specific DUT?

@mengdonglin , I'm afraid that 2 DUTs were randomly failure within 20 cycles from suspend_resume. The 3rd DUT will almost certainly appear. This problem can be easily repeated from customer reports.

Do you recommend the kernel test PR thesofproject/sof#8007 worth to tr yor other PRs recommendation?

[mengdonglin]

@mengdonglin , I'm afraid that 2 DUTs were randomly failure within 20 cycles from suspend_resume. The 3rd DUT will almost certainly appear. This problem can be easily repeated from customer reports.

Do you recommend the kernel test PR thesofproject/sof#8007 worth to tr yor other PRs recommendation? @macchian You needn't try PR thesofproject/sof#8007 with mtl-005.0.3. Because you've already tried with main branch FW that DSP runs at the highest clock, and the issue can still be reproduced. PR thesofproject/sof#8007 just make DSP runs at highest clock with mtl-005.0.3

[kv2019i]

@macchian @mengdonglin It is worth testing with https://github.com/thesofproject/sof/pull/7994 (disables IMR context save)

With the context-save, e.g. a leak in DSP resources will be compounding and lead to errors. So if 7994 has impact to repro rate, this can reveal a lot more information about the bug and help in debug.

[macchian]

@

@macchian @mengdonglin It is worth testing with thesofproject/sof#7994 (disables IMR context save)

With the context-save, e.g. a leak in DSP resources will be compounding and lead to errors. So if 7994 has impact to repro rate, this can reveal a lot more information about the bug and help in debug.

@kv2019i , I setup one device and it's very high reproduce rate no matter enabled or disabled IMR. Almost every time during 20 cycles, the DSP dump reproduce. I could share the remote access to you if you need something to check.

[ 131.013601] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------ [ 131.023065] sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware boot failure due to timeout [ 131.031919] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (3) [ 131.040875] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff [ 131.050595] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0xd000001c, ROM debug error: 0x2328 [ 131.061093] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled [ 131.066218] pcieport 0000:00:06.1: pciehp: Slot(8): No link [ 131.069065] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------

[macchian]

dsp_dump.log

[kv2019i]

Thanks @macchian this now looks a bit different. The DSP fails to boot (versus a IPC timeout before) and there's a ROM debug code:

[  131.023065] sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware boot failure due to timeout
[  131.031919] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (3)
[  131.040875] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
[  131.050595] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0xd000001c, ROM debug error: 0x2328
```

[mengdonglin]

@tmleman Can you help check this failure?

[tmleman]

@tmleman Can you help check this failure?

Ok.

[macchian]

@tmleman Can you help check this failure?

Ok.

Update the mtl-006 fw test result: fails

Can you please check if you can reproduce this issue with new mtl-006 FW release MTL-006 2023WW36? Reproduced. Updating to mtl-006 fw, fw boot failure still occurs in suspend_resume 20 cycles.

And I guess it’s not specific for C0 stepping silicon. @Chiang, Mac Can you help comment if you observed this FW boot failure with B-stepping or C-stepping Si? B stepping Silicon. Currently reported failure devices are all B stepping.

[ 206.492064] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------ [ 206.501314] cros-usbpd-charger cros-usbpd-charger.2.auto: PM: calling platform_pm_resume+0x0/0x43 @ 10277, parent: cros-ec-dev.1.auto [ 206.501394] cros-usbpd-charger cros-usbpd-charger.2.auto: PM: platform_pm_resume+0x0/0x43 returned 0 after 77 usecs [ 206.510751] sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware boot failure due to timeout [ 206.524167] cros-usbpd-logger cros-usbpd-logger.3.auto: PM: calling platform_pm_resume+0x0/0x43 @ 10277, parent: cros-ec-dev.1.auto [ 206.535827] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (3) [ 206.535838] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff [ 206.544681] cros-usbpd-logger cros-usbpd-logger.3.auto: PM: platform_pm_resume+0x0/0x43 returned 0 after 1 usecs [ 206.557896] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0xd000001c, ROM debug error: 0x2328 [ 206.566848] cros-ec-chardev cros-ec-chardev.4.auto: PM: calling platform_pm_resume+0x0/0x43 @ 10277, parent: cros-ec-dev.1.auto [ 206.576562] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled [ 206.587932] cros-ec-chardev cros-ec-chardev.4.auto: PM: platform_pm_resume+0x0/0x43 returned 0 after 0 usecs [ 206.598427] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------ [ 206.598429] sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed to boot DSP firmware after resume -5 [ 206.611261] cros-ec-debugfs cros-ec-debugfs.5.auto: PM: calling platform_pm_resume+0x0/0x43 @ 10277, parent: cros-ec-dev.1.auto [ 206.619217] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 3 -> 4 [ 206.630190] cros-ec-debugfs cros-ec-debugfs.5.auto: PM: platform_pm_resume+0x0/0x43 returned 0 after 2 usecs [ 206.639422] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: dpm_run_callback(): pci_pm_resume+0x0/0xef returns -5 [ 206.639425] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_resume+0x0/0xef returned -5 after 2304330 usecs [ 206.639427] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: failed to resume async: error -5

[macchian]

@mengdonglin @tmleman , reproduce on cav.2.7.

<7>[ 250.447847] PM: resume of devices complete after 562.635 msecs <6>[ 251.109100] pcieport 0000:00:06.1: pciehp: Slot(8): No link <4>[ 252.779716] sched: RT throttling activated <7>[ 261.397621] PM: Finishing wakeup. <6>[ 261.397635] OOM killer enabled. <6>[ 261.401175] Restarting tasks ... done. <5>[ 261.408596] random: crng reseeded on system resumption <12>[ 261.409527] init: cupsd main process ended, respawning <6>[ 261.425122] Resume caused by IRQ 9, acpi <6>[ 261.430721] PM: suspend exit <3>[ 261.905049] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0 <3>[ 261.913530] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------ <3>[ 261.922976] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0xe7000000|0x0|0x0, ctl: 0x3 <3>[ 261.935717] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------ <3>[ 261.944958] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------ <3>[ 261.954395] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout <3>[ 261.960818] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7) <3>[ 261.969484] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff <3>[ 261.979201] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0 <3>[ 261.989419] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled <3>[ 261.997397] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------ <4>[ 262.006640] sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend <1>[ 262.925365] BUG: unable to handle page fault for address: ffff9e99ca80001f <1>[ 262.933064] #PF: supervisor read access in kernel mode <1>[ 262.938810] #PF: error_code(0x0000) - not-present page <6>[ 262.944554] PGD 100000067 P4D 100000067 PUD 10020f067 PMD 166e89067 PTE 0 <4>[ 262.952149] Oops: 0000 [#1] PREEMPT SMP NOPTI <4>[ 262.957014] CPU: 8 PID: 4262 Comm: irq/196-AudioDS Tainted: G U W 6.1.52 thesofproject/sof#79 (HASH:050a 1) <4>[ 262.980429] RIP: 0010:mtl_dsp_check_ipc_irq+0x8e/0xef [snd_sof_intel_hda_common] <4>[ 262.988706] Code: 48 8b 49 20 48 8b 89 98 00 00 00 4c 8b 59 58 48 8d 34 10 48 83 c6 20 4d 85 db 74 0e 48 89 df 41 ff d3 0f 1f 00 41 89 c6 eb 03 <44> 8b 36 66 90 41 83 fe ff 0f 95 c0 41 20 c6 44 89 f0 5b 41 5e 5d <4>[ 263.009693] RSP: 0018:ffff9e99c96afe28 EFLAGS: 00010246

[tmleman]

ROM debug status: 0xd000001c, ROM debug error: 0x2328

Status and error are from bootloader.

status 0x1C : Remove access control (this operation completed successfully), error 0x2328: UNSUPPORTED_BOOT_TYPE

status 0x5 : means that the boot process has ended and DSP has started FW execution.

[tmleman]

@macchian do I understand correctly that on main branch you are getting ipc timeout and rom error is from 006?

[macchian]

@macchian do I understand correctly that on main branch you are getting ipc timeout and rom error is from 006?

Actually, it starts from mtl-005. And reproduced on mtl-006 and cav2.7 as well.

[tmleman]

Actually, it starts from mtl-005. And reproduced on mtl-006 and cav2.7 as well.

cav2.7 is release for TGL from main branch?

[macchian]

Actually, it starts from mtl-005. And reproduced on mtl-006 and cav2.7 as well.

cav2.7 is release for TGL from main branch?

From my understanding, cav2.5 and above release for ADL/RPL/MTL. @mengdonglin , could you comment it ?

[kv2019i]

@tmleman I think @macchian meant SOF2.7 release on MTL hardware.

[kv2019i]

@macchian @tmleman One more test to make is to disable boot from IMR completely. This will cause the FW authentication to be repeated on each DSP boot.

This can be forced with following modprobe.d option (no kernel or FW code change needed):

options snd_sof sof_debug=128

In dmesg, "Attempting iteration %d of Core En/ROM load..." should be seen on every DSP boot when this option is set and dmesg should NOT have "IMR restore supported, booting from IMR directy" logs (if the setting is correctly applied).

This is not a fix as this will slow down the resume/boot process, but if this helps to avoid the problem, this will help to limit the search space for debug.

[macchian]

This can be forced with following modprobe.d option (no kernel or FW code change needed): options snd_sof sof_debug=128

Still reproduce when enabled the sof_debug=0x80.

Attempting iteration %d of Core En/ROM load..." should be seen on every DSP boot when this option is set

@kv2019i , one thing need to confirm, we don't see the logs you mentioned in every DSP boot in dmesg, could you confirm what is missed or it's expected behavior not printed?

[ 1611.353547] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0 [ 1611.362027] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------ [ 1611.371472] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0xe7000000|0x0|0x0, ctl: 0x3 [ 1611.384202] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------ [ 1611.393443] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------ [ 1611.402877] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout [ 1611.409300] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7) [ 1611.417965] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff [ 1611.427688] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0 [ 1611.437901] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled [ 1611.445877] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------ [ 1611.455119] sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend [ 1611.909000] pcieport 0000:00:06.1: pciehp: Slot(8): Card present [ 1611.915775] BUG: unable to handle page fault for address: ffffa2928b40001f [ 1611.923463] #PF: supervisor read access in kernel mode [ 1611.929208] #PF: error_code(0x0000) - not-present page [ 1611.934952] PGD 100000067 P4D 100000067 PUD 10020f067 PMD 1225f9067 PTE 0 [ 1611.942543] Oops: 0000 [#1] PREEMPT SMP NOPTI