From mboxrd@z Thu Jan 1 00:00:00 1970 From: bugzilla-daemon@freedesktop.org Subject: [Bug 107278] Raven: pci_pm_resume takes over 1 second Date: Wed, 18 Jul 2018 14:55:00 +0000 Message-ID: Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="===============0867653751==" Return-path: Received: from culpepper.freedesktop.org (culpepper.freedesktop.org [131.252.210.165]) by gabe.freedesktop.org (Postfix) with ESMTP id F3CE36EB81 for ; Wed, 18 Jul 2018 14:55:00 +0000 (UTC) List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dri-devel-bounces@lists.freedesktop.org Sender: "dri-devel" To: dri-devel@lists.freedesktop.org List-Id: dri-devel@lists.freedesktop.org --===============0867653751== Content-Type: multipart/alternative; boundary="15319257001.f81E.9860" Content-Transfer-Encoding: 7bit --15319257001.f81E.9860 Date: Wed, 18 Jul 2018 14:55:00 +0000 MIME-Version: 1.0 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: http://bugs.freedesktop.org/ Auto-Submitted: auto-generated https://bugs.freedesktop.org/show_bug.cgi?id=3D107278 Bug ID: 107278 Summary: Raven: pci_pm_resume takes over 1 second Product: DRI Version: DRI git Hardware: Other OS: All Status: NEW Severity: normal Priority: medium Component: DRM/AMDgpu Assignee: dri-devel@lists.freedesktop.org Reporter: pmenzel+bugs.freedesktop@molgen.mpg.de Created attachment 140700 --> https://bugs.freedesktop.org/attachment.cgi?id=3D140700&action=3Dedit Linux 4.18-rc5+ messages Profiling the suspend and resume time [1] on a MSI B350M MORTAR (MS-7A37) w= ith 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 aft= er 14 usecs [ 76.483514] pci 0000:38:00.2: calling pci_pm_resume+0x0/0xa0 @ 1672, par= ent: 0000:00:08.1 [ 76.483528] reg-dummy reg-dummy: calling platform_pm_resume+0x0/0x40 @ 1= 653, 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 [butt= on] @ 1653, parent: LNXSYBUS:00 [ 76.483679] button PNP0C0C:00: acpi_button_resume+0x0/0x40 [button] retu= rned 0 after 5 usecs [ 76.483724] xhci_hcd 0000:38:00.3: pci_pm_resume+0x0/0xa0 returned 0 aft= er 173 usecs [ 76.483727] platform PNP0800:00: calling platform_pm_resume+0x0/0x40 @ 1= 653, 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 @ 1= 653, 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 @ 1= 653, 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 [but= ton] @ 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 use= cs [ 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 use= cs [ 76.483883] rtc_cmos 00:02: calling pnp_bus_resume+0x0/0x90 @ 1653, pare= nt: pnp0 [ 76.483934] xhci_hcd 0000:38:00.4: pci_pm_resume+0x0/0xa0 returned 0 aft= er 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 use= cs [ 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 0x000000F40090000= 0). [ 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 1= 751 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] @ 16= 72, parent: ata1 [ 76.488226] scsi host0: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488236] scsi host1: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata2 [ 76.488250] scsi host1: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488260] scsi host2: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata3 [ 76.488274] scsi host2: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488284] scsi host3: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata4 [ 76.488297] scsi host3: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488307] scsi host4: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata5 [ 76.488320] scsi host4: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488330] scsi host5: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata6 [ 76.488343] scsi host5: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488353] scsi host6: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata7 [ 76.488366] scsi host6: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 6 usecs [ 76.488376] scsi host7: calling scsi_bus_resume+0x0/0x20 [scsi_mod] @ 16= 72, parent: ata8 [ 76.488389] scsi host7: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 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] @ 16= 72, parent: ata9 [ 76.488443] scsi host8: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 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] return= ed 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] @ 16= 96, parent: target8:0:0 [ 76.505644] sd 8:0:0:0: scsi_bus_resume+0x0/0x20 [scsi_mod] returned 0 a= fter 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 aft= er 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 accessi= ble [ 76.959799] ata9.00: supports DRM functions and may not be fully accessi= ble [ 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 h= ub 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=E2=80=99d be great to reduce the time. Best would a few milliseconds. [1]: https://github.com/01org/pm-graph/ --=20 You are receiving this mail because: You are the assignee for the bug.= --15319257001.f81E.9860 Date: Wed, 18 Jul 2018 14:55:00 +0000 MIME-Version: 1.0 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: http://bugs.freedesktop.org/ Auto-Submitted: auto-generated
Bug ID 107278
Summary Raven: pci_pm_resume takes over 1 second
Product DRI
Version DRI git
Hardware Other
OS All
Status NEW
Severity normal
Priority medium
Component DRM/AMDgpu
Assignee dri-devel@lists.freedesktop.org
Reporter pmenzel+bugs.freedesktop@molgen.mpg.de 

