Bug 215419
| Summary: | boot performance: 100 ms regression in boottime before `ACPI: PCI Root Bridge [PCI0]` | ||
|---|---|---|---|
| Product: | ACPI | Reporter: | Paul Menzel (pmenzel+bugzilla.kernel.org) |
| Component: | ACPICA-Core | Assignee: | acpi_acpica-core (acpi_acpica-core) |
| Status: | NEW --- | ||
| Severity: | normal | CC: | pmenzel+bugzilla.kernel.org, rui.zhang |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | 5.15.5 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
| Attachments: |
Linux 5.13.9 messages (output of `dmesg`)
Linux 5.15.5 messages (output of `dmesg`) with ftrace of `acpi_bus_scan()` trace of `acpi_bus_scan()` (`… ftrace=function_graph ftrace_graph_max_depth=7 ftrace_graph_filter=acpi_bus_scan`) Output of `acpidump` |
||
|
Description
Paul Menzel
2021-12-26 22:49:28 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/ 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 */
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 */
[…]
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
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.
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 */
```
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?
|