Bug 208703 - boot performance: PnP ACPI init has 100 ms delay until quirk message - Acer TravelMate 5735Z
Summary: boot performance: PnP ACPI init has 100 ms delay until quirk message - Acer T...
Status: REOPENED
Alias: None
Product: Power Management
Classification: Unclassified
Component: Other (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Zhang Rui
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-07-27 09:13 UTC by Paul Menzel
Modified: 2021-12-26 22:51 UTC (History)
2 users (show)

See Also:
Kernel Version: 5.7.6
Subsystem:
Regression: No
Bisected commit-id:


Attachments
Linux 5.7.6 messages (output of `dmesg`) (60.85 KB, text/plain)
2020-07-27 09:13 UTC, Paul Menzel
Details
Output of `acpidump` (254.25 KB, text/plain)
2020-07-27 09:18 UTC, Paul Menzel
Details
Linux 5.15.5 messages (output of `dmesg`) (62.78 KB, text/plain)
2021-12-24 22:42 UTC, Paul Menzel
Details

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

Note You need to log in before you can comment on or make changes to this bug.