https://bugzilla.kernel.org/show_bug.cgi?id=200591
Bug ID: 200591
Summary: acpi_set_current_resources() takes over 700 ms during
resume from ACPI S3
Product: ACPI
Version: 2.5
Kernel Version: 4.18-rc5+
Hardware: All
OS: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
Assignee: [email protected]
Reporter: [email protected]
Regression: No
Created attachment 277399
--> https://bugzilla.kernel.org/attachment.cgi?id=277399&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+,
PNP0501 [00:05] resume takes 1.18 s, which is too long.
> serial @ PNP0501 [00:05] {serial} sync_device (Total Suspend: 0.562 ms Total
> Resume: 1188.025 ms)
[ 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
[ 77.674145] serial 00:05: pnp_bus_resume+0x0/0x90 returned 0 after 1160179
usecs
pnpacpi_set_resources (1.377 ms @ 76.486115)
• is_acpi_device_node
• acpi_has_method (0.001 ms @ 76.486115)
• pnpacpi_build_resource_template (0.613 ms @ 76.486117)
• pnpacpi_encode_resources (0.000 ms @ 76.486730)
• acpi_set_current_resources (0.761 ms @ 76.486731)
I am assuming that the resume can happen in parallel, right? So the problem is
*not* that other devices resume too, correct?
--
You are receiving this mail because:
You are watching the assignee of the bug.
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
acpi-bugzilla mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/acpi-bugzilla
