Hi There! On my HP Probook 450 G2 i have a 6 second boot-delay on ACPI. Look on dmesg: [ 0.398479] ACPI: Added _OSI(Module Device) [ 0.398480] ACPI: Added _OSI(Processor Device) [ 0.398481] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.398482] ACPI: Added _OSI(Processor Aggregator Device) [ 0.409163] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored [ 0.416282] ACPI: Dynamic OEM Table Load: [ 0.416293] ACPI: SSDT 0xFFFF937289858000 0003F3 (v01 PmRef Cpu0Cst 00003001 INTL 20130927) [ 0.416759] ACPI: Dynamic OEM Table Load: [ 0.416769] ACPI: SSDT 0xFFFF93728982B000 0005DB (v01 PmRef ApIst 00003000 INTL 20130927) [ 0.417314] ACPI: Dynamic OEM Table Load: [ 0.417321] ACPI: SSDT 0xFFFF937289F74800 000119 (v01 PmRef ApCst 00003000 INTL 20130927) [ 0.418555] ACPI : EC: EC started [ 6.649711] ACPI: \_SB_.PCI0.LPCB.EC0_: Used as first EC [ 6.649714] ACPI: \_SB_.PCI0.LPCB.EC0_: GPE=0x6, EC_CMD/EC_SC=0x66, EC_DATA=0x62 [ 6.649715] ACPI: \_SB_.PCI0.LPCB.EC0_: Used as boot DSDT EC to handle transactions [ 6.649716] ACPI: Interpreter enabled [ 6.649755] ACPI: (supports S0 S3 S4 S5) [ 6.649756] ACPI: Using IOAPIC for interrupt routing I filed a bug to the debian-kernel (http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=846792), and according to Salvatore Bonaccorso i compiled a vanilla-kernel. On Vanilla-Kernel, the delay persists. So Salvatore asked me, to file a bug against Kernel 4.9 here. This boot-delay started at least at Kernel 4.6 or 4.7. Maybe earlier. I tried different boot-options alone, in combination and all from this list: noacpi pcie_aspm=force acpi_osi=Linux acpi_osi='!Windows 2012' The 6 Second-boot-delay was here every boot. Do you need more information? Which one? Regards Jakob
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