Repository navigation
[BUG] sof-audio-pci-intel-mtl spends 573571us in pci_pm_suspend #8071
Description
Activity
@abonislawski fyi, any idea why IPC would take long time with commit above ?
Could be something with zephyr PM (its old on 005 now) or another issue with IMR context save because Dhara reported me CONFIG_ADSP_IMR_CONTEXT_SAVE=n helps here
yes, with CONFIG_ADSP_IMR_CONTEXT_SAVE=n,
[ 479.871280] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend+0x0/0x20b returned 0 after 138131 usecs
[ 479.975001] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend_late+0x0/0x3e returned 0 after 2 usecs
[ 480.026195] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend_noirq+0x0/0x236 returned 0 after 12138 usecs@RDharageswari can you clarify if the device is already in D3 while doing the suspend? IIRC there is a PCI requirement to go back to D0 before doing a system suspend, so that will clearly take time. If we want to check the suspend time only we need to start from the D0 state. Thanks.
@plbossart the device is in D3 before suspend but the main issue seems to be that the MOD_DX IPC during suspend takes ~300ms to be processed.
ok, but please make sure the D3->D0 time is not included in the analysis, otherwise we will conflate unrelated issues.
@plbossart but why shouldn't we include the D3->D0 time in the analysis. Even if it normal PCI device behavior, the transition is done due to an impending system suspend isnt it?
it's a separate step that we don't control so you want to account for it separately - a global number will likely include more time to resume...
@plbossart It is worth remembering that whenever runtime PM is enabled in Linux, the path of triggering a runtime resume during
pci_pm_suspendwill happen very often. Indeed if I disable runtime PM in Linux for this card, I'm getting suspend times of ~124ms. So the real problem here I presume is the D3->D0 path which is mandatory to prepare for
an s2idle suspend.@semihalf-kardach-stanislaw that's why I asked that we split variables and make sure we have different measurements for pm_runtime D3->D0 and system suspend D0 -> D3, otherwise we can talk forever about different things.
Edit: And btw 124ms to suspend is quite large, there's probably shady things happening here.
@ranj063 wrote:
@plbossart the device is in D3 before suspend but the main issue seems to be that the MOD_DX IPC during suspend takes ~300ms to be processed.
This is expected as we need to save DSP memory contents to IMR and this will take time
Can I propose we disable this feature (CONFIG_ADSP_IMR_CONTEXT_SAVE=n) for Chrome builds as the feature is not really needed (in Chrome). The Linux kernel has functionality to save stream states upon suspend (and even this only happens if you have paused streams when system goes to suspend, and this is another thing that is not used in Chrome by CRAS), so we have no real need to save DSP context (and thus no need to incur the context save cost when doing suspend).
Discussed with @abonislawski @mwasko @lgirdwood and @mengdonglin about this earlier offline, but commenting on this bug as well.
In the dmesg log there are 3 occurrences of sending "enter D3" IPC. Responses took 156 ms, 298 ms and 99 ms. Quite different results each time.
I tried D3 test on Windows machine. Response to "enter D3" IPC there is about 3 ms if CONFIG_ADSP_IMR_CONTEXT_SAVE=n and about 68 ms if CONFIG_ADSP_IMR_CONTEXT_SAVE=y. Note, DSP is running on lowest 38 MHz clock when processing that IPC as pipelines are not running. Results are very consistent if running test multiple times.
In order to enter D3, Zephyr scheduler must reach idle processing. Entering D3 will be postponed until any task/thread is in active state. Maybe we have some component in topology that keeps some task/thread active?
@RDharageswari , what is the topology used to reproduce the issue? Are you able to try to reproduce the issue on some other preferably much simpler topology, e.g., without Google AEC maybe (of course, if you have some other simple topology)?
Do you have firmware logs? These might also show us what is still active in firmware at a time of "enter D3" IPC processing.
i was able to repro this issue without Google AEC module itself, with the simpler topology
i was able to repro this issue without Google AEC module itself, with the simpler topology
@RDharageswari I assume IMR context save was still enabled in your simple test ?
IMR context save has been disabled, software contex save as a workaround was use. (Piority lower to P2)
@RDharageswari what is an acceptable contex save latency on the D3?@RDharageswari What are the current results for this test?
@sathya-nujella are you able to comment or close if @RDharageswari is out ?
Hi,
This issue is fixed with mtl-06 firmware. Sorry for closing the issue late.
dmesg | grep "1f.3: PM: pci_pm_suspend"
[ 451.555631] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend+0x0/0x20b returned 0 after 572713 usecs
[ 451.659567] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend_late+0x0/0x3e returned 0 after 2 usecs
[ 451.711738] sof-audio-pci-intel-mtl 0000:00:1f.3: PM: pci_pm_suspend_noirq+0x0/0x236 returned 0 after 12201 usecs
More logs:
[ 451.260063] sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0xf successful
[ 451.260092] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x47000000|0x0 [data size: 8]
[ 451.552578] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0
[ 451.552715] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x47000000|0x0 [data size: 8]
the tx reply takes about 300msec.
This issue is not seen with mtl-003 FW observed only wiht the
commit 9daaddc (HEAD -> dhara_v5.0.3, tag: releases/mtl/v5.0.3, ranj)
Author: Adrian Bonislawski adrian.bonislawski@intel.com
Date: Tue Jun 27 16:50:42 2023 +0200
dmesg_21.txt
To Reproduce
suspend_stress_test -c 1
Reproduction Rate
100%