[BUG]ADL-N DSP firmware download failed due to DMA errors.

[Vamshigopal]

Describe the bug
During suspend resume cycling we saw DSP firmware boot failed and DSP cannot come out of D3 during resume.

To Reproduce
run suspend_stress_test -c 1000

Reproduction Rate
Sporadic
2/10 boards and 1/500 cycles

Expected behavior
No issue on the suspend test.

Actual result
suspend test failes due to DSP firmware load failure

Impact
What impact does this issue have on your progress (e.g., annoyance, showstopper)

Environment
kernel:
v5.15 chrome kernel
SOF-firmware:
origin/adl-004-drop-stable

Screenshots or console output
2022-10-03T12:38:20.406290Z ERR kernel: [16426.262569] DMAR: DRHD: handling fault status reg 3
2022-10-03T12:38:20.406293Z ERR kernel: [16426.262584] DMAR: [DMA Read NO_PASID] Request device [00:1f.3] fault addr 0x10b6fa000 [fault reason 0x06] PTE Read access is not set
2022-10-03T12:38:20.406296Z INFO kernel: [16426.323788] usb usb1: PM: usb_dev_suspend+0x0/0x14 returned 0 after 143547 usecs
2022-10-03T12:38:20.406299Z INFO kernel: [16426.345773] usb usb2: PM: usb_dev_suspend+0x0/0x14 returned 0 after 165623 usecs
2022-10-03T12:38:20.406301Z INFO kernel: [16426.345861] xhci_hcd 0000:00:0d.0: PM: calling pci_pm_suspend+0x0/0x1f5 @ 31313, parent: pci0000:00
2022-10-03T12:38:20.406428Z INFO kernel: [16426.345993] xhci_hcd 0000:00:0d.0: PM: pci_pm_suspend+0x0/0x1f5 returned 0 after 104 usecs
2022-10-03T12:38:20.406437Z ERR kernel: [16429.264528] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_cl_copy_fw: timeout with rom_status_reg (0x80000) read
2022-10-03T12:38:20.406440Z ERR kernel: [16429.265016] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_trigger: cmd 0 on – (Playback, stream_tag: 1): timeout on STREAM_SD_OFFSET read
2022-10-03T12:38:20.406442Z ERR kernel: [16429.265028] sof-audio-pci-intel-tgl 0000:00:1f.3: error: DMA trigger stop failed
2022-10-03T12:38:20.406445Z ERR kernel: [16429.265036] sof-audio-pci-intel-tgl 0000:00:1f.3: -----------[ DSP dump start ]-----------
2022-10-03T12:38:20.406448Z ERR kernel: [16429.265043] sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware download failed
2022-10-03T12:38:20.406450Z ERR kernel: [16429.265050] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
2022-10-03T12:38:20.406453Z ERR kernel: [16429.265082] sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status: 0x5000001 0x0 0x0 0x0 0x0 0x0 0x2560542 0x0
2022-10-03T12:38:20.406456Z ERR kernel: [16429.265090] sof-audio-pci-intel-tgl 0000:00:1f.3: -----------[ DSP dump end ]-----------
2022-10-03T12:38:20.406458Z ERR kernel: [16429.265337] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to start DSP
2022-10-03T12:38:20.406461Z ERR kernel: [16429.265344] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
2022-10-03T12:38:20.406465Z ERR kernel: [16429.265380] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_tx_msg_unlocked: ipc message send for 0x40080000 failed: -19
2022-10-03T12:38:20.406468Z ERR kernel: [16429.265390] sof-audio-pci-intel-tgl 0000:00:1f.3: error: PM_GATE ipc error -19
2022-10-03T12:38:20.406470Z ERR kernel: [16429.265417] sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set requested target DSP state 0 substate 1
2022-10-03T12:38:20.406473Z ERR kernel: [16429.265425] sof-audio-pci-intel-tgl 0000:00:1f.3: error: setting dsp state 0 substate 1
2022-10-03T12:38:20.406475Z ERR kernel: [16429.265431] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to power down DSP during suspend -19
2022-10-03T12:38:20.406478Z ERR kernel: [16429.265438] PM: pci_pm_suspend(): snd_sof_suspend+0x0/0x11 [snd_sof] returns -19
2022-10-03T12:38:20.406480Z ERR kernel: [16429.265463] PM: dpm_run_callback(): pci_pm_suspend+0x0/0x1f5 returns -19
2022-10-03T12:38:20.406483Z INFO kernel: [16429.265478] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: pci_pm_suspend+0x0/0x1f5 returned -19 after 3090620 usecs
2022-10-03T12:38:20.406486Z ERR kernel: [16429.265498] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: failed to suspend async: error -19
2022-10-03T12:38:20.406488Z DEBUG kernel: [16429.265692] PM: suspend of devices aborted after 3104.767 msecs
2022-10-03T12:38:20.406491Z DEBUG kernel: [16429.265707] PM: start suspend of devices aborted after 3105.438 msecs
2022-10-03T12:38:20.406494Z ERR kernel: [16429.265714] PM: Some devices failed to suspend, or early wake event detected

