From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751441AbdL2QOy (ORCPT ); Fri, 29 Dec 2017 11:14:54 -0500 Received: from netrider.rowland.org ([192.131.102.5]:60573 "HELO netrider.rowland.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1751394AbdL2QOw (ORCPT ); Fri, 29 Dec 2017 11:14:52 -0500 Date: Fri, 29 Dec 2017 11:14:51 -0500 (EST) From: Alan Stern X-X-Sender: stern@netrider.rowland.org To: Bjorn Helgaas cc: Paul Menzel , , , David Woodhouse , Andy Shevchenko , Subject: Re: `pci_apply_final_quirks()` taking half a second In-Reply-To: <20171228212723.GB211339@bhelgaas-glaptop.roam.corp.google.com> 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 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 From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Return-Path: Date: Fri, 29 Dec 2017 11:14:51 -0500 (EST) From: Alan Stern To: Bjorn Helgaas cc: Paul Menzel , , , David Woodhouse , Andy Shevchenko , Subject: Re: `pci_apply_final_quirks()` taking half a second In-Reply-To: <20171228212723.GB211339@bhelgaas-glaptop.roam.corp.google.com> Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=UTF-8 List-ID: 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 From mboxrd@z Thu Jan 1 00:00:00 1970 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: base64 Subject: `pci_apply_final_quirks()` taking half a second From: Alan Stern Message-Id: Date: Fri, 29 Dec 2017 11:14:51 -0500 (EST) To: Bjorn Helgaas Cc: Paul Menzel , linux-pci@vger.kernel.org, linux-kernel@vger.kernel.org, David Woodhouse , Andy Shevchenko , linux-usb@vger.kernel.org List-ID: T24gVGh1LCAyOCBEZWMgMjAxNywgQmpvcm4gSGVsZ2FhcyB3cm90ZToKCj4gT24gVHVlLCBEZWMg MjYsIDIwMTcgYXQgMDQ6NTU6MjBQTSArMDEwMCwgUGF1bCBNZW56ZWwgd3JvdGU6Cj4gPiBBbSAw OC4wNC4yMDE3IHVtIDE3OjQxIHNjaHJpZWIgQmpvcm4gSGVsZ2FhczoKPiA+ID5PbiBGcmksIEFw ciAwNywgMjAxNyBhdCAxMTowNzoxNVBNICswMjAwLCBQYXVsIE1lbnplbCB3cm90ZToKPiA+IAo+ ID4gPj5NZWFzdXJpbmcgd2hlcmUgdGltZSBpcyBzcGVudCBkdXJpbmcgYm9vdCB3aXRoIGBzeXN0 ZW1kLWJvb3RjaGFydGAKPiA+ID4+b24gYW4gQXN1cyBBNzgwRnVsbEhELCBpdCB0dXJucyBvdXQg dGhhdCBoYWxmIGEgc2Vjb25kIGlzIHNwZW50IGluCj4gPiA+PmBwY2lfYXBwbHlfZmluYWxfcXVp cmtzKClgLgo+ID4gPgo+ID4gPkkgYWdyZWUsIHRoYXQgc2VlbXMgbGlrZSBhIGNyYXp5IGFtb3Vu dCBvZiB0aW1lLgo+ID4gPgo+ID4gPkNhbiB5b3UgZmlndXJlIG91dCBob3cgdG8gdHVybiBvbiBw cl9kZWJ1ZygpICh2aWEgdGhlIGR5bmFtaWMgZGVidWcKPiA+ID5tZXNzIG9yIHdoYXRldmVyKSBh bmQgYm9vdCB3aXRoICJpbml0Y2FsbF9kZWJ1ZyI/ICBUaGF0IHNob3VsZCB0ZWxsIHVzCj4gPiA+ aG93IGxvbmcgZWFjaCBxdWlyayB0b29rLgo+ID4gCj4gPiBJIGFtIHNvcnJ5IGZvciB0YWtpbmcg c28gbG9uZyB0byByZXBseS4gSSBmaW5hbGx5IGFkZGVkIGBkeW5kYmc9ZmlsZQo+ID4gcXVpcmtz LmMgK3BgIHRvIHRoZSBjb21tYW5kIGxpbmUgb2YgTGludXggNC4xMy4xMy4gVGhpcyBpcyBvbgo+ ID4gYW5vdGhlciBBTUQgc3lzdGVtIChBc3VzIEYyODVNIFBybykuCgo+ID4gRGV6IDI2IDE2OjIx OjQ2IGFzdXMtZjJhODUtcHJvIGtlcm5lbDogcGNpIGZpeHVwCj4gPiBxdWlya191c2JfZWFybHlf aGFuZG9mZisweDAvMHg2YjAgcmV0dXJuZWQgYWZ0ZXIgMTk3IHVzZWNzIGZvcgo+ID4gMDAwMDow MDoxMC4wCj4gPiBEZXogMjYgMTY6MjE6NDYgYXN1cy1mMmE4NS1wcm8ga2VybmVsOiBwY2kgZml4 dXAKPiA+IHF1aXJrX3VzYl9lYXJseV9oYW5kb2ZmKzB4MC8weDZiMCByZXR1cm5lZCBhZnRlciAx MjcgdXNlY3MgZm9yCj4gPiAwMDAwOjAwOjEwLjEKPiA+IERleiAyNiAxNjoyMTo0NiBhc3VzLWYy YTg1LXBybyBrZXJuZWw6IHBjaSBmaXh1cAo+ID4gcXVpcmtfdXNiX2Vhcmx5X2hhbmRvZmYrMHgw LzB4NmIwIHJldHVybmVkIGFmdGVyIDg4NjQzIHVzZWNzIGZvcgo+ID4gMDAwMDowMDoxMi4wCj4g PiBEZXogMjYgMTY6MjE6NDYgYXN1cy1mMmE4NS1wcm8ga2VybmVsOiBwY2kgZml4dXAKPiA+IHF1 aXJrX3VzYl9lYXJseV9oYW5kb2ZmKzB4MC8weDZiMCByZXR1cm5lZCBhZnRlciAxMzcgdXNlY3Mg Zm9yCj4gPiAwMDAwOjAwOjEyLjIKPiA+IERleiAyNiAxNjoyMTo0NiBhc3VzLWYyYTg1LXBybyBr ZXJuZWw6IHBjaSBmaXh1cAo+ID4gcGNpX2ZpeHVwX2FtZF9laGNpX3BtZSsweDAvMHgzMCByZXR1 cm5lZCBhZnRlciAxIHVzZWNzIGZvcgo+ID4gMDAwMDowMDoxMi4yCj4gPiBEZXogMjYgMTY6MjE6 NDYgYXN1cy1mMmE4NS1wcm8ga2VybmVsOiBwY2kgZml4dXAKPiA+IHF1aXJrX3VzYl9lYXJseV9o YW5kb2ZmKzB4MC8weDZiMCByZXR1cm5lZCBhZnRlciA4NTc3MCB1c2VjcyBmb3IKPiA+IDAwMDA6 MDA6MTMuMAo+ID4gRGV6IDI2IDE2OjIxOjQ2IGFzdXMtZjJhODUtcHJvIGtlcm5lbDogcGNpIGZp eHVwCj4gPiBxdWlya191c2JfZWFybHlfaGFuZG9mZisweDAvMHg2YjAgcmV0dXJuZWQgYWZ0ZXIg MTM0IHVzZWNzIGZvcgo+ID4gMDAwMDowMDoxMy4yCj4gPiBEZXogMjYgMTY6MjE6NDYgYXN1cy1m MmE4NS1wcm8ga2VybmVsOiBwY2kgZml4dXAKPiA+IHBjaV9maXh1cF9hbWRfZWhjaV9wbWUrMHgw LzB4MzAgcmV0dXJuZWQgYWZ0ZXIgMSB1c2VjcyBmb3IKPiA+IDAwMDA6MDA6MTMuMgo+ID4gRGV6 IDI2IDE2OjIxOjQ2IGFzdXMtZjJhODUtcHJvIGtlcm5lbDogcGNpIGZpeHVwCj4gPiBxdWlya191 c2JfZWFybHlfaGFuZG9mZisweDAvMHg2YjAgcmV0dXJuZWQgYWZ0ZXIgMTI1IHVzZWNzIGZvcgo+ ID4gMDAwMDowMzowMC4wW+KApl0KPiA+IGBgYAo+ID4gCj4gPiBTbyBpdOKAmXMgYHBjaSBmaXh1 cCBxdWlya191c2JfZWFybHlfaGFuZG9mZmAgdGFraW5nIGFyb3VuZCA4NSBtcywgYW5kCj4gPiB0 aGF0IHR3aWNlLgo+IAo+IFdvdy4gIFRoYXQncyBwcmV0dHkgcGFpbmZ1bCwgYnV0IG9mIGNvdXJz ZSBJIGRvbid0IGtub3cgaG93IHRvIGZpeCBpdC4KPiBGcm9tIGxvb2tpbmcgYXQgcXVpcmtfdXNi X2Vhcmx5X2hhbmRvZmYoKSwgaXQgbWF5IGRlcGVuZCBvbiBCSU9TCj4gZGV0YWlscy4gIE1heWJl IHRoZSBVU0IgZm9sa3Mgd2lsbCBoYXZlIHNvbWUgaWRlYXMuCgpDYW4gd2Ugc2VlIHRoZSBvdXRw dXQgZnJvbSBsc3BjaT8gIEl0IHdvdWxkIGhlbHAgdG8ga25vdyB3aGF0IHRoZSAxMi4wIAphbmQg MTMuMCBkZXZpY2VzIGFyZS4KCkFsYW4gU3Rlcm4KLS0tClRvIHVuc3Vic2NyaWJlIGZyb20gdGhp cyBsaXN0OiBzZW5kIHRoZSBsaW5lICJ1bnN1YnNjcmliZSBsaW51eC11c2IiIGluCnRoZSBib2R5 IG9mIGEgbWVzc2FnZSB0byBtYWpvcmRvbW9Admdlci5rZXJuZWwub3JnCk1vcmUgbWFqb3Jkb21v IGluZm8gYXQgIGh0dHA6Ly92Z2VyLmtlcm5lbC5vcmcvbWFqb3Jkb21vLWluZm8uaHRtbAo=