Re: `pci_apply_final_quirks()` taking half a second

[Paul Menzel]

Am 29.12.2017 um 17:14 schrieb Alan Stern:
> On Thu, 28 Dec 2017, Bjorn Helgaas wrote:
>
> > On Tue, Dec 26, 2017 at 04:55:20PM +0100, Paul Menzel wrote:
> > > Am 08.04.2017 um 17:41 schrieb Bjorn Helgaas:
> > > > On Fri, Apr 07, 2017 at 11:07:15PM +0200, Paul Menzel wrote:
> > >
> > > > > Measuring where time is spent during boot with `systemd-bootchart`
> > > > > on an Asus A780FullHD, it turns out that half a second is spent in
> > > > > `pci_apply_final_quirks()`.
> > > >
> > > > I agree, that seems like a crazy amount of time.
> > > >
> > > > Can you figure out how to turn on pr_debug() (via the dynamic debug
> > > > mess or whatever) and boot with "initcall_debug"?  That should tell us
> > > > how long each quirk took.
> > >
> > > I am sorry for taking so long to reply. I finally added `dyndbg=file
> > > quirks.c +p` to the command line of Linux 4.13.13. This is on
> > > another AMD system (Asus F285M Pro).
>
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 197 usecs for
> > > 0000:00:10.0
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 127 usecs for
> > > 0000:00:10.1
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 88643 usecs for
> > > 0000:00:12.0
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 137 usecs for
> > > 0000:00:12.2
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > pci_fixup_amd_ehci_pme+0x0/0x30 returned after 1 usecs for
> > > 0000:00:12.2
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 85770 usecs for
> > > 0000:00:13.0
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 134 usecs for
> > > 0000:00:13.2
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > pci_fixup_amd_ehci_pme+0x0/0x30 returned after 1 usecs for
> > > 0000:00:13.2
> > > Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> > > quirk_usb_early_handoff+0x0/0x6b0 returned after 125 usecs for
> > > 0000:03:00.0[â]
> > > ```
> > >
> > > So itâs `pci fixup quirk_usb_early_handoff` taking around 85 ms, and
> > > that twice.
> >
> > Wow.  That's pretty painful, but of course I don't know how to fix it.
> >  From looking at quirk_usb_early_handoff(), it may depend on BIOS
> > details.  Maybe the USB folks will have some ideas.
>
> Can we see the output from lspci?  It would help to know what the 12.0
> and 13.0 devices are.

Sorry, that was trimmed from the original message. Here is the output 
from the ASRock A780FullD.

> ```
> $ more /proc/version
> Linux version 4.9.0-0.bpo.2-amd64 (debian-kernel@xxxxxxxxxxxxxxxx)
> (gcc version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Debian 4.9.13-1~bpo8+1 (2017-02-27)
> $ lspci -nn
> 00:00.0 Host bridge [0600]: Advanced Micro Devices, Inc. [AMD] RS780 Host Bridge [1022:9600]
> 00:01.0 PCI bridge [0604]: ASRock Incorporation Device [1849:9602]
> 00:09.0 PCI bridge [0604]: Advanced Micro Devices, Inc. [AMD] RS780/RS880 PCI to PCI bridge (PCIE port 4) [1022:9608]
> 00:0a.0 PCI bridge [0604]: Advanced Micro Devices, Inc. [AMD] RS780/RS880 PCI to PCI bridge (PCIE port 5) [1022:9609]
> 00:11.0 SATA controller [0106]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 SATA Controller [AHCI mode] [1002:4391]
> 00:12.0 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 USB OHCI0 Controller [1002:4397]
> 00:12.1 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0 USB OHCI1 Controller [1002:4398]
> 00:12.2 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 USB EHCI Controller [1002:4396]
> 00:13.0 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 USB OHCI0 Controller [1002:4397]
> 00:13.1 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0 USB OHCI1 Controller [1002:4398]
> 00:13.2 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 USB EHCI Controller [1002:4396]
> 00:14.0 SMBus [0c05]: Advanced Micro Devices, Inc. [AMD/ATI] SBx00 SMBus Controller [1002:4385] (rev 3a)
> 00:14.1 IDE interface [0101]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 IDE Controller [1002:439c]
> 00:14.2 Audio device [0403]: Advanced Micro Devices, Inc. [AMD/ATI] SBx00 Azalia (Intel HDA) [1002:4383]
> 00:14.3 ISA bridge [0601]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 LPC host controller [1002:439d]
> 00:14.4 PCI bridge [0604]: Advanced Micro Devices, Inc. [AMD/ATI] SBx00 PCI to PCI Bridge [1002:4384]
> 00:14.5 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD/ATI] SB7x0/SB8x0/SB9x0 USB OHCI2 Controller [1002:4399]
> 00:18.0 Host bridge [0600]: Advanced Micro Devices, Inc. [AMD] K8 [Athlon64/Opteron] HyperTransport Technology Configuration [1022:1100]
> 00:18.1 Host bridge [0600]: Advanced Micro Devices, Inc. [AMD] K8 [Athlon64/Opteron] Address Map [1022:1101]
> 00:18.2 Host bridge [0600]: Advanced Micro Devices, Inc. [AMD] K8 [Athlon64/Opteron] DRAM Controller [1022:1102]
> 00:18.3 Host bridge [0600]: Advanced Micro Devices, Inc. [AMD] K8 [Athlon64/Opteron] Miscellaneous Control [1022:1103]
> 01:05.0 VGA compatible controller [0300]: Advanced Micro Devices, Inc. [AMD/ATI] RS780 [Radeon HD 3200] [1002:9610]
> 04:00.0 Ethernet controller [0200]: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller
> [10ec:8168] (rev 02)
> ```

So far, this can be reproduce on all AMD systems I have (ASRock 
A780FullHD, ASRock E350M1, Asus F2A85-M Pro).


Kind regards,

Paul