**logs
messages.zip
We have captured full logs , from line no 460461 we have seen issue.

[kv2019i]

Let's start on kernel side (moved the bug here from FW).

[kv2019i]

Discussed offline that issue not seen with chrome-5.10 kernel. @Vamshigopal to continue bisect recent changes in the 5.15 tree.

[kv2019i]

@Vamshigopal One thing to check (discussed with @ranj063 ) is to ensure the stop DMA patches are correctly backported:

69acac569031426e2ab9b5244593b60d0c9abd04 ASoC: SOF: Intel: hda: send DAI_CONFIG IPC during pause
a0f84dfb3f6d9f78f862cbe885036d3e4449fc6f ASoC: SOF: IPC: dai: Expand DAI_CONFIG IPC flags
0b639dcd457b1d3fc660e5a77b02cf65acde3b5a ASoC: SOF: align the hw_free sequence with stop
85d7acd0ef18725b1d3a7980eee8b84d46296b91 ASoC: SOF: pcm: move the check for prepared flag
d9a7246534753efa383ad8d05ab3691df846c4b4 ASoC: SOF: Add a helper for freeing PCM stream
47934e0fcbbe2bf488bcae2d68431b9ea5972488 ASoC: SOF: call platform hw_free for paused streams during suspend
0dd71a3340b92b503278af4565156f086ccbca3f ASoC: SOF: pcm: invoke platform hw_free for STOP/SUSPEND triggers
4794601a52d40a425542be1b88f8f5614fcf45b4 ASoC: SOF: Intel: hda: reset stream before coupling host and link DMA's
2b1acedccf36434924ae530410e008e7eb427cd3 ASoC: SOF: Intel: hda: Add a helper function for stream reset
e14cddc5888418cc9f2ba66c01a04cdbab3b5b25 ASoC: SOF: Intel: hda: clear stream before freeing the DAI widget

[Vamshigopal]

@kv2019i we have all the above mentioned patches in the chrome kernel 5.15.

[ujfalusi]

I believe this is not directly coming from the audio stack:

2022-10-03T12:38:20.406290Z ERR kernel: [16426.262569] DMAR: DRHD: handling fault status reg 3
2022-10-03T12:38:20.406293Z ERR kernel: [16426.262584] DMAR: [DMA Read NO_PASID] Request device [00:1f.3] fault addr 0x10b6fa000 [fault reason 0x06] PTE Read access is not set

I don't know what DMAR is, but it is reporting an error PTE Read access is not set for the audio device (00:1f.3) and then we have firmware download timeout with the DMA...

[Vamshigopal]

iommu driver is throwing this error because audio device is requesting fault address, we need to understand couple of things
what is the address range for audio device
where this addr 0x10b6fa000 comes from and whether its falling in the given range for audio device.

[Vamshigopal]

Peter,
What DMA request we are doing suspend path ?

[kv2019i]

@Vamshigopal Before the error, the audio driver has kicked the audio (HDA) DMA to transfer the DSP image from host DDR, and is waiting for the ADSP ROM to signal boot completion (which it in normal case does after it has received the image, verified the signature and booted into the newly loaded FW). The address 0x10b6fa000 doesn't ring any immediate bells. ADSP should only be accessing the kernel memory where the FW image is loaded (as loaded by request_firmware() in kernel). We've never seen any such error in the past.

