Bug 191561

You need to try latest kernel as this sounds like an old bug.
Let me first mark it as duplicate.
Feel free to re-open when you can reproduce it with latest kernels.

*** This bug has been marked as a duplicate of bug 153511 ***

Looks you think it's reproducible for the latest kernel from this URL:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=846792

Please:
1. Enable CONFIG_ACPI_DEBUG and rebuild the kernel
2. Boot the kernel with acpi.trace_state=enable
3. Upload the full dmesg output and acpidump here

And since you think this started from an old kernel.
Could you bisect the culprit commit out?

(In reply to Lv Zheng from comment #3)
> And since you think this started from an old kernel.
> Could you bisect the culprit commit out?

Actually I build the new kernel 4.10-rc2. Because the 4.9-kernel shows the same delay as the kernel before on my machine.

I tried to remember the past... On my HP Probook 450 G2, i had all the time a long delay before starting plymouth, after selecting the kernel in grub. I thought it is a problem of decompressing the initrd.

But a few weeks ago i recognized, there is another possibility to get information about the boot-delay, and so i found the message in dmesg in the title of this bugreport. I tested it on all installed kernels (4.4, 4.5, 4.6, 4.7, 4.8 and at least the self compiled 4.9-rc8 from debian and 4.9 from kernel org a few days ago). The delay was on all kernels. Maybe it was the same delay also on 3.16 from debian jessie and older (i bought my notebook in march 2015 - and installed debian from beginning on it - and there was all the time the delay on booting... but as described before... i don't know, if it is the same... the bootchart from systemd showed me all the time constantly 8-10 seconds loading the kernel before any other service was started)

One question: The output of acpidump is to large for pastebin.com and paste.debian.net... should i add it directly here?

Here is dmesg:

http://pastebin.com/uAq6nKvV

And here is acpidump in two parts:
Part1:
http://pastebin.com/fEBWcbrQ

Part2:
http://pastebin.com/cEFRCgwx

The delay of 6 seconds persists still with this kernel-version (4.10-rc2)

My boot-parameters are:
"acpi.trace_state=enable log_buf_len=1M rootflags=subvol=@debian-testing apparmor=1 security=apparmor pcie_aspm=force"

I'm booting from a btrfs-subvolume.

Regards
Jakob

(In reply to Jakobus Schürz from comment #4)
> (In reply to Lv Zheng from comment #3)
> > And since you think this started from an old kernel.
> > Could you bisect the culprit commit out?
> 
> Actually I build the new kernel 4.10-rc2. Because the 4.9-kernel shows the
> same delay as the kernel before on my machine.
> 
> I tried to remember the past... On my HP Probook 450 G2, i had all the time
> a long delay before starting plymouth, after selecting the kernel in grub. I
> thought it is a problem of decompressing the initrd.
> 
> But a few weeks ago i recognized, there is another possibility to get
> information about the boot-delay, and so i found the message in dmesg in the
> title of this bugreport. I tested it on all installed kernels (4.4, 4.5,
> 4.6, 4.7, 4.8 and at least the self compiled 4.9-rc8 from debian and 4.9
> from kernel org a few days ago). The delay was on all kernels. Maybe it was
> the same delay also on 3.16 from debian jessie and older (i bought my
> notebook in march 2015 - and installed debian from beginning on it - and
> there was all the time the delay on booting... but as described before... i
> don't know, if it is the same... the bootchart from systemd showed me all
> the time constantly 8-10 seconds loading the kernel before any other service
> was started)

So this is not a regression.

> 
> One question: The output of acpidump is to large for pastebin.com and
> paste.debian.net... should i add it directly here?

You can post the acpidump output here.

Thanks
Lv

(In reply to Jakobus Schürz from comment #5)
> Here is dmesg:
> 
> http://pastebin.com/uAq6nKvV
> 
> And here is acpidump in two parts:
> Part1:
> http://pastebin.com/fEBWcbrQ
> 
> Part2:
> http://pastebin.com/cEFRCgwx
> 

Sorry, I cannot reach them.
Please post the files here.
You can compress them with zip/bzip/gzip, and paste them here via this link:
https://bugzilla.kernel.org/attachment.cgi?bugid=191561&action=enter

Thanks
Lv

Accessing pastebin, browser returns me:

Network Error (tcp_error) 
  
 A communication error occurred: ""   
 The Web Server may be down, too busy, or experiencing other problems preventing it from responding to requests. You may wish to try again at a later time.   

 For assistance, contact your network support team.  

Thanks
Lv

Created attachment 250191 [details]
acpidump 4.10-rc2

Created attachment 250201 [details]
dmesg 4.10-rc2

Hi Lv!

Hope this works now. (Btw... i can open the pastebin.com-links now and here... shit happens sometimes :) )

And i hope, you can find out something helpful.

Thank you!

Jakob

OK, I'll check it later.
Marking the bug as ASSIGNED. :)

Created attachment 251871 [details]
[PATCH] ACPI / EC: Use busy polling mode when GPE is not enabled

Looks like a known issue.
Please try the attached patch.

Thanks
Lv

Created attachment 251911 [details]
[PATCH] ACPI / EC: Use busy polling mode when GPE is not enabled

Maybe this one.
Which is more stable.

This (the second) patch reduces the delay from 6 to 3 seconds... 
How log should this wait-delay be - normally?

According to your log, your EC._REG simply executes too many things.
So the patch worked.
It reduces EC wait-delay into busy-delay. Should be able to improve performance for special stages (bootup/shutdown/suspend/resume) where other kernel modules are waiting for EC to complete.

For the rest 3 seconds, I think that's AML interpreter performance issue or the BIOS AML code problem.
There's surely something improvable.

For example, method owned object destruction can be improved.
Such objects should be deleted right after terminating the control method execution.
While finding them via namespace search is slow.

If you want to try, we can check some of the causes in this 3 seconds.

First let's see what has been executed in AML.
1. Please apply the patch, rebuild the kernel with CONFIG_ACPI_DEBUG.
2. Boot the kernel with acpi.trace_state=opcode acpi.trace_method_name=_SB.PCI0.LPCB.EC0._REG (maybe you need to enlarge log_buf_len).
3. Upload the dmesg here.

If you don't want to try, I think this bug can be closed.
Other issues are not related to this bug.
I'll send the patch to the upstream with a Tested-by tag of your names.

Thanks and best regards
Lv

I will try this. And you'll get the dmesg-upload as soon as possible.
My machine is slow to build the kernel (takes about 3 or more hours...).

And i have to rebuild it with acpi-debug... 

With kernel 4.10 with your patch, it took 10 seconds to load the kernel and initramfs before systemd started to work. Without the path it was about 13 seconds.

Some kernel-versions before, it took only 8 seconds - including this 6 second delay from the bugreport...

But you'll get the dmesg asap.

best regards

Jakob

Created attachment 252351 [details]
dmesg 4.10-rc4 acpi-ec-patch

Hi there!

Now I'm on Kernel 4.10-rc6 and the 6 second-Delay still persists.

Does the patch didn't get merged into the kernel?

regards

jakob

It's there:
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=c3a696b6

However I think it might be 4.11-rc1, not 4.10-rc6.

Thanks
Lv

I've applied that commit to 4.10.1 mainline stable kernel and it also improved boot speed from 10 seconds delay to 3 seconds for my HP Probook G430 G4. Thank you.

[    0.514767] ACPI: Added _OSI(Module Device)
[    0.514767] ACPI: Added _OSI(Processor Device)
[    0.514768] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.514769] ACPI: Added _OSI(Processor Aggregator Device)
[    0.522974] ACPI: Executed 50 blocks of module-level executable AML code
[    0.529320] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
[    0.534381] ACPI: Dynamic OEM Table Load:
[    0.534422] ACPI: SSDT 0xFFFF88041D861800 0006B4 (v02 PmRef  Cpu0Ist  00003000 INTL 20160422)
[    0.534561] ACPI: Executed 1 blocks of module-level executable AML code
[    0.534638] ACPI: \_PR_.CPU0: _OSC native thermal LVT Acked
[    0.535162] ACPI Error: Field [CAP1] at 96 exceeds Buffer [NULL] size 64 (bits) (20160930/dsopcode-236)
[    0.535228] ACPI Error: Method parse/execution failed [\_SB._OSC] (Node ffff88041f8f62f8), AE_AML_BUFFER_LIMIT (20160930/psparse-543)
[    0.535634] ACPI: Dynamic OEM Table Load:
[    0.535641] ACPI: SSDT 0xFFFF88041D9EB000 0003FF (v02 PmRef  Cpu0Cst  00003001 INTL 20160422)
[    0.535750] ACPI: Executed 1 blocks of module-level executable AML code
[    0.536142] ACPI: Dynamic OEM Table Load:
[    0.536149] ACPI: SSDT 0xFFFF88041D867000 00065C (v02 PmRef  ApIst    00003000 INTL 20160422)
[    0.536466] ACPI: Executed 1 blocks of module-level executable AML code
[    0.536627] ACPI: Dynamic OEM Table Load:
[    0.536634] ACPI: SSDT 0xFFFF88041D9CD000 00018A (v02 PmRef  ApCst    00003000 INTL 20160422)
[    0.536742] ACPI: Executed 1 blocks of module-level executable AML code
[    0.537896] ACPI : EC: EC started
[    0.537897] ACPI : EC: interrupt blocked
[    2.761202] ACPI: \_SB_.PCI0.LPCB.EC0_: Used as first EC
[    2.761204] ACPI: \_SB_.PCI0.LPCB.EC0_: GPE=0x6e, EC_CMD/EC_SC=0x66, EC_DATA=0x62
[    2.761205] ACPI: \_SB_.PCI0.LPCB.EC0_: Used as boot DSDT EC to handle transactions
[    2.761205] ACPI: Interpreter enabled
[    2.761259] ACPI: (supports S0 S3 S4 S5)
[    2.761260] ACPI: Using IOAPIC for interrupt routing
[    2.761298] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    2.767813] ACPI: Power Resource [WRST] (off)
[    2.768757] ACPI: Power Resource [PXP] (on)
[    2.936022] ACPI: Power Resource [PXPR] (on)
[    2.941181] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    2.941186] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
[    2.942977] acpi PNP0A08:00: _OSC: OS now controls [PCIeHotplug PME PCIeCapability]
[    2.942978] acpi PNP0A08:00: FADT indicates ASPM is unsupported, using BIOS configuration


Will you bring that fix also into the longterm stable series?

Thanks for the confirmation.
I'll close this again.

For stable related, I think the answer is no.
As this issue is not a regression.
And we couldn't sense this as a really urgent issue.

Thanks
Lv