[BUG] MTL firmware does not resume any more

[marc-hb]

As of July 22nd, the current status is: something (IMR heap?) overwrites the firmware code stored in the IMR and used for resuming. That's why not booting from IMR with sof_debug=0x80 avoids the crash.
 

---

To Reproduce

Use audio. Wait. Try to use it again.

Reproduction Rate

100%

Impact

Show stopper

cc:

• [BUG] DSP panic with Zephyr on Intel MTL, regression 27th June #9268

Screenshots or console output

https://sof-ci.01.org/sofpr/PR9305/build6552/devicetest/index.html
https://sof-ci.01.org/softestpr/PR1220/build662/devicetest/index.html

[  161.664059] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  161.664078] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  161.667119] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  161.667125] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[  161.667133] kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-mtl 0000:00:1f.3: Current DSP power state: D0I0
[  161.667138] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 0 -> 2
[  161.667143] kernel: snd_sof:snd_sof_load_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: loading firmware
[  161.667146] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 2 -> 3
[  161.668181] kernel: snd_sof_pci_intel_mtl:mtl_dsp_pre_fw_run: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x1010000 successful
[  161.669221] kernel: snd_sof_pci_intel_mtl:mtl_dsp_pre_fw_run: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1d1c]=0x8151 successful
[  161.669227] kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: booting DSP firmware
[  161.669233] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: IMR restore supported, booting from IMR directly
[  161.670274] kernel: snd_sof_pci_intel_mtl:mtl_dsp_core_power_up: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000101 successful
[  161.670281] kernel: snd_sof_pci_intel_mtl:mtl_dsp_cl_init: sof-audio-pci-intel-mtl 0000:00:1f.3: Primary core power up successful
[  161.670290] kernel: snd_sof_pci_intel_mtl:mtl_dsp_cl_init: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x73214]=0x80000000 successful
[  161.670301] kernel: snd_sof_pci_intel_mtl:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1800]=0x41 successful
[  161.670310] kernel: snd_sof_pci_intel_mtl:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1140]=0x1 successful
[  161.670320] kernel: snd_sof_pci_intel_mtl:mtl_dsp_cl_init: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x163200]=0x50000005 successful
[  163.714303] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  163.714323] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware boot failure due to timeout
[  163.714330] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (3)
[  163.714343] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: 0x50000005: module: ROM_EXT, state: FW_ENTERED, running
[  163.714356] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Firmware state: 0x5, status/error code: 0x0
[  163.714438] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Unknown toolchain is used
[  163.714446] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: DSP Firmware Oops
[  163.714451] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: Exception Cause: AllocaCause, MOVSP instruction, if caller’s registers are not in the register file
[  163.714458] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: EXCCAUSE 0x00000005 EXCVADDR 0x00000004 PS       0x00060020 SAR     0x00000004
[  163.714466] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: EPC1     0xa0088553 EPC2     0x00000000 EPC3     0x00000000 EPC4    0x00000000
[  163.714474] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[  163.714480] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: EPS2     0x00000000 EPS3     0x00000000 EPS4     0x00000000 EPS5    0x00000000
[  163.714486] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00000000
[  163.714492] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: stack dump from 0x00000000
[  163.714498] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: AR registers:
[  163.714506] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: 0x0: a0041e68 a0102688 00000000 a0065c84
[  163.714512] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: 0x10: a0066370 00000001 0000000a a01025c8
[  163.714519] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: 0x20: a0065d65 a0102628 00000001 40150478
[  163.714525] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: 0x30: a0065d65 a0102628 00000001 40150478
[  163.714532] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  163.714538] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed to boot DSP firmware after resume -5
[  163.714547] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 3 -> 4
[  163.714558] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_pm_runtime_get on 0000:00:1f.3: -5
[  163.714569] kernel:  NoCodec-0: ASoC: error at __soc_pcm_open on NoCodec-0: -5
[  163.714578] kernel:  Port0: ASoC: error at dpcm_be_dai_startup on Port0: -5
[  163.714588] kernel:  Port0: ASoC: error at dpcm_fe_dai_startup on Port0: -5

[marc-hb]

Last working daily test run 43924

Start Time: 2024-07-16 13:08:34 UTC
Linux Commit: 1998ade4783a
KConfig Commit: 8189104a4f38
SOF Commit: 3051607efb4f
Zephyr Commit: 650227d8c47f

First failing daily test run 43972

Start Time: 2024-07-17 13:21:12 UTC
Linux Commit: c3ecd35f66c1
KConfig Commit: 8189104a4f38
SOF Commit: d629e521020c
Zephyr Commit: 740d7f735e23

d629e52 serhiy.katsyuba@intel.com // (origin/main) ipc4: copier: Add IPC4 channel map handler
ffce2cb serhiy.katsyuba@intel.com // ipc4: copier: Extend get_convertion_func() to support remapping
eda6029 serhiy.katsyuba@intel.com // dai-zephyr: Prioritize HW params channels over base config params
8082006 serhiy.katsyuba@intel.com // ipc4: pcm_converter: Add channel remapping conversion functions
3199786 serhiy.katsyuba@intel.com // pcm_converter: Add channel map parameter
8b927ad serhiy.katsyuba@intel.com // dai-zephyr: Use frames, not samples, for DMA copy bytes calculation
6e183cb serhiy.katsyuba@intel.com // dai-zephyr: Fix to avoid using buffers with uninitialized stream params
ee66620 serhiy.katsyuba@intel.com // ipc4: dai-zephyr: Do not reuse process func as multi-gateway channel copy
5a000e8 tomasz.m.leman@intel.com // west.yml: update zephyr to 740d7f735e2
3051607 guennadi.liakhovetski@linux.intel.com // kcps: fix 0 module CPC case

_

c3ecd35f66c1 Vijendar.Mukunda@amd.com // !fixup ASoC: amd: acp: fix for unused-but-set-variable warning for amp_num
1998ade4783a pierre-louis.bossart@linux.intel.com // ASoC: SOF: sof-audio.h: optimize snd_sof_pcm_stream_pipeline_list

I checked all the corresponding Pull Requests and they all passed separately.

cc: @serhiy-katsyuba-intel

[lyakh]

@marc-hb the last passing test of 16.07 already includes LLEXT patches as you can also see by following 3051607 and by checking that daily test's logs

[lyakh]

can it be the 5a000e8 Zephyr upgrade?

[fredoh9]

I only reverted LLEXT PR while keeping zephyr upgrade.
FW re-loading worked fine. This is my revert branch, https://github.com/fredoh9/sof/tree/fix/revert

[lyakh]

I only reverted LLEXT PR while keeping zephyr upgrade. FW re-loading worked fine. This is my revert branch, https://github.com/fredoh9/sof/tree/fix/revert

@fredoh9 thanks for checking that! And that isn't surprising, since every PR, merged after LLEXT passed its testing too - on a base that didn't include LLEXT. But apparently one of those PRs conflicts with LLEXT.

[kv2019i]

@lyakh @tmleman can you check this, it's seems it's a combination of LLEXT and Zephyr update. Given where it fails, this could be a new side-effect of the power_down.S changes.