Bug 215419 - boot performance: 100 ms regression in boottime before `ACPI: PCI Root Bridge [PCI0]`
Summary: boot performance: 100 ms regression in boottime before `ACPI: PCI Root Bridge...
Status: NEW
Alias: None
Product: ACPI
Classification: Unclassified
Component: ACPICA-Core (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: acpi_acpica-core@kernel-bugs.osdl.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-12-26 22:49 UTC by Paul Menzel
Modified: 2022-06-21 06:52 UTC (History)
2 users (show)

See Also:
Kernel Version: 5.15.5
Tree: Mainline
Regression: No


Attachments
Linux 5.13.9 messages (output of `dmesg`) (61.23 KB, text/plain)
2022-01-02 13:40 UTC, Paul Menzel
Details
Linux 5.15.5 messages (output of `dmesg`) with ftrace of `acpi_bus_scan()` (64.04 KB, text/plain)
2022-01-09 21:18 UTC, Paul Menzel
Details
trace of `acpi_bus_scan()` (`… ftrace=function_graph ftrace_graph_max_depth=7 ftrace_graph_filter=acpi_bus_scan`) (37.16 KB, text/plain)
2022-01-09 21:43 UTC, Paul Menzel
Details
Output of `acpidump` (254.25 KB, text/plain)
2022-02-20 20:12 UTC, Paul Menzel
Details

Description Paul Menzel 2021-12-26 22:49:28 UTC
On the Intel T4500 laptop Acer TravelMate 5735Z with Debian sid/unstable, there is a 100 ms introduced between Linux 5.10.46 and 5.14.6, and is still present in Linux 5.15.5.

### 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.10.46

[    0.000000] sitopanaki kernel: Linux version 5.10.0-8-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.46-4 (2021-08-03)
[    0.000000] sitopanaki kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.0-8-amd64 root=UUID=e17cec4f-d2b8-4cc3-bd39-39a10ed422f4 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on tsc=unstable
[…]
[    0.258452] sitopanaki kernel: ACPI: Enabled 15 GPEs in block 00 to 3F
[    0.266600] sitopanaki kernel: ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])

### Linux 5.14.6 (regression)

[    0.000000] sitopanaki kernel: Linux version 5.14.0-1-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.3.0-10) 10.3.0, GNU ld (GNU Binutils for Debian) 2.37) #1 SMP Debian 5.14.6-2 (2021-09-19)
[    0.000000] sitopanaki kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.14.0-1-amd64 root=UUID=e17cec4f-d2b8-4cc3-bd39-39a10ed422f4 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on tsc=unstable

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

### Linux 5.15.5 (regression)

[    0.264773] ACPI: Enabled 15 GPEs in block 00 to 3F
[    0.377958] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
Comment 1 Paul Menzel 2022-01-02 13:40:08 UTC
Created attachment 300203 [details]
Linux 5.13.9 messages (output of `dmesg`)

It’s already there in Linux 5.13.9 [1].

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

Unfortunately, due to the release freeze, there do not seem to be Linux 5.11 and 5.12 packages in the official Debian archives (experimental suite) [2].

[1]: https://snapshot.debian.org/package/linux/5.13.9-1%7Eexp2/#linux-image-5.13.0-trunk-amd64-unsigned_5.13.9-1:7e:exp2
[2]: https://snapshot.debian.org/package/linux/
Comment 2 Paul Menzel 2022-01-02 19:08:11 UTC
Using ftrace

    [    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] Command line: BOOT_IMAGE=/boot/vmlinuz-5.15.0-2-amd64 root=UUID=e17cec4f-d2b8-4cc3-bd39-39a10ed422f4 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on log_buf_len=32M trace_buf_size=146454K trace_clock=global trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time ftrace=function_graph ftrace_graph_max_depth=7 ftrace_graph_filter=acpi_bus_scan
    […]
    [    0.786455] ACPI: Enabled 15 GPEs in block 00 to 3F
    [    0.982583] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
    […]

it shows, that `acpi_pci_root_create()` takes 82 ms. The 200 ms delay instead of 100 ms are due to tracing.

        0.982641 |   0)   swapper-1    |               |            pci_acpi_scan_root() {
        0.982641 |   0)   swapper-1    | + 17.904 us   |              acpi_get_node();
        0.982660 |   0)   swapper-1    |   0.391 us    |              x86_pci_root_bus_node();
        0.982661 |   0)   swapper-1    |   1.038 us    |              pci_find_bus();
        0.982662 |   0)   swapper-1    |   0.867 us    |              kmem_cache_alloc_trace();
        0.982663 |   0)   swapper-1    | * 82014.31 us |              acpi_pci_root_create();
        1.064681 |   0)   swapper-1    |   1.203 us    |              pcie_bus_configure_settings();
        1.064682 |   0)   swapper-1    |   0.837 us    |              pcie_bus_configure_settings();
        1.064683 |   0)   swapper-1    |   0.857 us    |              pcie_bus_configure_settings();
        1.064684 |   0)   swapper-1    |   0.301 us    |              pcie_bus_configure_settings();
        1.064685 |   0)   swapper-1    | * 82044.38 us |            } /* pci_acpi_scan_root */
Comment 3 Paul Menzel 2022-01-09 21:18:07 UTC
Created attachment 300247 [details]
Linux 5.15.5 messages (output of `dmesg`) with ftrace of `acpi_bus_scan()`

Sorry, the comment above regarding `acpi_pci_root_create()` as the culprit is incorrect. (The timestamps are bigger than the ones from the Linux log.)

It’s actually `acpi_bus_get_status()`:

    […]
        0.807591 |   0)   swapper-1    |               |        acpi_bus_check_add_1() {
        0.807591 |   0)   swapper-1    |               |          acpi_bus_check_add() {
        0.807591 |   0)   swapper-1    |               |            handle_to_device() {
        0.807592 |   0)   swapper-1    |   1.488 us    |              acpi_get_data_full();
        0.807593 |   0)   swapper-1    |   2.050 us    |            } /* handle_to_device */
        0.807594 |   0)   swapper-1    |               |            acpi_get_type() {
        0.807594 |   0)   swapper-1    |   0.923 us    |              acpi_ut_acquire_mutex();
        0.807595 |   0)   swapper-1    |   0.346 us    |              acpi_ns_validate_handle();
        0.807596 |   0)   swapper-1    |   0.602 us    |              acpi_ut_release_mutex();
        0.807597 |   0)   swapper-1    |   3.188 us    |            } /* acpi_get_type */
        0.807597 |   0)   swapper-1    |               |            acpi_scan_check_dep() {
        0.807598 |   0)   swapper-1    |   3.148 us    |              acpi_has_method();
        0.807601 |   0)   swapper-1    |   3.790 us    |            } /* acpi_scan_check_dep */
        0.807601 |   0)   swapper-1    |               |            acpi_add_single_object() {
        0.807602 |   0)   swapper-1    |   0.832 us    |              kmem_cache_alloc_trace();
        0.807603 |   0)   swapper-1    | ! 132.304 us  |              acpi_init_device_object();
        0.807736 |   0)   swapper-1    | @ 108199.6 us |              acpi_bus_get_status();
        0.915939 |   0)   swapper-1    |   3.683 us    |              acpi_has_method();
        0.915943 |   0)   swapper-1    |   2.922 us    |              acpi_has_method();
        0.915947 |   0)   swapper-1    |   2.857 us    |              acpi_has_method();
        0.915950 |   0)   swapper-1    |   1.875 us    |              acpi_attach_data();
        0.915952 |   0)   swapper-1    | + 71.565 us   |              __acpi_device_add();
        0.916024 |   0)   swapper-1    |   0.301 us    |              acpi_power_add_remove_device();
        0.916025 |   0)   swapper-1    |   0.326 us    |              dev_uevent_filter();
        0.916026 |   0)   swapper-1    |   0.271 us    |              dev_uevent_name();
        0.916026 |   0)   swapper-1    |   0.887 us    |              kmem_cache_alloc_trace();
        0.916028 |   0)   swapper-1    |   0.596 us    |              __kmalloc();
        0.916030 |   0)   swapper-1    |   1.463 us    |              dev_uevent();
        0.916032 |   0)   swapper-1    |   0.571 us    |              mutex_lock();
        0.916033 |   0)   swapper-1    |   0.516 us    |              netlink_has_listeners();
        0.916034 |   0)   swapper-1    |   0.351 us    |              consume_skb();
        0.916034 |   0)   swapper-1    |   0.387 us    |              mutex_unlock();
        0.916035 |   0)   swapper-1    |   0.321 us    |              kfree();
        0.916036 |   0)   swapper-1    |   0.305 us    |              kfree();
        0.916036 |   0)   swapper-1    | @ 108431.8 us |            } /* acpi_add_single_object */
        0.916037 |   0)   swapper-1    |               |            acpi_has_method() {
        0.916037 |   0)   swapper-1    |   2.932 us    |              acpi_get_handle();
        0.916040 |   0)   swapper-1    |   3.554 us    |            } /* acpi_has_method */
        0.916040 |   0)   swapper-1    |               |            acpi_has_method() {
        0.916041 |   0)   swapper-1    |   2.832 us    |              acpi_get_handle();
        0.916044 |   0)   swapper-1    |   3.464 us    |            } /* acpi_has_method */
        0.916044 |   0)   swapper-1    |               |            acpi_bay_match() {
        0.916045 |   0)   swapper-1    |   2.942 us    |              acpi_has_method();
        0.916048 |   0)   swapper-1    |   3.549 us    |            } /* acpi_bay_match */
        0.916048 |   0)   swapper-1    |               |            acpi_scan_match_handler() {
        0.916050 |   0)   swapper-1    |   6.721 us    |              acpi_pnp_match();
        0.916057 |   0)   swapper-1    |   8.958 us    |            } /* acpi_scan_match_handler */
        0.916057 |   0)   swapper-1    | @ 108463.3 us |          } /* acpi_bus_check_add */
        0.916058 |   0)   swapper-1    | @ 108464.0 us |        } /* acpi_bus_check_add_1 */
    […]
Comment 4 Paul Menzel 2022-01-09 21:43:48 UTC
Created attachment 300249 [details]
trace of `acpi_bus_scan()` (`… ftrace=function_graph ftrace_graph_max_depth=7 ftrace_graph_filter=acpi_bus_scan`)

    [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.15.0-2-amd64 root=UUID=e17cec4f-d2b8-4cc3-bd39-39a10ed422f4 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on log_buf_len=32M trace_buf_size=146454K trace_clock=global trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time ftrace=function_graph ftrace_graph_max_depth=7 ftrace_graph_filter=acpi_bus_scan
Comment 5 Paul Menzel 2022-02-20 19:52:11 UTC
Tracing `acpi_ds_exec_end_op()` in Linux 5.16.7 shows:

    [    0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28
    [    0.000000] Linux version 5.16.0-1-amd64 (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU ld (GNU Binutils for Debian) 2.37.90.20220130) #1 SMP PREEMPT Debian 5.16.7-2 (2022-02-09)
    [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.16.0-1-amd64 root=UUID=e17cec4f-d2b8-4cc3-bd39-39a10ed422f4 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on initcall_debug log_buf_len=32M trace_buf_size=74631K trace_clock=global trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time ftrace=function_graph ftrace_graph_max_depth=3 ftrace_graph_filter=acpi_ds_exec_end_op
    […]
    [    0.885867] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
    [    0.887934] ACPI: Enabled 15 GPEs in block 00 to 3F
    […]

```
    0.909187 |   0)   swapper-1    |               |  acpi_ds_exec_end_op() {
    0.909187 |   0)   swapper-1    |               |    acpi_ds_create_operands() {
    0.909188 |   0)   swapper-1    |   1.343 us    |      acpi_ds_create_operand();
    0.909189 |   0)   swapper-1    |   2.040 us    |    } /* acpi_ds_create_operands */
    0.909190 |   0)   swapper-1    |               |    acpi_ex_resolve_operands() {
    0.909190 |   0)   swapper-1    |   0.305 us    |      acpi_ps_get_opcode_info();
    0.909191 |   0)   swapper-1    |   0.371 us    |      acpi_ut_valid_object_type();
    0.909192 |   0)   swapper-1    |   0.321 us    |      acpi_ex_resolve_to_value();
    0.909192 |   0)   swapper-1    |   0.360 us    |      acpi_ex_convert_to_integer();
    0.909193 |   0)   swapper-1    |   3.042 us    |    } /* acpi_ex_resolve_operands */
    0.909193 |   0)   swapper-1    |               |    acpi_ex_opcode_1A_0T_0R() {
    0.909194 |   0)   swapper-1    | @ 107530.6 us |      acpi_ex_system_do_sleep();
    1.016727 |   0)   swapper-1    | @ 107531.5 us |    } /* acpi_ex_opcode_1A_0T_0R */
    1.016727 |   0)   swapper-1    |               |    acpi_ds_clear_operands() {
    1.016728 |   0)   swapper-1    |   1.749 us    |      acpi_ut_remove_reference();
    1.016730 |   0)   swapper-1    |   2.506 us    |    } /* acpi_ds_clear_operands */
    1.016730 |   0)   swapper-1    |   0.306 us    |    acpi_ex_truncate_for32bit_table();
    1.016731 |   0)   swapper-1    | @ 107541.6 us |  } /* acpi_ds_exec_end_op */