Created attachment 1407=
00 [details]
Linux 4.18-rc5+ messages

Profiling the suspend and resume time [1] on a MSI B350M MORTAR (MS-7A37) w=
ith
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 @ 17=
31,
parent: 0000:00:08.1
[   76.483499] pcieport 0000:16:01.0: pci_pm_resume+0x0/0xa0 returned 0 aft=
er
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 =
4; 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 [butt=
on]
@ 1653, parent: LNXSYBUS:00
[   76.483679] button PNP0C0C:00: acpi_button_resume+0x0/0x40 [button] retu=
rned
0 after 5 usecs
[   76.483724] xhci_hcd 0000:38:00.3: pci_pm_resume+0x0/0xa0 returned 0 aft=
er
173 usecs
[   76.483727] platform PNP0800:00: calling platform_pm_resume+0x0/0x40 =
4; 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 =
4; 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 &#=
64;
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 =
4; 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 [but=
ton]
@ 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, pa=
rent:
pnp0
[   76.483854] system 00:00: pnp_bus_resume+0x0/0x90 returned 0 after 6 use=
cs
[   76.483862] system 00:01: calling pnp_bus_resume+0x0/0x90 @ 1653, pa=
rent:
pnp0
[   76.483875] system 00:01: pnp_bus_resume+0x0/0x90 returned 0 after 6 use=
cs
[   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 aft=
er
190 usecs
[   76.483943] snd_hda_intel 0000:38:00.6: calling pci_pm_resume+0x0/0xa0 &=
#64;
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 @ 172=
9,
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, pa=
rent:
pnp0
[   76.484302] system 00:03: pnp_bus_resume+0x0/0x90 returned 0 after 3 use=
cs
[   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 0x000000F40090000=
0).
[   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 1=
751
usecs
[   76.486111] serial 00:05: calling pnp_bus_resume+0x0/0x90 @ 1653, pa=
rent:
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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] @ 16=
72,
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 a=
fter
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 a=
fter
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 a=
fter
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 a=
fter
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 a=
fter
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 a=
fter
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 a=
fter
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 a=
fter
6 usecs
[   76.488400]  ata9: calling ata_port_pm_resume+0x0/0x50 [libata] @ 16=
72,
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 a=
fter
8 usecs
[   76.494515] usb usb3: calling usb_dev_resume+0x0/0x10 [usbcore] @ 16=
86,
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] @ 17=
25,
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] @ 17=
25,
parent: 0000:38:00.4
[   76.505392] usb usb6: calling usb_dev_resume+0x0/0x10 [usbcore] @ 16=
98,
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] return=
ed 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 a=
fter
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 aft=
er
54692 usecs
[   76.539456] usb usb1: calling usb_dev_resume+0x0/0x10 [usbcore] @ 16=
72,
parent: 0000:15:00.0
[   76.539484] usb usb2: calling usb_dev_resume+0x0/0x10 [usbcore] @ 17=
12,
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] @ 172=
2,
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] @ 17=
23,
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 accessi=
ble
[   76.959799] ata9.00: supports DRM functions and may not be fully accessi=
ble
[   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 h=
ub 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=E2=80=99d be great to reduce the time. Best would a few milliseconds.

[1]: https://github.com/01or=
g/pm-graph/

You are receiving this mail because:
  • You are the assignee for the bug.
= --15319257001.f81E.9860-- --===============0867653751== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: base64 Content-Disposition: inline X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX18KZHJpLWRldmVs IG1haWxpbmcgbGlzdApkcmktZGV2ZWxAbGlzdHMuZnJlZWRlc2t0b3Aub3JnCmh0dHBzOi8vbGlz dHMuZnJlZWRlc2t0b3Aub3JnL21haWxtYW4vbGlzdGluZm8vZHJpLWRldmVsCg== --===============0867653751==--