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])
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?