Bug 107278

Summary: Raven: pci_pm_resume takes over 1 second
Product: DRI Reporter: Paul Menzel <pmenzel+bugs.freedesktop.org>
Component: DRM/AMDgpuAssignee: Default DRI bug account <dri-devel>
Status: RESOLVED MOVED QA Contact:
Severity: enhancement    
Priority: medium CC: pmenzel+bugs.freedesktop.org
Version: DRI git   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Bug Depends on: 107375, 107376    
Bug Blocks:    
Attachments:
Description Flags
Linux 4.18-rc5+ messages
none
HTML output of `sudo ./sleepgraph.py -config config/suspend-callgraph.cfg -maxdepth=5` none

Description Paul Menzel 2018-07-18 14:55:00 UTC 
Created attachment 140700 [details]
Linux 4.18-rc5+ messages

Profiling the suspend and resume time [1] on a MSI B350M MORTAR (MS-7A37) with AMD Ryzen 3 2200G with Radeon Vega Graphics with Linux 4.18-rc5+, `pci_pm_suspend()` takes over one second, which is too long.

[   76.483494] amdgpu 0000:38:00.0: calling pci_pm_resume+0x0/0xa0 @ 1731, parent: 0000:00:08.1
[   76.483499] pcieport 0000:16:01.0: pci_pm_resume+0x0/0xa0 returned 0 after 14 usecs
[   76.483514] pci 0000:38:00.2: calling pci_pm_resume+0x0/0xa0 @ 1672, parent: 0000:00:08.1
[   76.483528] reg-dummy reg-dummy: calling platform_pm_resume+0x0/0x40 @ 1653, parent: platform
[   76.483530] pci 0000:38:00.2: pci_pm_resume+0x0/0xa0 returned 0 after 9 usecs
[   76.483540] xhci_hcd 0000:38:00.3: calling pci_pm_resume+0x0/0xa0 @ 1672, parent: 0000:00:08.1
[   76.483543] reg-dummy reg-dummy: platform_pm_resume+0x0/0x40 returned 0 after 5 usecs
[   76.483667] button PNP0C0C:00: calling acpi_button_resume+0x0/0x40 [button] @ 1653, parent: LNXSYBUS:00
[   76.483679] button PNP0C0C:00: acpi_button_resume+0x0/0x40 [button] returned 0 after 5 usecs
[   76.483724] xhci_hcd 0000:38:00.3: pci_pm_resume+0x0/0xa0 returned 0 after 173 usecs
[   76.483727] platform PNP0800:00: calling platform_pm_resume+0x0/0x40 @ 1653, parent: 0000:00:14.3
[   76.483733] xhci_hcd 0000:38:00.4: calling pci_pm_resume+0x0/0xa0 @ 1672, parent: 0000:00:08.1
[   76.483739] platform PNP0800:00: platform_pm_resume+0x0/0x40 returned 0 after 5 usecs
[   76.483748] platform PNP0C0C:00: calling platform_pm_resume+0x0/0x40 @ 1653, parent: platform
[   76.483759] platform PNP0C0C:00: platform_pm_resume+0x0/0x40 returned 0 after 4 usecs
[   76.483767] platform AMDI0030:00: calling platform_pm_resume+0x0/0x40 @ 1653, parent: platform
[   76.483778] platform AMDI0030:00: platform_pm_resume+0x0/0x40 returned 0 after 4 usecs
[   76.483791] platform PNP0103:00: calling platform_pm_resume+0x0/0x40 @ 1653, parent: platform
[   76.483802] platform PNP0103:00: platform_pm_resume+0x0/0x40 returned 0 after 4 usecs
[   76.483813] button LNXPWRBN:00: calling acpi_button_resume+0x0/0x40 [button] @ 1653, parent: LNXSYSTM:00
[   76.483825] button LNXPWRBN:00: acpi_button_resume+0x0/0x40 [button] returned 0 after 5 usecs
[   76.483841] system 00:00: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.483854] system 00:00: pnp_bus_resume+0x0/0x90 returned 0 after 6 usecs
[   76.483862] system 00:01: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.483875] system 00:01: pnp_bus_resume+0x0/0x90 returned 0 after 6 usecs
[   76.483883] rtc_cmos 00:02: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.483934] xhci_hcd 0000:38:00.4: pci_pm_resume+0x0/0xa0 returned 0 after 190 usecs
[   76.483943] snd_hda_intel 0000:38:00.6: calling pci_pm_resume+0x0/0xa0 @ 1672, parent: 0000:00:08.1
[   76.484150] ahci 0000:39:00.0: calling pci_pm_resume+0x0/0xa0 @ 1730, parent: 0000:00:08.2
[   76.484222] ahci 0000:39:00.0: pci_pm_resume+0x0/0xa0 returned 0 after 66 usecs
[   76.484234] r8169 0000:18:00.0: calling pci_pm_resume+0x0/0xa0 @ 1729, parent: 0000:16:01.0
[   76.484291] rtc_cmos 00:02: pnp_bus_resume+0x0/0x90 returned 0 after 393 usecs
[   76.484296] system 00:03: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.484302] system 00:03: pnp_bus_resume+0x0/0x90 returned 0 after 3 usecs
[   76.484307] parport_pc 00:04: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.485185] [drm] PCIE GART of 1024M enabled (table at 0x000000F400900000).
[   76.485220] [drm] PSP is resuming...
[   76.486099] parport_pc 00:04: activated
[   76.486105] parport_pc 00:04: pnp_bus_resume+0x0/0x90 returned 0 after 1751 usecs
[   76.486111] serial 00:05: calling pnp_bus_resume+0x0/0x90 @ 1653, parent: pnp0
[   76.487493] serial 00:05: activated
[   76.487975] snd_hda_intel 0000:38:00.6: pci_pm_resume+0x0/0xa0 returned 0 after 3933 usecs
[   76.487995]  ata1: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488016]  ata1: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 12 usecs
[   76.488025]  ata2: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488043]  ata2: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 10 usecs
[   76.488052]  ata3: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488070]  ata3: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488079]  ata4: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488096]  ata4: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488105]  ata5: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488122]  ata5: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488131]  ata6: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488149]  ata6: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 10 usecs
[   76.488158]  ata7: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488175]  ata7: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488184]  ata8: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:15:00.1
[   76.488201]  ata8: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488212] scsi host0: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata1
[   76.488226] scsi host0: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488236] scsi host1: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata2
[   76.488250] scsi host1: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488260] scsi host2: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata3
[   76.488274] scsi host2: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488284] scsi host3: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata4
[   76.488297] scsi host3: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488307] scsi host4: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata5
[   76.488320] scsi host4: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488330] scsi host5: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata6
[   76.488343] scsi host5: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488353] scsi host6: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata7
[   76.488366] scsi host6: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488376] scsi host7: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata8
[   76.488389] scsi host7: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 6 usecs
[   76.488400]  ata9: calling ata_port_pm_resume+0x0/0x50 [libata] @ 1672, parent: 0000:39:00.0
[   76.488417]  ata9: ata_port_pm_resume+0x0/0x50 [libata] returned 0 after 9 usecs
[   76.488426] scsi host8: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1672, parent: ata9
[   76.488443] scsi host8: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 8 usecs
[   76.494515] usb usb3: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1686, parent: 0000:38:00.3
[   76.494902] usb usb3: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 366 usecs
[   76.494961] usb usb4: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1725, parent: 0000:38:00.3
[   76.495281] usb usb4: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 294 usecs
[   76.495320] usb usb5: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1725, parent: 0000:38:00.4
[   76.505392] usb usb6: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1698, parent: 0000:38:00.4
[   76.505518] usb usb6: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 105 usecs
[   76.505552] scsi target8:0:0: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1721, parent: host8
[   76.505577] scsi target8:0:0: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 10 usecs
[   76.505583] snd_hda_codec_realtek hdaudioC1D0: calling pm_runtime_force_resume+0x0/0xc0 @ 181, parent: 0000:38:00.6
[   76.505598] snd_hda_codec_realtek hdaudioC1D0: pm_runtime_force_resume+0x0/0xc0 returned 0 after 7 usecs
[   76.505612] sd 8:0:0:0: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 1696, parent: target8:0:0
[   76.505644] sd 8:0:0:0: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 after 14 usecs
[   76.505645] sd 8:0:0:0: [sda] Starting disk
[   76.521990] r8169 0000:18:00.0: pci_pm_resume+0x0/0xa0 returned 0 after 36861 usecs
[   76.539426] xhci_hcd 0000:15:00.0: pci_pm_resume+0x0/0xa0 returned 0 after 54692 usecs
[   76.539456] usb usb1: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1672, parent: 0000:15:00.0
[   76.539484] usb usb2: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1712, parent: 0000:15:00.0
[   76.541850] r8169 0000:18:00.0 enp24s0: link down
[   76.553242] usb usb5: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 56543 usecs
[   76.553269] usb 5-1: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1722, parent: usb5
[   76.555075] usb 5-1: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 1755 usecs
[   76.646442] usb usb2: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 104432 usecs
[   76.753730] usb usb1: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 209240 usecs
[   76.754226] usb 1-10: calling usb_dev_resume+0x0/0x10 [usbcore] @ 1723, parent: usb1
[   76.796293] ata6: SATA link down (SStatus 0 SControl 300)
[   76.796728] ata1: SATA link down (SStatus 0 SControl 300)
[   76.797665] ata5: SATA link down (SStatus 0 SControl 300)
[   76.808565] ata2: SATA link down (SStatus 0 SControl 300)
[   76.957819] ata9: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[   76.958976] ata9.00: supports DRM functions and may not be fully accessible
[   76.959799] ata9.00: supports DRM functions and may not be fully accessible
[   76.960392] ata9.00: configured for UDMA/133
[   77.021998] usb 1-10: reset low-speed USB device number 2 using xhci_hcd
[   77.194278] amdgpu: [powerplay] dpm has been enabled
[   77.465520] usb 1-10: usb_dev_resume+0x0/0x10 [usbcore] returned 0 after 694599 usecs
[   77.669669] [drm] VCN decode and encode initialized successfully.
[   77.669702] amdgpu 0000:38:00.0: ring 0(gfx) uses VM inv eng 4 on hub 0
[   77.669709] amdgpu 0000:38:00.0: ring 1(comp_1.0.0) uses VM inv eng 5 on hub 0
[   77.669710] amdgpu 0000:38:00.0: ring 2(comp_1.1.0) uses VM inv eng 6 on hub 0
[   77.669712] amdgpu 0000:38:00.0: ring 3(comp_1.2.0) uses VM inv eng 7 on hub 0
[   77.669714] amdgpu 0000:38:00.0: ring 4(comp_1.3.0) uses VM inv eng 8 on hub 0
[   77.669715] amdgpu 0000:38:00.0: ring 5(comp_1.0.1) uses VM inv eng 9 on hub 0
[   77.669717] amdgpu 0000:38:00.0: ring 6(comp_1.1.1) uses VM inv eng 10 on hub 0
[   77.669719] amdgpu 0000:38:00.0: ring 7(comp_1.2.1) uses VM inv eng 11 on hub 0
[   77.669721] amdgpu 0000:38:00.0: ring 8(comp_1.3.1) uses VM inv eng 12 on hub 0
[   77.669722] amdgpu 0000:38:00.0: ring 9(kiq_2.1.0) uses VM inv eng 13 on hub 0
[   77.669724] amdgpu 0000:38:00.0: ring 10(sdma0) uses VM inv eng 4 on hub 1
[   77.669726] amdgpu 0000:38:00.0: ring 11(vcn_dec) uses VM inv eng 5 on hub 1
[   77.669727] amdgpu 0000:38:00.0: ring 12(vcn_enc0) uses VM inv eng 6 on hub 1
[   77.669729] amdgpu 0000:38:00.0: ring 13(vcn_enc1) uses VM inv eng 7 on hub 1
[   77.673927] amdgpu 0000:38:00.0: pci_pm_resume+0x0/0xa0 returned 0 after 1162525 usecs
```

According to the trace the time is spent in `amdgpu_device_ip_resume_phase2()`.

It’d be great to reduce the time. Best would a few milliseconds.

[1]: https://github.com/01org/pm-graph/
Comment 1 Paul Menzel 2018-07-18 14:55:40 UTC 
Created attachment 140701 [details]
HTML output of `sudo ./sleepgraph.py -config config/suspend-callgraph.cfg -maxdepth=5`
Comment 2 Martin Peres 2019-11-19 08:44:48 UTC 
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/drm/amd/issues/456.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.