```

`acpi_ex_system_do_sleep()` runs 107 ms, so there is some sleep specified in the ACPI tables? I disassembled them, and searched for *sleep* but didn’t notice anything. I am going to attach the acpidump output in the next days.
Comment 6 Paul Menzel 2022-02-20 20:01:19 UTC
I also traced Linux 5.10.46, and interestingly the 100 ms then also started to show up.

Trace of `acpi_bus_scan()` with maximum depth of 7(?):

```
    0.778182 |   1)   swapper-1    |               |  acpi_bus_scan() {
    0.778184 |   1)   swapper-1    |               |    acpi_bus_check_add() {
[…]
    0.778541 |   1)   swapper-1    | ! 357.324 us  |    } /* acpi_bus_check_add */          
    0.778542 |   1)   swapper-1    |               |    acpi_walk_namespace() {
[…]
    0.869146 |   1)   swapper-1    | * 90601.57 us |    } /* acpi_walk_namespace */  
    0.869146 |   1)   swapper-1    |               |    acpi_bus_attach() {
[…]
    0.949104 |   1)   swapper-1    |               |            acpi_bus_attach() {
    0.949104 |   1)   swapper-1    |   3.343 us    |              acpi_bus_get_ejd();
    0.949108 |   1)   swapper-1    | @ 107439.9 us |              acpi_bus_get_status();
    1.056551 |   1)   swapper-1    |   4.586 us    |              acpi_scan_match_handler();
    1.056556 |   1)   swapper-1    |   3.143 us    |              device_attach();
    1.056559 |   1)   swapper-1    | ! 123.417 us  |              acpi_create_platform_device();
    1.056683 |   1)   swapper-1    | @ 107577.3 us |            } /* acpi_bus_attach */
