* `pci_apply_final_quirks()` taking half a second
@ 2017-04-07 21:07 Paul Menzel
2017-04-08 15:41 ` Bjorn Helgaas
0 siblings, 1 reply; 23+ messages in thread
From: Paul Menzel @ 2017-04-07 21:07 UTC (permalink / raw)
To: linux-pci; +Cc: linux-kernel
Dear Linux folks,
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()`.
Here are the times copied from the SVG:
init_ladder 0.012s
init_menu 0.012s
pm_sysrq_init 0.012s
acpi_init 0.027s
pci_subsys_init 0.008s
hpet_late_init 0.004s
tracer_init_tracefs 0.002s
event_trace_init 0.008s
pnpacpi_init 0.002s
chr_dev_init 0.003s
init_acpi_pm_clocksource 0.004s
pci_apply_final_quirks 0.452s
populate_rootfs 0.400s
pci_iommu_init 0.003s
rsa_init 0.058s
serial8250_init 0.020s
i8042_init 0.003s
load_system_certificate_list 0.002s
ata_init 0.007s
ehci_pci_init 0.030s
ohci_pci_init 0.312s
ahci_pci_driver_init 0.342s
atiixp_pci_driver_init 0.337s
hid_init 0.004s
init_sr 0.031s
I don’t know what information you need, so I just include the Linux
Kernel version, and the output of `lspci -nn`.
```
$ more /proc/version
Linux version 4.9.0-0.bpo.2-amd64 (debian-kernel@lists.debian.org) (gcc
version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Debian 4.9.13-1~bpo8+1 (201
7-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)
```
It’d be great, if the times could be reduced, so that the time from GRUB
to entering the LUKS passphrase gets smaller.
Kind regards,
Paul
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-04-07 21:07 `pci_apply_final_quirks()` taking half a second Paul Menzel
@ 2017-04-08 15:41 ` Bjorn Helgaas
2017-04-08 17:00 ` David Woodhouse
2017-12-26 15:55 ` Paul Menzel
0 siblings, 2 replies; 23+ messages in thread
From: Bjorn Helgaas @ 2017-04-08 15:41 UTC (permalink / raw)
To: Paul Menzel; +Cc: linux-pci, linux-kernel
On Fri, Apr 07, 2017 at 11:07:15PM +0200, Paul Menzel wrote:
> Dear Linux folks,
>
>
> 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.
> Here are the times copied from the SVG:
>
> init_ladder 0.012s
> init_menu 0.012s
> pm_sysrq_init 0.012s
> acpi_init 0.027s
> pci_subsys_init 0.008s
> hpet_late_init 0.004s
> tracer_init_tracefs 0.002s
> event_trace_init 0.008s
> pnpacpi_init 0.002s
> chr_dev_init 0.003s
> init_acpi_pm_clocksource 0.004s
> pci_apply_final_quirks 0.452s
> populate_rootfs 0.400s
> pci_iommu_init 0.003s
> rsa_init 0.058s
> serial8250_init 0.020s
> i8042_init 0.003s
> load_system_certificate_list 0.002s
> ata_init 0.007s
> ehci_pci_init 0.030s
> ohci_pci_init 0.312s
> ahci_pci_driver_init 0.342s
> atiixp_pci_driver_init 0.337s
> hid_init 0.004s
> init_sr 0.031s
>
> I don’t know what information you need, so I just include the Linux
> Kernel version, and the output of `lspci -nn`.
>
> ```
> $ more /proc/version
> Linux version 4.9.0-0.bpo.2-amd64 (debian-kernel@lists.debian.org)
> (gcc version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Debian 4.9.13-1~bpo8+1
> (201
> 7-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)
> ```
>
> It’d be great, if the times could be reduced, so that the time from
> GRUB to entering the LUKS passphrase gets smaller.
>
>
> Kind regards,
>
> Paul
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-04-08 15:41 ` Bjorn Helgaas
@ 2017-04-08 17:00 ` David Woodhouse
2017-04-08 19:06 ` Bjorn Helgaas
2017-12-26 15:55 ` Paul Menzel
1 sibling, 1 reply; 23+ messages in thread
From: David Woodhouse @ 2017-04-08 17:00 UTC (permalink / raw)
To: Bjorn Helgaas, Paul Menzel; +Cc: linux-pci, linux-kernel
[-- Attachment #1: Type: text/plain, Size: 971 bytes --]
On Sat, 2017-04-08 at 10:41 -0500, Bjorn Helgaas 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.
It could well be spending a fair amount of time just attempting to
match each device against the list. When I first implemented the table-
based quirks, back in the mists of time, there were relatively few.
Now I wonder if it's worth sorting the list by vendor ID or something,
at least for the common case of the quirks which match on
vendor/device.
I note it's also reading PCI_CACHE_LINE_SIZE From config space for each
device in pci_apply_final_quirks(). How long does that take?
[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 4938 bytes --]
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-04-08 17:00 ` David Woodhouse
@ 2017-04-08 19:06 ` Bjorn Helgaas
2017-05-03 18:42 ` Andy Shevchenko
0 siblings, 1 reply; 23+ messages in thread
From: Bjorn Helgaas @ 2017-04-08 19:06 UTC (permalink / raw)
To: David Woodhouse; +Cc: Paul Menzel, linux-pci, linux-kernel
On Sat, Apr 08, 2017 at 07:00:19PM +0200, David Woodhouse wrote:
> ...
> I note it's also reading PCI_CACHE_LINE_SIZE From config space for each
> device in pci_apply_final_quirks(). How long does that take?
I don't know, but it's pointless on modern PCIe systems where the
Cache Line Size has no effect. It'd be really nice if somebody
cleaned that up and got rid of the read itself and the useless
messages.
Bjorn
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-04-08 19:06 ` Bjorn Helgaas
@ 2017-05-03 18:42 ` Andy Shevchenko
0 siblings, 0 replies; 23+ messages in thread
From: Andy Shevchenko @ 2017-05-03 18:42 UTC (permalink / raw)
To: Bjorn Helgaas; +Cc: David Woodhouse, Paul Menzel, linux-pci, linux-kernel
On Sat, Apr 8, 2017 at 10:06 PM, Bjorn Helgaas <helgaas@kernel.org> wrote:
> On Sat, Apr 08, 2017 at 07:00:19PM +0200, David Woodhouse wrote:
>> ...
>> I note it's also reading PCI_CACHE_LINE_SIZE From config space for each
>> device in pci_apply_final_quirks(). How long does that take?
>
> I don't know, but it's pointless on modern PCIe systems where the
> Cache Line Size has no effect. It'd be really nice if somebody
> cleaned that up and got rid of the read itself and the useless
> messages.
What I can think of is 10ms delay for PM. The laptop might be one of
Intel BayTrails where we have it.
But it's just a guess.
--
With Best Regards,
Andy Shevchenko
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-04-08 15:41 ` Bjorn Helgaas
2017-04-08 17:00 ` David Woodhouse
@ 2017-12-26 15:55 ` Paul Menzel
2017-12-28 21:27 ` Bjorn Helgaas
1 sibling, 1 reply; 23+ messages in thread
From: Paul Menzel @ 2017-12-26 15:55 UTC (permalink / raw)
To: Bjorn Helgaas
Cc: linux-pci, linux-kernel, David Woodhouse, Andy Shevchenko, linux-usb
Dear Bjorn,
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_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:00.0
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_no_pm_reset+0x0/0x20 returned after 0 usecs for 0000:00:01.0
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.0
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.1
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.2
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.3
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.4
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for 0000:00:18.5
Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
pci_fixup_video+0x0/0x110 returned after 4 usecs for 0000:00:01.0
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.
>> Here are the times copied from the SVG:
>>
>> init_ladder 0.012s
>> init_menu 0.012s
>> pm_sysrq_init 0.012s
>> acpi_init 0.027s
>> pci_subsys_init 0.008s
>> hpet_late_init 0.004s
>> tracer_init_tracefs 0.002s
>> event_trace_init 0.008s
>> pnpacpi_init 0.002s
>> chr_dev_init 0.003s
>> init_acpi_pm_clocksource 0.004s
>> pci_apply_final_quirks 0.452s
>> populate_rootfs 0.400s
>> pci_iommu_init 0.003s
>> rsa_init 0.058s
>> serial8250_init 0.020s
>> i8042_init 0.003s
>> load_system_certificate_list 0.002s
>> ata_init 0.007s
>> ehci_pci_init 0.030s
>> ohci_pci_init 0.312s
>> ahci_pci_driver_init 0.342s
>> atiixp_pci_driver_init 0.337s
>> hid_init 0.004s
>> init_sr 0.031s
[…]
>> It’d be great, if the times could be reduced, so that the time from
>> GRUB to entering the LUKS passphrase gets smaller.
Kind regards,
Paul
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2017-12-28 21:27 ` Bjorn Helgaas
0 siblings, 0 replies; 23+ messages in thread
From: Bjorn Helgaas @ 2017-12-28 21:27 UTC (permalink / raw)
To: Paul Menzel
Cc: linux-pci, linux-kernel, David Woodhouse, Andy Shevchenko, linux-usb
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_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:00.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_no_pm_reset+0x0/0x20 returned after 0 usecs for 0000:00:01.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.1
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.2
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.3
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.4
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.5
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> pci_fixup_video+0x0/0x110 returned after 4 usecs for 0000:00:01.0
> 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.
>From the PCI perspective, we could do something like the following to
make slow quirks more noticeable and perhaps provide a little hint
that quirk performance is important.
commit a9eec698db04ccffa1fe43634752220a2fd2108d
Author: Bjorn Helgaas <bhelgaas@google.com>
Date: Thu Dec 28 13:23:03 2017 -0600
PCI: Report quirks that take more than 10ms
When the "initcall_debug" kernel parameter is used, we report the runtime
of each PCI quirk. In addition, report the runtime of any quirk that takes
more than 10ms to execute. The purpose is to make it easier to notice
quirks that slow down boot.
Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
index fd49b976973f..96008ff78a1a 100644
--- a/drivers/pci/quirks.c
+++ b/drivers/pci/quirks.c
@@ -3105,16 +3105,12 @@ DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_INTEL, 0x0e0d, quirk_intel_ntb);
static ktime_t fixup_debug_start(struct pci_dev *dev,
void (*fn)(struct pci_dev *dev))
{
- ktime_t calltime = 0;
-
- dev_dbg(&dev->dev, "calling %pF\n", fn);
if (initcall_debug) {
- pr_debug("calling %pF @ %i for %s\n",
- fn, task_pid_nr(current), dev_name(&dev->dev));
- calltime = ktime_get();
+ dev_info(&dev->dev, "calling %pF @ %i\n",
+ fn, task_pid_nr(current));
}
- return calltime;
+ return ktime_get();
}
static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
@@ -3123,12 +3119,11 @@ static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
ktime_t delta, rettime;
unsigned long long duration;
- if (initcall_debug) {
- rettime = ktime_get();
- delta = ktime_sub(rettime, calltime);
- duration = (unsigned long long) ktime_to_ns(delta) >> 10;
- pr_debug("pci fixup %pF returned after %lld usecs for %s\n",
- fn, duration, dev_name(&dev->dev));
+ rettime = ktime_get();
+ delta = ktime_sub(rettime, calltime);
+ duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+ if (initcall_debug || duration > 10000) {
+ dev_info(&dev->dev, "%pF took %lld usecs\n", fn, duration);
}
}
^ permalink raw reply related [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2017-12-28 21:27 ` Bjorn Helgaas
0 siblings, 0 replies; 23+ messages in thread
From: Bjorn Helgaas @ 2017-12-28 21:27 UTC (permalink / raw)
To: Paul Menzel
Cc: linux-pci, linux-kernel, David Woodhouse, Andy Shevchenko, linux-usb
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_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:00.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_no_pm_reset+0x0/0x20 returned after 0 usecs for 0000:00:01.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.0
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.1
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.2
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.3
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.4
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> quirk_mmio_always_on+0x0/0x10 returned after 0 usecs for
> 0000:00:18.5
> Dez 26 16:21:46 asus-f2a85-pro kernel: pci fixup
> pci_fixup_video+0x0/0x110 returned after 4 usecs for 0000:00:01.0
> 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.
From the PCI perspective, we could do something like the following to
make slow quirks more noticeable and perhaps provide a little hint
that quirk performance is important.
commit a9eec698db04ccffa1fe43634752220a2fd2108d
Author: Bjorn Helgaas <bhelgaas@google.com>
Date: Thu Dec 28 13:23:03 2017 -0600
PCI: Report quirks that take more than 10ms
When the "initcall_debug" kernel parameter is used, we report the runtime
of each PCI quirk. In addition, report the runtime of any quirk that takes
more than 10ms to execute. The purpose is to make it easier to notice
quirks that slow down boot.
Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
index fd49b976973f..96008ff78a1a 100644
--- a/drivers/pci/quirks.c
+++ b/drivers/pci/quirks.c
@@ -3105,16 +3105,12 @@ DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_INTEL, 0x0e0d, quirk_intel_ntb);
static ktime_t fixup_debug_start(struct pci_dev *dev,
void (*fn)(struct pci_dev *dev))
{
- ktime_t calltime = 0;
-
- dev_dbg(&dev->dev, "calling %pF\n", fn);
if (initcall_debug) {
- pr_debug("calling %pF @ %i for %s\n",
- fn, task_pid_nr(current), dev_name(&dev->dev));
- calltime = ktime_get();
+ dev_info(&dev->dev, "calling %pF @ %i\n",
+ fn, task_pid_nr(current));
}
- return calltime;
+ return ktime_get();
}
static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
@@ -3123,12 +3119,11 @@ static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
ktime_t delta, rettime;
unsigned long long duration;
- if (initcall_debug) {
- rettime = ktime_get();
- delta = ktime_sub(rettime, calltime);
- duration = (unsigned long long) ktime_to_ns(delta) >> 10;
- pr_debug("pci fixup %pF returned after %lld usecs for %s\n",
- fn, duration, dev_name(&dev->dev));
+ rettime = ktime_get();
+ delta = ktime_sub(rettime, calltime);
+ duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+ if (initcall_debug || duration > 10000) {
+ dev_info(&dev->dev, "%pF took %lld usecs\n", fn, duration);
}
}
^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-12-28 21:27 ` Bjorn Helgaas
(?)
@ 2017-12-29 16:14 ` Alan Stern
-1 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-29 16:14 UTC (permalink / raw)
To: Bjorn Helgaas
Cc: Paul Menzel, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
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.
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2017-12-29 16:14 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-29 16:14 UTC (permalink / raw)
To: Bjorn Helgaas
Cc: Paul Menzel, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
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.
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2017-12-29 16:14 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-29 16:14 UTC (permalink / raw)
To: Bjorn Helgaas
Cc: Paul Menzel, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
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.
Alan Stern
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2017-12-31 7:18 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2017-12-31 7:18 UTC (permalink / raw)
To: Alan Stern, Bjorn Helgaas
Cc: linux-pci, linux-kernel, David Woodhouse, Andy Shevchenko, linux-usb
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@lists.debian.org)
> (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
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2017-12-31 7:18 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2017-12-31 7:18 UTC (permalink / raw)
To: Alan Stern, Bjorn Helgaas
Cc: linux-pci, linux-kernel, David Woodhouse, Andy Shevchenko, linux-usb
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@lists.debian.org)
> (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
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2017-12-31 7:18 ` Paul Menzel
(?)
@ 2017-12-31 21:16 ` Alan Stern
-1 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-31 21:16 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Sun, 31 Dec 2017, Paul Menzel wrote:
> 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 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 85770 usecs for
> >>> 0000:00:13.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@lists.debian.org)
> > (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: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]
> So far, this can be reproduce on all AMD systems I have (ASRock
> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
So they are OHCI controllers. You could add some debugging statements
to quirk_usb_handoff_ohci() to try and locate the part that's taking so
long.
It's also worth mentioning that the same source file contains lots of
special-case code for AMD and ASmedia hardware. I don't know whether
any of it is involved in the long time delays you are seeing, however.
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2017-12-31 21:16 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-31 21:16 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Sun, 31 Dec 2017, Paul Menzel wrote:
> 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 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 85770 usecs for
> >>> 0000:00:13.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@lists.debian.org)
> > (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: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]
> So far, this can be reproduce on all AMD systems I have (ASRock
> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
So they are OHCI controllers. You could add some debugging statements
to quirk_usb_handoff_ohci() to try and locate the part that's taking so
long.
It's also worth mentioning that the same source file contains lots of
special-case code for AMD and ASmedia hardware. I don't know whether
any of it is involved in the long time delays you are seeing, however.
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2017-12-31 21:16 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2017-12-31 21:16 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Sun, 31 Dec 2017, Paul Menzel wrote:
> 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 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 85770 usecs for
> >>> 0000:00:13.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@lists.debian.org)
> > (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: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]
> So far, this can be reproduce on all AMD systems I have (ASRock
> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
So they are OHCI controllers. You could add some debugging statements
to quirk_usb_handoff_ohci() to try and locate the part that's taking so
long.
It's also worth mentioning that the same source file contains lots of
special-case code for AMD and ASmedia hardware. I don't know whether
any of it is involved in the long time delays you are seeing, however.
Alan Stern
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2018-01-01 10:21 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2018-01-01 10:21 UTC (permalink / raw)
To: Alan Stern
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
Dear Alan,
First, please note, that your mailer (MUA) doesn’t set the references
header, which breaks threading for people not having their own answers
in the inbox.
Am 31.12.2017 um 22:16 schrieb Alan Stern:
> On Sun, 31 Dec 2017, Paul Menzel wrote:
>
>> 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 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 85770 usecs for
>>>>> 0000:00:13.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@lists.debian.org)
>>> (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: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]
>
>> So far, this can be reproduce on all AMD systems I have (ASRock
>> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
>
> So they are OHCI controllers. You could add some debugging statements
> to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> long.
As you suggested debugging statements, I guess the Linux kernel doesn’t
offer other ways to instrument functions without modifying the source code.
Is it possible to only rebuild the module somehow or is the early
handoff stuff not a module?
> It's also worth mentioning that the same source file contains lots of
> special-case code for AMD and ASmedia hardware. I don't know whether
> any of it is involved in the long time delays you are seeing, however.
Thank you for already looking into this. I haven’t had to time to read
the commit messages, which might shed some light into the reasoning.
Kind regards,
Paul
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2018-01-01 10:21 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2018-01-01 10:21 UTC (permalink / raw)
To: Alan Stern
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
Dear Alan,
First, please note, that your mailer (MUA) doesn’t set the references
header, which breaks threading for people not having their own answers
in the inbox.
Am 31.12.2017 um 22:16 schrieb Alan Stern:
> On Sun, 31 Dec 2017, Paul Menzel wrote:
>
>> 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 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 85770 usecs for
>>>>> 0000:00:13.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@lists.debian.org)
>>> (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: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]
>
>> So far, this can be reproduce on all AMD systems I have (ASRock
>> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
>
> So they are OHCI controllers. You could add some debugging statements
> to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> long.
As you suggested debugging statements, I guess the Linux kernel doesn’t
offer other ways to instrument functions without modifying the source code.
Is it possible to only rebuild the module somehow or is the early
handoff stuff not a module?
> It's also worth mentioning that the same source file contains lots of
> special-case code for AMD and ASmedia hardware. I don't know whether
> any of it is involved in the long time delays you are seeing, however.
Thank you for already looking into this. I haven’t had to time to read
the commit messages, which might shed some light into the reasoning.
Kind regards,
Paul
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
2018-01-01 10:21 ` Paul Menzel
(?)
@ 2018-01-01 15:47 ` Alan Stern
-1 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2018-01-01 15:47 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Mon, 1 Jan 2018, Paul Menzel wrote:
> > So they are OHCI controllers. You could add some debugging statements
> > to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> > long.
>
> As you suggested debugging statements, I guess the Linux kernel doesn’t
> offer other ways to instrument functions without modifying the source code.
It does. Look into ftrace, for example. However, ftrace only provides
tracing at the level of function calls (hence the name -- "ftrace" for
"function trace"), not for individual statements within a function.
There are other facilities as well, but none of them are likely to help
here.
> Is it possible to only rebuild the module somehow or is the early
> handoff stuff not a module?
It is not a module.
> > It's also worth mentioning that the same source file contains lots of
> > special-case code for AMD and ASmedia hardware. I don't know whether
> > any of it is involved in the long time delays you are seeing, however.
>
> Thank you for already looking into this. I haven’t had to time to read
> the commit messages, which might shed some light into the reasoning.
Good luck!
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: `pci_apply_final_quirks()` taking half a second
@ 2018-01-01 15:47 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2018-01-01 15:47 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Mon, 1 Jan 2018, Paul Menzel wrote:
> > So they are OHCI controllers. You could add some debugging statements
> > to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> > long.
>
> As you suggested debugging statements, I guess the Linux kernel doesn’t
> offer other ways to instrument functions without modifying the source code.
It does. Look into ftrace, for example. However, ftrace only provides
tracing at the level of function calls (hence the name -- "ftrace" for
"function trace"), not for individual statements within a function.
There are other facilities as well, but none of them are likely to help
here.
> Is it possible to only rebuild the module somehow or is the early
> handoff stuff not a module?
It is not a module.
> > It's also worth mentioning that the same source file contains lots of
> > special-case code for AMD and ASmedia hardware. I don't know whether
> > any of it is involved in the long time delays you are seeing, however.
>
> Thank you for already looking into this. I haven’t had to time to read
> the commit messages, which might shed some light into the reasoning.
Good luck!
Alan Stern
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2018-01-01 15:47 ` Alan Stern
0 siblings, 0 replies; 23+ messages in thread
From: Alan Stern @ 2018-01-01 15:47 UTC (permalink / raw)
To: Paul Menzel
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
On Mon, 1 Jan 2018, Paul Menzel wrote:
> > So they are OHCI controllers. You could add some debugging statements
> > to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> > long.
>
> As you suggested debugging statements, I guess the Linux kernel doesn’t
> offer other ways to instrument functions without modifying the source code.
It does. Look into ftrace, for example. However, ftrace only provides
tracing at the level of function calls (hence the name -- "ftrace" for
"function trace"), not for individual statements within a function.
There are other facilities as well, but none of them are likely to help
here.
> Is it possible to only rebuild the module somehow or is the early
> handoff stuff not a module?
It is not a module.
> > It's also worth mentioning that the same source file contains lots of
> > special-case code for AMD and ASmedia hardware. I don't know whether
> > any of it is involved in the long time delays you are seeing, however.
>
> Thank you for already looking into this. I haven’t had to time to read
> the commit messages, which might shed some light into the reasoning.
Good luck!
Alan Stern
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
* `quirk_usb_handoff_ohci` takes over 73 ms (twice) on AMD system (was: `pci_apply_final_quirks()` taking half a second)
@ 2018-06-24 16:49 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2018-06-24 16:49 UTC (permalink / raw)
To: Alan Stern
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
Dear Alan,
Sorry for the long delay.
Am 31.12.2017 um 22:16 schrieb Alan Stern:
> On Sun, 31 Dec 2017, Paul Menzel wrote:
>
>> 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:
[…]
>>>>> 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@lists.debian.org)
>>> (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: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]
>
>> So far, this can be reproduce on all AMD systems I have (ASRock
>> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
>
> So they are OHCI controllers. You could add some debugging statements
> to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> long.
> 737 static void quirk_usb_handoff_ohci(struct pci_dev *pdev)
> 738 {
> 739 void __iomem *base;
> 740 u32 control;
> 741 u32 fminterval = 0;
> 742 bool no_fminterval = false;
> 743 int cnt;
> 744
> 745 if (!mmio_resource_enabled(pdev, 0))
> 746 return;
> 747
> 748 base = pci_ioremap_bar(pdev, 0);
> 749 if (base == NULL)
> 750 return;
> 751
> 752 /*
> 753 * ULi M5237 OHCI controller locks the whole system when accessing
> 754 * the OHCI_FMINTERVAL offset.
> 755 */
> 756 if (pdev->vendor == PCI_VENDOR_ID_AL && pdev->device == 0x5237)
> 757 no_fminterval = true;
> 758
> 759 control = readl(base + OHCI_CONTROL);
> 760
> 761 printk(KERN_INFO "1\n");
> 762 /* On PA-RISC, PDC can leave IR set incorrectly; ignore it there. */
> 763 #ifdef __hppa__
> 764 #define OHCI_CTRL_MASK (OHCI_CTRL_RWC | OHCI_CTRL_IR)
> 765 #else
> 766 #define OHCI_CTRL_MASK OHCI_CTRL_RWC
> 767
> 768 if (control & OHCI_CTRL_IR) {
> 769 int wait_time = 500; /* arbitrary; 5 seconds */
> 770 writel(OHCI_INTR_OC, base + OHCI_INTRENABLE);
> 771 writel(OHCI_OCR, base + OHCI_CMDSTATUS);
> 772 while (wait_time > 0 &&
> 773 readl(base + OHCI_CONTROL) & OHCI_CTRL_IR) {
> 774 wait_time -= 10;
> 775 msleep(10);
> 776 }
> 777 if (wait_time <= 0)
> 778 dev_warn(&pdev->dev,
> 779 "OHCI: BIOS handoff failed (BIOS bug?) %08x\n",
> 780 readl(base + OHCI_CONTROL));
> 781 }
> 782 #endif
> 783
> 784 printk(KERN_INFO "2\n");
> 785 /* disable interrupts */
> 786 writel((u32) ~0, base + OHCI_INTRDISABLE);
> 787
> 788 printk(KERN_INFO "3\n");
> 789 /* Reset the USB bus, if the controller isn't already in RESET */
> 790 if (control & OHCI_HCFS) {
> 791 /* Go into RESET, preserving RWC (and possibly IR) */
> 792 writel(control & OHCI_CTRL_MASK, base + OHCI_CONTROL);
> 793 readl(base + OHCI_CONTROL);
> 794
> 795 /* drive bus reset for at least 50 ms (7.1.7.5) */
> 796 msleep(50);
> 797 }
> 798 printk(KERN_INFO "4\n");
> 799
> 800 /* software reset of the controller, preserving HcFmInterval */
> 801 if (!no_fminterval)
> 802 fminterval = readl(base + OHCI_FMINTERVAL);
> 803
> 804 writel(OHCI_HCR, base + OHCI_CMDSTATUS);
> 805 printk(KERN_INFO "5\n");
> 806
> 807 /* reset requires max 10 us delay */
> 808 for (cnt = 30; cnt > 0; --cnt) { /* ... allow extra time */
> 809 printk(KERN_INFO "6 cnt = %d\n", cnt);
> 810 if ((readl(base + OHCI_CMDSTATUS) & OHCI_HCR) == 0)
> 811 break;
> 812 udelay(1);
> 813 }
> 814
> 815 printk(KERN_INFO "7\n");
> 816 if (!no_fminterval)
> 817 writel(fminterval, base + OHCI_FMINTERVAL);
> 818
> 819 /* Now the controller is safely in SUSPEND and nothing can wake it up */
> 820 iounmap(base);
> 821 }
Here is the result.
> [ 0.062796] pci 0000:00:12.0: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.062860] 1
> [ 0.086662] 2
Around 24 ms are spent in the loop checking `readl(base + OHCI_CONTROL)
& OHCI_CTRL_IR)` in line 772.
> [ 0.086663] 3
> [ 0.138645] 4
That’s the 50 ms from resetting the USB bus, if the controller isn't
already in RESET in line 796.
> [ 0.138647] 5
> [ 0.138649] 6 cnt = 30
> [ 0.138650] 7
> [ 0.138771] pci 0000:00:12.0: quirk_usb_early_handoff+0x0/0x700 took 74188 usecs
> [ 0.138778] pci 0000:00:12.2: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.138917] pci 0000:00:12.2: quirk_usb_early_handoff+0x0/0x700 took 133 usecs
> [ 0.138919] pci 0000:00:12.2: calling pci_fixup_amd_ehci_pme+0x0/0x30 @ 1
> [ 0.138920] pci 0000:00:12.2: PME# does not work under D3, disabling it
> [ 0.138922] pci 0000:00:12.2: pci_fixup_amd_ehci_pme+0x0/0x30 took 0 usecs
> [ 0.138926] pci 0000:00:13.0: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.138987] 1
> [ 0.161639] 2
> [ 0.161640] 3
> [ 0.213622] 4
> [ 0.213625] 5
> [ 0.213626] 6 cnt = 30
> [ 0.213627] 7
> [ 0.213748] pci 0000:00:13.0: quirk_usb_early_handoff+0x0/0x700 took 73062 usecs
So, is there a way to not reset the controller? In my case the firmware
and GRUB already used the controller and set it up.
Additionally, can this be done in parallel for both PCI devices?
Can you think of other ways to decrease the time?
Kind regards,
Paul
^ permalink raw reply [flat|nested] 23+ messages in thread
* `pci_apply_final_quirks()` taking half a second
@ 2018-06-24 16:49 ` Paul Menzel
0 siblings, 0 replies; 23+ messages in thread
From: Paul Menzel @ 2018-06-24 16:49 UTC (permalink / raw)
To: Alan Stern
Cc: Bjorn Helgaas, linux-pci, linux-kernel, David Woodhouse,
Andy Shevchenko, linux-usb
Dear Alan,
Sorry for the long delay.
Am 31.12.2017 um 22:16 schrieb Alan Stern:
> On Sun, 31 Dec 2017, Paul Menzel wrote:
>
>> 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:
[…]
>>>>> 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@lists.debian.org)
>>> (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: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]
>
>> So far, this can be reproduce on all AMD systems I have (ASRock
>> A780FullHD, ASRock E350M1, Asus F2A85-M Pro).
>
> So they are OHCI controllers. You could add some debugging statements
> to quirk_usb_handoff_ohci() to try and locate the part that's taking so
> long.
> 737 static void quirk_usb_handoff_ohci(struct pci_dev *pdev)
> 738 {
> 739 void __iomem *base;
> 740 u32 control;
> 741 u32 fminterval = 0;
> 742 bool no_fminterval = false;
> 743 int cnt;
> 744
> 745 if (!mmio_resource_enabled(pdev, 0))
> 746 return;
> 747
> 748 base = pci_ioremap_bar(pdev, 0);
> 749 if (base == NULL)
> 750 return;
> 751
> 752 /*
> 753 * ULi M5237 OHCI controller locks the whole system when accessing
> 754 * the OHCI_FMINTERVAL offset.
> 755 */
> 756 if (pdev->vendor == PCI_VENDOR_ID_AL && pdev->device == 0x5237)
> 757 no_fminterval = true;
> 758
> 759 control = readl(base + OHCI_CONTROL);
> 760
> 761 printk(KERN_INFO "1\n");
> 762 /* On PA-RISC, PDC can leave IR set incorrectly; ignore it there. */
> 763 #ifdef __hppa__
> 764 #define OHCI_CTRL_MASK (OHCI_CTRL_RWC | OHCI_CTRL_IR)
> 765 #else
> 766 #define OHCI_CTRL_MASK OHCI_CTRL_RWC
> 767
> 768 if (control & OHCI_CTRL_IR) {
> 769 int wait_time = 500; /* arbitrary; 5 seconds */
> 770 writel(OHCI_INTR_OC, base + OHCI_INTRENABLE);
> 771 writel(OHCI_OCR, base + OHCI_CMDSTATUS);
> 772 while (wait_time > 0 &&
> 773 readl(base + OHCI_CONTROL) & OHCI_CTRL_IR) {
> 774 wait_time -= 10;
> 775 msleep(10);
> 776 }
> 777 if (wait_time <= 0)
> 778 dev_warn(&pdev->dev,
> 779 "OHCI: BIOS handoff failed (BIOS bug?) %08x\n",
> 780 readl(base + OHCI_CONTROL));
> 781 }
> 782 #endif
> 783
> 784 printk(KERN_INFO "2\n");
> 785 /* disable interrupts */
> 786 writel((u32) ~0, base + OHCI_INTRDISABLE);
> 787
> 788 printk(KERN_INFO "3\n");
> 789 /* Reset the USB bus, if the controller isn't already in RESET */
> 790 if (control & OHCI_HCFS) {
> 791 /* Go into RESET, preserving RWC (and possibly IR) */
> 792 writel(control & OHCI_CTRL_MASK, base + OHCI_CONTROL);
> 793 readl(base + OHCI_CONTROL);
> 794
> 795 /* drive bus reset for at least 50 ms (7.1.7.5) */
> 796 msleep(50);
> 797 }
> 798 printk(KERN_INFO "4\n");
> 799
> 800 /* software reset of the controller, preserving HcFmInterval */
> 801 if (!no_fminterval)
> 802 fminterval = readl(base + OHCI_FMINTERVAL);
> 803
> 804 writel(OHCI_HCR, base + OHCI_CMDSTATUS);
> 805 printk(KERN_INFO "5\n");
> 806
> 807 /* reset requires max 10 us delay */
> 808 for (cnt = 30; cnt > 0; --cnt) { /* ... allow extra time */
> 809 printk(KERN_INFO "6 cnt = %d\n", cnt);
> 810 if ((readl(base + OHCI_CMDSTATUS) & OHCI_HCR) == 0)
> 811 break;
> 812 udelay(1);
> 813 }
> 814
> 815 printk(KERN_INFO "7\n");
> 816 if (!no_fminterval)
> 817 writel(fminterval, base + OHCI_FMINTERVAL);
> 818
> 819 /* Now the controller is safely in SUSPEND and nothing can wake it up */
> 820 iounmap(base);
> 821 }
Here is the result.
> [ 0.062796] pci 0000:00:12.0: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.062860] 1
> [ 0.086662] 2
Around 24 ms are spent in the loop checking `readl(base + OHCI_CONTROL)
& OHCI_CTRL_IR)` in line 772.
> [ 0.086663] 3
> [ 0.138645] 4
That’s the 50 ms from resetting the USB bus, if the controller isn't
already in RESET in line 796.
> [ 0.138647] 5
> [ 0.138649] 6 cnt = 30
> [ 0.138650] 7
> [ 0.138771] pci 0000:00:12.0: quirk_usb_early_handoff+0x0/0x700 took 74188 usecs
> [ 0.138778] pci 0000:00:12.2: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.138917] pci 0000:00:12.2: quirk_usb_early_handoff+0x0/0x700 took 133 usecs
> [ 0.138919] pci 0000:00:12.2: calling pci_fixup_amd_ehci_pme+0x0/0x30 @ 1
> [ 0.138920] pci 0000:00:12.2: PME# does not work under D3, disabling it
> [ 0.138922] pci 0000:00:12.2: pci_fixup_amd_ehci_pme+0x0/0x30 took 0 usecs
> [ 0.138926] pci 0000:00:13.0: calling quirk_usb_early_handoff+0x0/0x700 @ 1
> [ 0.138987] 1
> [ 0.161639] 2
> [ 0.161640] 3
> [ 0.213622] 4
> [ 0.213625] 5
> [ 0.213626] 6 cnt = 30
> [ 0.213627] 7
> [ 0.213748] pci 0000:00:13.0: quirk_usb_early_handoff+0x0/0x700 took 73062 usecs
So, is there a way to not reset the controller? In my case the firmware
and GRUB already used the controller and set it up.
Additionally, can this be done in parallel for both PCI devices?
Can you think of other ways to decrease the time?
Kind regards,
Paul
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 23+ messages in thread
end of thread, other threads:[~2018-06-24 16:49 UTC | newest]
Thread overview: 23+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-04-07 21:07 `pci_apply_final_quirks()` taking half a second Paul Menzel
2017-04-08 15:41 ` Bjorn Helgaas
2017-04-08 17:00 ` David Woodhouse
2017-04-08 19:06 ` Bjorn Helgaas
2017-05-03 18:42 ` Andy Shevchenko
2017-12-26 15:55 ` Paul Menzel
2017-12-28 21:27 ` Bjorn Helgaas
2017-12-28 21:27 ` Bjorn Helgaas
2017-12-29 16:14 ` Alan Stern
2017-12-29 16:14 ` Alan Stern
2017-12-29 16:14 ` Alan Stern
2017-12-31 7:18 ` Paul Menzel
2017-12-31 7:18 ` Paul Menzel
2017-12-31 21:16 ` Alan Stern
2017-12-31 21:16 ` Alan Stern
2017-12-31 21:16 ` Alan Stern
2018-01-01 10:21 ` Paul Menzel
2018-01-01 10:21 ` Paul Menzel
2018-01-01 15:47 ` Alan Stern
2018-01-01 15:47 ` Alan Stern
2018-01-01 15:47 ` Alan Stern
2018-06-24 16:49 ` `quirk_usb_handoff_ohci` takes over 73 ms (twice) on AMD system (was: `pci_apply_final_quirks()` taking half a second) Paul Menzel
2018-06-24 16:49 ` `pci_apply_final_quirks()` taking half a second Paul Menzel
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.