All of lore.kernel.org
 help / color / mirror / Atom feed
From: bugzilla-daemon@freedesktop.org
To: dri-devel@lists.freedesktop.org
Subject: [Bug 107278] Raven: pci_pm_resume takes over 1 second
Date: Wed, 18 Jul 2018 14:55:00 +0000	[thread overview]
Message-ID: <bug-107278-502@http.bugs.freedesktop.org/> (raw)


[-- Attachment #1.1: Type: text/plain, Size: 12502 bytes --]

https://bugs.freedesktop.org/show_bug.cgi?id=107278

            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=140700&action=edit
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/

-- 
You are receiving this mail because:
You are the assignee for the bug.

[-- Attachment #1.2: Type: text/html, Size: 14175 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
dri-devel mailing list
dri-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/dri-devel

             reply	other threads:[~2018-07-18 14:55 UTC|newest]

Thread overview: 8+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-07-18 14:55 bugzilla-daemon [this message]
2018-07-18 14:55 ` [Bug 107278] Raven: pci_pm_resume takes over 1 second bugzilla-daemon
2018-07-18 15:27 ` bugzilla-daemon
2018-07-25 13:28 ` bugzilla-daemon
2018-07-25 13:52 ` bugzilla-daemon
2019-11-19  8:44 ` bugzilla-daemon
2019-11-19  8:45 ` bugzilla-daemon
2019-11-20  7:49 ` bugzilla-daemon

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=bug-107278-502@http.bugs.freedesktop.org/ \
    --to=bugzilla-daemon@freedesktop.org \
    --cc=dri-devel@lists.freedesktop.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.