linux-kernel - Re: `pci_apply_final_quirks()` taking half a second

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <c3a7c75b-c50e-1cde-7bb1-94df5dc51f08@molgen.mpg.de>
Date:   Tue, 26 Dec 2017 16:55:20 +0100
From:   Paul Menzel <pmenzel+linux-pci@...gen.mpg.de>
To:     Bjorn Helgaas <helgaas@...nel.org>
Cc:     linux-pci@...r.kernel.org, linux-kernel@...r.kernel.org,
        David Woodhouse <dwmw2@...radead.org>,
        Andy Shevchenko <andy.shevchenko@...il.com>,
        linux-usb@...r.kernel.org
Subject: Re: `pci_apply_final_quirks()` taking half a second

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