[…]
    1.064413 |   1)   swapper-1    | @ 195263.3 us |    } /* acpi_bus_attach */
    1.064413 |   1)   swapper-1    | @ 286227.2 us |  } /* acpi_bus_scan */
```

Trace of `acpi_bus_scan()` with maximum depth of 2:

```
    0.777785 |   1)   swapper-1    |               |  acpi_bus_scan() {
    0.777787 |   1)   swapper-1    |               |    acpi_bus_check_add() {
    0.777788 |   1)   swapper-1    |   1.790 us    |      acpi_get_data_full();
    0.777790 |   1)   swapper-1    |   0.316 us    |      acpi_get_type();
    0.777791 |   1)   swapper-1    | ! 171.688 us  |      acpi_add_single_object();
    0.777963 |   1)   swapper-1    |   6.276 us    |      acpi_has_method();
    0.777970 |   1)   swapper-1    |   5.594 us    |      acpi_has_method();
    0.777976 |   1)   swapper-1    |   5.654 us    |      acpi_bay_match();
    0.777982 |   1)   swapper-1    |   5.784 us    |      acpi_scan_match_handler();
    0.777988 |   1)   swapper-1    |   6.351 us    |      acpi_device_dep_initialize();
    0.777994 |   1)   swapper-1    | ! 207.142 us  |    } /* acpi_bus_check_add */
    0.777995 |   1)   swapper-1    |               |    acpi_walk_namespace() {
    0.777995 |   1)   swapper-1    |   1.299 us    |      acpi_ut_acquire_read_lock();
    0.777997 |   1)   swapper-1    |   0.632 us    |      acpi_ut_acquire_mutex();
    0.777998 |   1)   swapper-1    |   0.295 us    |      acpi_ns_validate_handle();
    0.777998 |   1)   swapper-1    | * 47792.60 us |      acpi_ns_walk_namespace();
    0.825799 |   1)   swapper-1    |   1.048 us    |      acpi_ut_release_mutex();
    0.825800 |   1)   swapper-1    |   1.373 us    |      acpi_ut_release_read_lock();
    0.825801 |   1)   swapper-1    | * 47803.62 us |    } /* acpi_walk_namespace */
    0.825802 |   1)   swapper-1    |               |    acpi_bus_attach() {
    0.825802 |   1)   swapper-1    |   6.501 us    |      acpi_bus_get_ejd();
    0.825809 |   1)   swapper-1    |   8.632 us    |      acpi_bus_get_status();
    0.825818 |   1)   swapper-1    |   3.143 us    |      acpi_scan_match_handler();
    0.825821 |   1)   swapper-1    |   1.634 us    |      device_attach();
    0.825823 |   1)   swapper-1    | + 44.135 us   |      acpi_bus_attach();
    0.825868 |   1)   swapper-1    | + 50.461 us   |      acpi_bus_attach();
    0.825919 |   1)   swapper-1    | + 27.354 us   |      acpi_bus_attach();
    0.825947 |   1)   swapper-1    | + 36.491 us   |      acpi_bus_attach();
    0.825983 |   1)   swapper-1    | @ 201902.8 us |      acpi_bus_attach();
    1.027891 |   1)   swapper-1    | + 29.303 us   |      acpi_bus_attach();
    1.027920 |   1)   swapper-1    | @ 202117.8 us |    } /* acpi_bus_attach */
    1.027921 |   1)   swapper-1    | @ 250133.4 us |  } /* acpi_bus_scan */
```
Comment 7 Paul Menzel 2022-02-20 20:12:09 UTC
Created attachment 300493 [details]
Output of `acpidump`

```
$ grep -i sleep *dsl
dsdt.dsl:    Method (_PTS, 1, NotSerialized)  // _PTS: Prepare To Sleep
dsdt.dsl:                    Sleep (0x05DC)
dsdt.dsl:            Sleep (0x64)
dsdt.dsl:            Sleep (0x01F4)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                        Sleep (0x64)
dsdt.dsl:                        Sleep (ASLP)
dsdt.dsl:                        Sleep (ASLP)
dsdt.dsl:                        Sleep (ASLP)
dsdt.dsl:                                Sleep (0x64)
dsdt.dsl:                                Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                                Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                            Sleep (0x64)
dsdt.dsl:                    Name (_HID, EisaId ("PNP0C0E") /* Sleep Button Device */)  // _HID: Hardware ID
dsdt.dsl:                        Sleep (0x03F0)
dsdt.dsl:                        Sleep (0x03F0)
```

Is there an easy way to find out, which of these it is?

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