[ujfalusi]

@Vamshigopal, it looks like we are booting up the DSP just to send the PM_GATE message, I think:

2022-10-03T12:38:20.406437Z ERR kernel: [16429.264528] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_cl_copy_fw: timeout with rom_status_reg (0x80000) read
2022-10-03T12:38:20.406440Z ERR kernel: [16429.265016] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_trigger: cmd 0 on -- (Playback, stream_tag: 1): timeout on STREAM_SD_OFFSET read
2022-10-03T12:38:20.406442Z ERR kernel: [16429.265028] sof-audio-pci-intel-tgl 0000:00:1f.3: error: DMA trigger stop failed
2022-10-03T12:38:20.406445Z ERR kernel: [16429.265036] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
2022-10-03T12:38:20.406448Z ERR kernel: [16429.265043] sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware download failed
2022-10-03T12:38:20.406450Z ERR kernel: [16429.265050] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
2022-10-03T12:38:20.406453Z ERR kernel: [16429.265082] sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x2560542 0x0
2022-10-03T12:38:20.406456Z ERR kernel: [16429.265090] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
2022-10-03T12:38:20.406458Z ERR kernel: [16429.265337] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to start DSP
2022-10-03T12:38:20.406461Z ERR kernel: [16429.265344] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110

Boot fail ^

2022-10-03T12:38:20.406465Z ERR kernel: [16429.265380] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_tx_msg_unlocked: ipc message send for 0x40080000 failed: -19
2022-10-03T12:38:20.406468Z ERR kernel: [16429.265390] sof-audio-pci-intel-tgl 0000:00:1f.3: error: PM_GATE ipc error -19
2022-10-03T12:38:20.406470Z ERR kernel: [16429.265417] sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set requested target DSP state 0 substate 1
2022-10-03T12:38:20.406473Z ERR kernel: [16429.265425] sof-audio-pci-intel-tgl 0000:00:1f.3: error: setting dsp state 0 substate 1
2022-10-03T12:38:20.406475Z ERR kernel: [16429.265431] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to power down DSP during suspend -19

And because of that the PM_GATE message is failed.

The PM_GATE is sent with no_pm flag, it should not wake up the DSP to boot, but the -19 is ENODEV, which is what is returned if the DSP is not in booted state or the IPC is disabled.

Something is waking up the device on suspend which triggers a firmware boot and this fails (because other devices have already been put to suspend?), a bit later the suspend is called for the audio device as the kernel thinks it is powered up and we fail to send the PM_GATE since the firmware is not booted and this error (-19) propagates to pm core.

But what is triggering the boot? Can it be the previous resume and we just got the timeout in time of the next suspend?

[Vamshigopal]

@ujfalusi

But what is triggering the boot? Can it be the previous resume and we just got the timeout in time of the next suspend?

Seeing the logs, audio driver exited previous resumes cleanly.
[16390.288994] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: pci_pm_resume+0x0/0xf3 returned 0 after 163732 usecs

I do agree that just before failure suspend, something is keeping the DSP busy.

[sathyap-chrome]

Hi @ujfalusi / @kv2019i

I think the PM gate IPC failure is in the next cycle.

We might need to find the cause for this

2022-10-03T12:38:20.406293Z ERR kernel: [16426.262584] DMAR: [DMA Read NO_PASID] Request device [00:1f.3] fault addr 0x10b6fa000 [fault reason 0x06] PTE Read access is not set >> What is audio device trying to read here ?

When this print comes, we are already in suspend path. We can see from the below print and logs
2022-10-03T12:38:17.007329Z INFO kernel: [16426.141955] PM: suspend entry (s2idle)

Note that the earlier PM suspend and resume was fine and no audio errors seen
Below is the previous resume
2022-10-03T12:37:41.269253Z INFO kernel: [16390.393009] PM: suspend exit

So we were successful in Nth CYCLE.
In N+1th suspend cycle, there is a DMAR error as we tried to read / access something we are not supposed to
In N+1th resume onwards, DSP unable to boot and hence FW load fails and subsequent suspends all fail.

We might need to find the few DMA requests we make in suspend path and instrument suspend path for finding root cause ?