[    0.116998] smpboot: CPU0: Intel Pentium(R) Dual-Core CPU       T4500  @ 2.30GHz (family: 0x6, model: 0x17, stepping: 0xa)

#define INTEL_FAM6_CORE2_PENRYN         0x17

Wow, the oldest platform I've seen in recent years. :p

Paul, given the limited bandwidth for both of us, I'd suggest we only focus on for these performance issues for new platforms, say skylake and later, what do you think?

(In reply to Zhang Rui from comment #1)
> [    0.116998] smpboot: CPU0: Intel Pentium(R) Dual-Core CPU       T4500  @
> 2.30GHz (family: 0x6, model: 0x17, stepping: 0xa)
> 
> #define INTEL_FAM6_CORE2_PENRYN         0x17
> 
> Wow, the oldest platform I've seen in recent years. :p

Yes, but still usable. (Big thanks to Intel to manufacturing long-lasting processors.)

> Paul, given the limited bandwidth for both of us, I'd suggest we only focus
> on for these performance issues for new platforms, say skylake and later,
> what do you think?

As I do not know, if it’s regression, I guess, I have to accept that.

If you could tell me an ACPI debug line for the Linux kernel command line to find out more by myself, that would be great.

(In reply to Paul Menzel from comment #2)
> (In reply to Zhang Rui from comment #1)
> 
> > Paul, given the limited bandwidth for both of us, I'd suggest we only focus
> > on for these performance issues for new platforms, say skylake and later,
> > what do you think?
> 
> As I do not know, if it’s regression, I guess, I have to accept that.

If it is a regression, we definitely need to take care of them.
But for boot performance issue on the old platform, I don't think it worth putting effort on.

> 
> If you could tell me an ACPI debug line for the Linux kernel command line to
> find out more by myself, that would be great.

Together with the previous bug report, I'd say, I'm not aware of any kernel command line for this purpose.

Paul, as mentioned earlier, 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.

Understood. Thank you for going through the bug reports.

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
    […]
    [    1.064636] pci 0000:00:1e.0:   bridge window [mem 0xc0000000-0xfebfffff window] (subtractive decode)
    [    1.172941] ACPI: PCI: Interrupt link LNKA configured for IRQ 11
    […]

it shows that 100 ms are spent in `acpi_bus_get_status()`:

        1.065243 |   0)   swapper-1    |               |            acpi_bus_attach() {
        1.065244 |   0)   swapper-1    |   4.070 us    |              acpi_bus_get_ejd();
        1.065248 |   0)   swapper-1    | @ 106685.8 us |              acpi_bus_get_status();
        1.171939 |   0)   swapper-1    |   6.777 us    |              acpi_scan_match_handler();
        1.171946 |   0)   swapper-1    |   2.802 us    |              device_attach();
        1.171949 |   0)   swapper-1    | ! 111.522 us  |              acpi_create_platform_device();
        1.172061 |   0)   swapper-1    | @ 106813.9 us |            } /* acpi_bus_attach */

How can I find out, what device(?)/bus(?) that is?

Created attachment 300204 [details]
Linux 5.15.5 messages (output of `dmesg`) with ftrace of `acpi_bus_scan()`

The time seems to be spent in `acpi_ds_exec_end_op()`. I try to provide more traces next week.

Created attachment 300494 [details]
Output of `acpidump`

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
    […]
    [    1.145619] pci 0000:00:1e.0:   bridge window [mem 0xc0000000-0xfebfffff window] (subtractive decode)
    [    1.254161] ACPI: PCI: Interrupt link LNKA configured for IRQ 11
    […]

```
    1.146586 |   1)   swapper-1    |               |  acpi_ds_exec_end_op() {    
    1.146587 |   1)   swapper-1    |               |    acpi_ds_create_operands() {
    1.146587 |   1)   swapper-1    |   1.338 us    |      acpi_ds_create_operand();
    1.146589 |   1)   swapper-1    |   1.955 us    |    } /* acpi_ds_create_operands */
    1.146589 |   1)   swapper-1    |               |    acpi_ex_resolve_operands() {
    1.146589 |   1)   swapper-1    |   0.311 us    |      acpi_ps_get_opcode_info();
    1.146590 |   1)   swapper-1    |   0.296 us    |      acpi_ut_valid_object_type();    
    1.146591 |   1)   swapper-1    |   0.325 us    |      acpi_ex_resolve_to_value();
    1.146591 |   1)   swapper-1    |   0.296 us    |      acpi_ex_convert_to_integer();
    1.146592 |   1)   swapper-1    |   2.831 us    |    } /* acpi_ex_resolve_operands */  
    1.146592 |   1)   swapper-1    |               |    acpi_ex_opcode_1A_0T_0R() {
    1.146592 |   1)   swapper-1    | @ 106131.9 us |      acpi_ex_system_do_sleep();
    1.252727 |   1)   swapper-1    | @ 106132.7 us |    } /* acpi_ex_opcode_1A_0T_0R */
    1.252728 |   1)   swapper-1    |               |    acpi_ds_clear_operands() {
    1.252728 |   1)   swapper-1    |   1.609 us    |      acpi_ut_remove_reference();
    1.252730 |   1)   swapper-1    |   2.221 us    |    } /* acpi_ds_clear_operands */
    1.252730 |   1)   swapper-1    |   0.310 us    |    acpi_ex_truncate_for32bit_table();
    1.252731 |   1)   swapper-1    | @ 106142.2 us |  } /* acpi_ds_exec_end_op */
```

`acpi_ex_system_do_sleep()` runs 106 ms, so there is some sleep specified in the ACPI tables? I disassembled them, and searchd for `Sleep`:

```
$ grep 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?