Bug 208703

Summary: boot performance: PnP ACPI init has 100 ms delay until quirk message - Acer TravelMate 5735Z
Product: Power Management Reporter: Paul Menzel (pmenzel+bugzilla.kernel.org)
Component: OtherAssignee: Zhang Rui (rui.zhang)
Status: REOPENED ---    
Severity: normal CC: pmenzel+bugzilla.kernel.org, rui.zhang
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 5.7.6 Subsystem:
Regression: No Bisected commit-id:
Attachments: Linux 5.7.6 messages (output of `dmesg`)
Output of `acpidump`
Linux 5.15.5 messages (output of `dmesg`)

Description Paul Menzel 2020-07-27 09:13:47 UTC 
Created attachment 290603 [details]
Linux 5.7.6 messages (output of `dmesg`)

On Acer TravelMate 5735Z with Debian Sid/unstable and Linux 5.7.6, over 100 ms are spent in PnP ACPI init.

```
[    0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28
[    0.000000] Linux version 5.7.0-1-amd64 (debian-kernel@lists.debian.org) (gcc version 9.3.0 (Debian 9.3.0-14), GNU ld (GNU Binutils for Debian) 2.34) #1 SMP Debian 5.7.6-1 (2020-06-24)
[…]
[    0.383219] pnp: PnP ACPI init
[    0.488229] pnp 00:00: disabling [io  0x164e-0x164f] because it overlaps 0000:00:1c.2 BAR 13 [io  0x1000-0x1fff]
[    0.488299] system 00:00: [io  0x0600-0x060f] has been reserved
[    0.488301] system 00:00: [io  0x0610] has been reserved
[    0.488303] system 00:00: [io  0x0800-0x080f] has been reserved
[    0.488305] system 00:00: [io  0x0810-0x0817] has been reserved
[    0.488307] system 00:00: [io  0x0820-0x0823] has been reserved
[    0.488308] system 00:00: [io  0x0400-0x047f] has been reserved
[    0.488310] system 00:00: [io  0x0500-0x057f] has been reserved
[    0.488313] system 00:00: [io  0xff2c-0xff2f] has been reserved
[    0.488316] system 00:00: [mem 0xf8000000-0xfbffffff] has been reserved
[    0.488318] system 00:00: [mem 0xfed1c000-0xfed1ffff] has been reserved
[    0.488320] system 00:00: [mem 0xfed10000-0xfed13fff] has been reserved
[    0.488322] system 00:00: [mem 0xfed18000-0xfed18fff] has been reserved
[    0.488324] system 00:00: [mem 0xfed19000-0xfed19fff] has been reserved
[    0.488326] system 00:00: [mem 0xfec00000-0xfec00fff] could not be reserved
[    0.488328] system 00:00: [mem 0xfed20000-0xfed8ffff] has been reserved
[    0.488330] system 00:00: [mem 0xfee00000-0xfee00fff] has been reserved
[    0.488338] system 00:00: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.488412] pnp 00:01: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.488500] pnp 00:02: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.488598] pnp 00:03: Plug and Play ACPI device, IDs SYN1b1d SYN1b00 SYN0002 PNP0f13 (active)
[    0.488759] pnp: PnP ACPI: found 4 devices

The warning message is shown in `quirk_system_pci_resources()`. Is there an easy way to analyze this to get rid of the delay.

Please find all Linux messages attached.
Comment 1 Paul Menzel 2020-07-27 09:18:07 UTC 
Created attachment 290605 [details]
Output of `acpidump`
Comment 2 Paul Menzel 2021-01-03 21:25:16 UTC 
By the way, I found the Linux kernel parameter `pnpacpi=` [1]. Unfortunately, it’s not well documented.

>     pnpacpi=        [ACPI]
>                     { off }

Would that help?

Otherwise, any acpi debug line I could add for more insight?

[1]: https://www.kernel.org/doc/html/v5.10/admin-guide/kernel-parameters.html
Comment 3 Zhang Rui 2021-03-21 14:11:29 UTC 
I think this is because we need to walk ACPI namespace to find all the matched PNP devices. Thus this is probably a generic problem.
Are you aware of this on other platforms?

pnpacpi=off stops ACPI from enumerating these devices but I'm not sure if this is a good idea.
Comment 4 Zhang Rui 2021-06-03 02:46:14 UTC 
Paul, as mentioned in bug #208705, as this is an pretty old machine, we won't look at it unless it is a kernel regression.
So I'd like to close this bug report.
Please feel free to re-open it if you have any different opinions.
Comment 5 Paul Menzel 2021-12-24 22:32:15 UTC 
This is still present in Linux 5.15.5:

    [    0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28
    [    0.000000] Linux version 5.15.0-2-amd64 (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-13) 11.2.0, GNU ld (GNU Binutils for Debian) 2.37)
 #1 SMP Debian 5.15.5-2 (2021-12-18)
    […]
    [    0.000000] DMI: Acer TravelMate 5735Z/BA51_MV, BIOS V1.14 07/26/2011
    […]
    [    0.565625] pnp: PnP ACPI init
    [    0.675076] pnp 00:00: disabling [io  0x164e-0x164f] because it overlaps 0000:00:1c.2 BAR 13 [io  0x1000-0x1fff]
    […]

In my opinion, this is a bug, and it’d be great if it’d be analyzed despite the age of the hardware.

Could you please point me, how to at least figure out, where the delay is happening? ftrace? Something with `acpi.debug_layer=` or `acpi.debug_level=`?
Comment 6 Paul Menzel 2021-12-24 22:42:25 UTC 
Created attachment 300139 [details]
Linux 5.15.5 messages (output of `dmesg`)

For the record, I am attaching the Linux 5.15.5 messages.

PS: They also contain another regression compared to Linux 5.7.6, where duration increased from 8 ms to 113 ms:

Linux 5.7.6:

[    0.184442] ACPI: Enabled 15 GPEs in block 00 to 3F
[    0.192301] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])

Linux 5.15.5:

[    0.264773] ACPI: Enabled 15 GPEs in block 00 to 3F
[    0.377958] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
Comment 7 Paul Menzel 2021-12-26 22:51:17 UTC 
For the problem reported in the postscript, I created bug #215419 [1].

[1]: https://bugzilla.kernel.org/show_bug.cgi?id=215419