Repository navigation
[BUG]ADL-N DSP firmware download failed due to DMA errors. #3915
Description
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.
Activity
kv2019i commentedon Oct 11, 2022
Let's start on kernel side (moved the bug here from FW).
kv2019i commentedon Oct 11, 2022
Discussed offline that issue not seen with chrome-5.10 kernel. @Vamshigopal to continue bisect recent changes in the 5.15 tree.
kv2019i commentedon Oct 11, 2022
@Vamshigopal One thing to check (discussed with @ranj063 ) is to ensure the stop DMA patches are correctly backported:
Vamshigopal commentedon Oct 11, 2022
@kv2019i we have all the above mentioned patches in the chrome kernel 5.15.
ujfalusi commentedon Oct 11, 2022
I believe this is not directly coming from the audio stack:
I don't know what DMAR is, but it is reporting an error
PTE Read access is not setfor the audio device (00:1f.3) and then we have firmware download timeout with the DMA...Vamshigopal commentedon Oct 11, 2022
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 commentedon Oct 11, 2022
Peter,
What DMA request we are doing suspend path ?
kv2019i commentedon Oct 11, 2022
@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 commentedon Oct 11, 2022
@Vamshigopal, it looks like we are booting up the DSP just to send the PM_GATE message, I think:
Boot fail ^
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 commentedon Oct 11, 2022
@ujfalusi
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 commentedon Oct 12, 2022
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 ?
kv2019i commentedon Oct 13, 2022
The timing is also interesting. Last normal/expected call to SOF driver is here:
2022-10-03T12:38:20.405047Z INFO kernel: [16426.173282] sof-audio-pci-intel-tgl 0000:00:1f.3: PM: calling pci_pm_suspend+0x0/0x1f5 @ 17799, parent: pci0000:00
Next one is:
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
That's 89ms later.
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
That comes ~3091ms later. This is expected and matches the 3sec timeout used by driver.
So it really seems like DMA'ing the FW image is what causes the fault.
@Vamshigopal Have you been able to do any bisect with chromeos-5.15 kernel history? Has this happened for a long time? And also, do you have logs with SOF dynamic debug logs enabled? Maybe something in the FW load setup has gone wrong. Otherwise it seems we need to try to setup a machine for reproduction.
2 remaining items
sathyap-chrome commentedon Oct 19, 2022
Will try with the suggested change.
plbossart commentedon Oct 20, 2022
Maybe a red-herring, but why aren't we using the IMR during suspend-resume tests? This is the recommended configuration, I don't understand why we are attempting to download firmware in S3-S0 transitions.
marc-hb commentedon Oct 20, 2022
I didn't understand how tests had any choice here. @plbossart just explained to me (thx!) that they don't: the choice is made here:
kv2019i commentedon Oct 21, 2022
@plbossart IMR boot is not used due to lack of support in FW in this release. Kernel support is in place.
kv2019i commentedon Oct 21, 2022
A new debug patch is at kv2019i@b993d5f
A normal run (with fault injection disabled looks like):
When the fault happens, logs look like:
I had CONFIG_DMAR_DEBUG=y and CONFIG_INTEL_IOMMU_DEBUGFS=y enabled in above tests.
It would be very interesting to get logs from this issue with similar logging enabled (and DMAR_DEBUG=y).
One curious thing that pops out from this is the fault address "0x10b6fa000" looks very different from what I get in a successful run.
It's upto iommu how to allocate the addresses, so this could be a different configuration, but it would be curious to see similar logs enabled when the problem happens (actual bug, not fault injection), and cross-check whether SOF driver programmed the fault address to hardware or not.
kv2019i commentedon Oct 21, 2022
Patch to only print the programmed HDA DMA addresses -> kv2019i@d04dc9d
Fault injection -> kv2019i@968d3ef
plbossart commentedon Oct 21, 2022
Where is the emoji for "team painting itself in a corner"....
kv2019i commentedon Oct 25, 2022
@kv2019i wrote:
This seems to be related to iommu configuration. I now did experiments on a ADL_N chromebook with 5.15 kernel, applied my debug patch linked above and I can confirm the addresses iommu driver returns look a bit different than in my earlier tests (upstream kernel and different hw).
So fault address of 0x10b6fa000 can indeed be a perfectly valid address iommu driver assigns to us.
marc-hb commentedon Nov 1, 2022
Just for the record; you don't care about this: the sof->linux issue transfer was actually initiated on October 25th or earlier but then it stayed stuck at "This issue is being transferred. Timeline may not be complete until it finishes." for days. I filed (private) support ticket https://support.github.com/ticket/1847674 where Github support (manually?) completed the transfer.
kv2019i commentedon Nov 4, 2022
Potential issue in upstream ALSA, discussed in https://mailman.alsa-project.org/pipermail/alsa-devel/2022-November/208068.html
kv2019i commentedon Nov 11, 2022
Fix for ALSA memalloc.c available on alsa-devel https://lore.kernel.org/alsa-devel/20221110132216.30605-1-tiwai@suse.de/T/#u
This will avoid the DMAR fault . It is still open why dma_alloc_noncontiguous() fails to begin with (leading to DSP firmware load to fail). This is likely not a SOF driver issue, but keeping this open until we have more data and can make more firm conclusions on the sequence.
kv2019i commentedon Nov 14, 2022
Another issue found with SGT/nonconfig allocs not used when IOMMU is enabled with chromeos-5.15 kernel. More detailed analysis posted to alsa-devel:
https://mailman.alsa-project.org/pipermail/alsa-devel/2022-November/208661.html
kv2019i commentedon Nov 18, 2022
Issue not occuring with upstream kernel, so closing here.