Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751157AbdLaVQr (ORCPT ); Sun, 31 Dec 2017 16:16:47 -0500 Received: from netrider.rowland.org ([192.131.102.5]:47493 "HELO netrider.rowland.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1750936AbdLaVQq (ORCPT ); Sun, 31 Dec 2017 16:16:46 -0500 Date: Sun, 31 Dec 2017 16:16:45 -0500 (EST) From: Alan Stern X-X-Sender: stern@netrider.rowland.org To: Paul Menzel cc: Bjorn Helgaas , , , David Woodhouse , Andy Shevchenko , Subject: Re: `pci_apply_final_quirks()` taking half a second In-Reply-To: Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=UTF-8 Content-Transfer-Encoding: 8BIT Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 3199 Lines: 69 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