Bug 77681
Created attachment 139261 [details]
lspci
Created attachment 139271 [details]
dmidecode
Created attachment 139281 [details]
acpidump
Created attachment 139291 [details]
config-3.15.0
My Linux kernel configuration
Created attachment 139391 [details]
dmesg with ACPI DEBUG enabled
Created attachment 139411 [details]
config-3.15.0
Enabled ACPI_WMI + HP_WMI, did not affect the 1.5 second delay.
Lv, I think you have an EC patch set that could probably fix this issue, right? why not post the patches/urls here? No. This bug is not related to EC. According to the log, this 1.5s delay seems to be caused by ACPICA interpreter. I'll work on it after finishing my current tasks. I have some upstream purifiying work need to be done prior than jumping into this bug. Created attachment 144321 [details]
[PATCH 1/7] ACPICA: Executer: Add back pointing reference of method operand.
This is used to close end of tracing.
Created attachment 144331 [details]
[PATCH 2/7] ACPICA: Dispatcher: Add trace support for interpreter.
This adds debugging messages for tracing.
Created attachment 144341 [details]
[PATCH 3/7] ACPICA: Executer: Add interpreter tracing mode for method tracing facility.
This patch makes tracing a part of the original acpi method tracing facility so that boot parameters can be used to enable the tracer for kernel bootup.
Created attachment 144351 [details]
[PATCH 4/7] ACPICA: Interpreter: Add OSL trace hook support.
This allows OSPM to use the tracer framework to implement various possiblities.
Created attachment 144361 [details]
[PATCH 5/7] ACPI: Add AML interpreter execution trace support.
This implements a Linux ftrace plugin to trace AML method/opcode execution.
Created attachment 144371 [details]
[PATCH 6/7] ACPI: Update method tracing facility.
This updates method tracing sysfs interfaces.
Created attachment 144381 [details]
[PATCH 7/7] ACPI/OSL: Add semaphore/mutex bypassing support when scheduler is not ready.
This allows early param to invoke acpi.trace_xxx.
Hi, Steffen Sorry for the delay. I've been working on preparing EC patches these days. Now I'm back. The tracer patches are rebased and purified, so now you can try it again. Here is the test request: 1. Please apply the patches on top of recent upstream Linux. 2. Build kernel with your config that can reproduce this issue. 3. Boot the kernel with the following parameters: acpi.trace_debug_level=0x00000010 acpi.trace_debug_layer=0x00000080 acpi.trace_state=method log_buf_len=1M If 1M is not enough to contain all bootup logs, please extend it. 4. Upload the dmesg output here. Thanks in advance. > 1. Please apply the patches on top of recent upstream Linux.
I've tried with Linux 3.15.6 and 3.16-rc7. In both cases patches 1 + 2 apply cleanly but patches 3 + 4 fail. I've not yet tried patches 5, 6 and 7.
Which kernel version should I use?
(In reply to Steffen Weber from comment #17) > > 1. Please apply the patches on top of recent upstream Linux. > > I've tried with Linux 3.15.6 and 3.16-rc7. In both cases patches 1 + 2 apply > cleanly but patches 3 + 4 fail. I've not yet tried patches 5, 6 and 7. > > Which kernel version should I use? We all using ACPI tree: git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm.git linux-next branch where ACPICA dependencies are included. It will be merged by upstream Linux soon, you can wait and try again or pull this branch to test. Created attachment 145161 [details]
dmesg "linux-pm" branch + 7 patches
Created attachment 145171 [details]
dmesg "linux-pm" branch + 7 patches + ACPI_DEBUG
I guess that I had to enable ACPI_DEBUG. So here it is.
(I've cloned "linux-pm" a few minutes ago, the last commit is 7b777942af148e5333d03440f46366b7bc543cfc).
(In reply to Steffen Weber from comment #20) > I guess that I had to enable ACPI_DEBUG. So here it is. Yes, thanks for doing this. :-) > (I've cloned "linux-pm" a few minutes ago, the last commit is > 7b777942af148e5333d03440f46366b7bc543cfc). I checked the log, didn't find any serious delays in it. It seems there was just too many AML stuff executed during the boot. I'll dig into the details using the decoded acpidump output. Maybe we could use some _OSI strings to bypass some initialization steps to make your platform boot faster. Thanks and best regards -Lv Recently I fixed a performance issue detected in the system memory operation region accesses. The patches can be found at: https://patchwork.kernel.org/patch/5137761/ https://patchwork.kernel.org/patch/5137771/ https://patchwork.kernel.org/patch/5137751/ https://patchwork.kernel.org/patch/5137731/ https://patchwork.kernel.org/patch/5137721/ https://patchwork.kernel.org/patch/5137691/ Could you please give them a try? Thanks and best regards -Lv I've applied all 6 patches on top of Linux 3.18-rc1. The kernel compiled and booted fine but the delay is still there ("ACPI: Interpreter enabled" happens at ~ 1.6 seconds).
Ah, so this is still a different issue... I'll check the executed AML opcodes... Thanks Hi,
The dynamic loaded tables are not in the dump.
I found them in ssdt4:
Name (SSDT, Package (0x0C)
{
"CPU0IST ",
0xB8708A98,
0x00000544,
"APIST ",
0xBBDE3698,
0x000005DB,
"CPU0CST ",
0xBBDE2918,
0x000003F3,
"APCST ",
0xBBDE1D98,
0x00000119
})
OperationRegion (CST0, SystemMemory, DerefOf (Index (SSDT, 0x07)), DerefOf (Index (SSDT, 0x08
)))
Load (CST0, HC0) /* \_PR_.CPU0.HC0_ */
OperationRegion (CST1, SystemMemory, DerefOf (Index (SSDT, 0x0A)), DerefOf (Index (SSDT, 0x0B
)))
Load (CST1, HC1) /* \_PR_.CPU1.HC1_ */
OperationRegion (IST1, SystemMemory, DerefOf (Index (SSDT, 0x04)), DerefOf (Index (SSDT, 0x05
)))
Load (IST1, HI1) /* \_PR_.CPU1.HI1_ */
Please try the following acpidump commands and upload the outputs:
acpidump -a 0xB8708A98
acpidump -a 0xBBDE3698
acpidump -a 0xBBDE2918
acpidump -a 0xBBDE1D98
Thanks and best regards
-Lv
# acpidump -a 0xB8708A98 ACPI tables were not found. If you know location of RSD PTR table (from dmesg, etc), supply it with either --addr or -a option Same for all 4 acpidump commands. But I supplied the "-a option"? :-/ You should try the acpidump compiled from the latest kernel source tree. It is under tools/power/acpi Or you should try the acpidump built from recent ACPICA source distribution. I think you might be failed to obtain the first table because it is not used in the ssdt4, so I will not be surprised if it really doesn't exist. The used tables are 0x04/0x07/0x0A of SSDT. So you should be able to obtain the latter 3 tables. Thanks! # ./acpidump -a 0xB8708A98 Cannot map /dev/mem Could not map table header at 0x00000000B8708A98 Could not get table at 0x00000000B8708A98, AE_BAD_ADDRESS As you said, the latter 3 tables worked. I'll attach them. Created attachment 155671 [details]
acpidump -a 0xBBDE3698
Created attachment 155681 [details]
acpidump -a 0xBBDE2918
Created attachment 155691 [details]
acpidump -a 0xBBDE1D98
Hi, Steffen I checked the dmesg, the entry control methods executed during boot are as follows: [ 0.104940] Begin [0xffff88042484b630:\_SB_.PCI0.LPCB.EC0_._STA] [ 0.106238] End [0xffff88042484b630:\_SB_.PCI0.LPCB.EC0_._STA] [ 0.106573] Begin [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.108888] End [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.109744] Begin [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 0.112052] End [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 0.112706] Begin [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.115018] End [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.115301] Begin [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.117613] End [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.117886] Begin [0xffff880424846510:\_SB_.PCI0.EHC1._REG] ? [ 0.125871] Begin [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.128185] End [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.130347] Begin [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.132657] End [0xffff8804248411b0:\_SB_.PCI0.GFX0._REG] [ 0.132931] Begin [0xffff880424846510:\_SB_.PCI0.EHC1._REG] [ 0.137281] End [0xffff880424846510:\_SB_.PCI0.EHC1._REG] [ 0.148933] Begin [0xffff8804248324c8:\_SB_._INI] [ 0.780243] End [0xffff8804248324c8:\_SB_._INI] [ 0.780508] Begin [0xffff880424841000:\_SB_.PCI0.PEGP._INI] [ 0.782839] End [0xffff880424841000:\_SB_.PCI0.PEGP._INI] [ 0.783101] Begin [0xffff880424844240:\_SB_.PCI0.GFX0._INI] [ 0.835756] End [0xffff880424844240:\_SB_.PCI0.GFX0._INI] [ 0.836026] Begin [0xffff88042484b630:\_SB_.PCI0.LPCB.EC0_._STA] [ 0.837311] End [0xffff88042484b630:\_SB_.PCI0.LPCB.EC0_._STA] [ 0.837574] Begin [0xffff88042484b798:\_SB_.PCI0.LPCB.EC0_._INI] [ 1.253396] End [0xffff88042484b798:\_SB_.PCI0.LPCB.EC0_._INI] [ 1.253667] Begin [0xffff88042484e9d8:\_SB_.PCI0.LPCB.SIO_._INI] [ 1.262680] End [0xffff88042484e9d8:\_SB_.PCI0.LPCB.SIO_._INI] [ 1.262944] Begin [0xffff880424856288:\_SB_.PCI0.RP01._STA] [ 1.269878] End [0xffff880424856288:\_SB_.PCI0.RP01._STA] [ 1.270138] Begin [0xffff880424850948:\_SB_.PCI0.RP01._INI] [ 1.274517] End [0xffff880424850948:\_SB_.PCI0.RP01._INI] [ 1.274778] Begin [0xffff8804248562d0:\_SB_.PCI0.RP02._STA] [ 1.285122] End [0xffff8804248562d0:\_SB_.PCI0.RP02._STA] [ 1.285382] Begin [0xffff880424856318:\_SB_.PCI0.RP03._STA] [ 1.293844] End [0xffff880424856318:\_SB_.PCI0.RP03._STA] [ 1.294104] Begin [0xffff880424856360:\_SB_.PCI0.RP04._STA] [ 1.302910] End [0xffff880424856360:\_SB_.PCI0.RP04._STA] [ 1.303170] Begin [0xffff880424853120:\_SB_.PCI0.RP04._INI] [ 1.307549] End [0xffff880424853120:\_SB_.PCI0.RP04._INI] [ 1.307810] Begin [0xffff8804248563a8:\_SB_.PCI0.RP05._STA] [ 1.316276] End [0xffff8804248563a8:\_SB_.PCI0.RP05._STA] [ 1.316536] Begin [0xffff8804248563f0:\_SB_.PCI0.RP06._STA] [ 1.323468] End [0xffff8804248563f0:\_SB_.PCI0.RP06._STA] [ 1.323727] Begin [0xffff8804248536c0:\_SB_.PCI0.RP06._INI] [ 1.329982] End [0xffff8804248536c0:\_SB_.PCI0.RP06._INI] [ 1.330243] Begin [0xffff880424853948:\_SB_.PCI0.RP07._STA] [ 1.337170] End [0xffff880424853948:\_SB_.PCI0.RP07._STA] [ 1.337430] Begin [0xffff880424853990:\_SB_.PCI0.RP07._INI] [ 1.341808] End [0xffff880424853990:\_SB_.PCI0.RP07._INI] [ 1.342069] Begin [0xffff880424853c18:\_SB_.PCI0.RP08._STA] [ 1.348996] End [0xffff880424853c18:\_SB_.PCI0.RP08._STA] [ 1.349255] Begin [0xffff880424853c60:\_SB_.PCI0.RP08._INI] [ 1.355507] End [0xffff880424853c60:\_SB_.PCI0.RP08._INI] [ 1.355769] Begin [0xffff880424856750:\_SB_.PCI0.ACEL._STA] [ 1.380454] End [0xffff880424856750:\_SB_.PCI0.ACEL._STA] [ 1.380713] Begin [0xffff880424856708:\_SB_.PCI0.ACEL._INI] [ 1.540219] End [0xffff880424856708:\_SB_.PCI0.ACEL._INI] [ 1.540480] Begin [0xffff88042487d510:\_SB_.PCI0.B0D3._STA] [ 1.544336] End [0xffff88042487d510:\_SB_.PCI0.B0D3._STA] [ 1.544596] Begin [0xffff88042487d558:\_SB_.PCI0.B0D3._INI] [ 1.554936] End [0xffff88042487d558:\_SB_.PCI0.B0D3._INI] [ 1.555245] Begin [0xffff880424832510:\_SB_._OSC] [ 1.575489] End [0xffff880424832510:\_SB_._OSC] [ 1.577672] Begin [0xffff88042487ab40:\_PR_.CPU0._PDC] [ 1.665948] ACPI: Dynamic OEM Table Load: [ 1.666139] ACPI: SSDT 0xFFFF8804241C1400 0003F3 (v01 PmRef Cpu0Cst 00003001 INTL 20110112) [ 1.703497] End [0xffff88042487ab40:\_PR_.CPU0._PDC] [ 1.703761] Begin [0xffff88042487aca8:\_PR_.CPU1._PDC] [ 1.789378] ACPI: Dynamic OEM Table Load: [ 1.789567] ACPI: SSDT 0xFFFF8804241D9800 0005DB (v01 PmRef ApIst 00003000 INTL 20110112) [ 2.028638] ACPI: Dynamic OEM Table Load: [ 2.028825] ACPI: SSDT 0xFFFF8804241CA400 000119 (v01 PmRef ApCst 00003000 INTL 20110112) [ 2.060141] End [0xffff88042487aca8:\_PR_.CPU1._PDC] [ 2.060406] Begin [0xffff88042487ae10:\_PR_.CPU2._PDC] [ 2.151319] End [0xffff88042487ae10:\_PR_.CPU2._PDC] [ 2.151582] Begin [0xffff88042487aee8:\_PR_.CPU3._PDC] [ 2.242483] End [0xffff88042487aee8:\_PR_.CPU3._PDC] [ 2.242867] Begin [0xffff880424850000:\_SB_.PCI0.LPCB.SIO_.LPT0._HID] [ 2.269904] End [0xffff880424850000:\_SB_.PCI0.LPCB.SIO_.LPT0._HID] [ 2.270172] Begin [0xffff88042485dab0:\_SB_.PCI0.LPCB.PS2M._HID] [ 2.311477] End [0xffff88042485dab0:\_SB_.PCI0.LPCB.PS2M._HID] [ 2.311804] Begin [0xffff88042485d3f0:\_SB_.GTPM._HID] [ 2.317024] End [0xffff88042485d3f0:\_SB_.GTPM._HID] [ 2.317349] Begin [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 4.559623] End [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 4.559924] ACPI: Interpreter enabled It seems the 1.5s delay happens after: [ 2.028825] ACPI: SSDT 0xFFFF8804241CA400 000119 (v01 PmRef ApCst 00003000 INTL 20110112) and before: [ 4.559924] ACPI: Interpreter enabled is caused by \_SB_.PCI0.LPCB.EC0_._REG execution: [ 2.317349] Begin [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 4.559623] End [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] The dynamic loaded tables themselves are not problem. It's strange that when the first time \_SB_.PCI0.LPCB.EC0_._REG is executed: [ 0.109744] Begin [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] [ 0.112052] End [0xffff88042484b6c0:\_SB_.PCI0.LPCB.EC0_._REG] It doesn't delay too much. I'll dig deeper in \_SB_.PCI0.LPCB.EC0_._REG executions see what's the difference. Thanks The first EC0._REG is executed because of non EmbeddedControl operation region registration, so it is no-op. And the second EC0._REG is executed for EmbeddedControl operation region registration. For second execution, I can only see many opcodes executed there, each takes a time (approximately 250us) equaling to the time taken by another opcode. There is no difference between EC access opcodes, mutex opcodes and simpler opcodes. So this means ACPICA AML interpreter can just only work as fast as this. From this log, it seems ACPICA AML interpreter is just even slower than the EC driver/firmware. So we can say ACPICA AML interpreter is the bottle neck. We may have chances to tune it faster, any small improvements can lead to great overall performance improvements. Let me try it. But TBH, I'm not sure if this can be taken as a bug. Yes, this is just a minor inconvenience. I usually boot my notebook once per day and therefore don't care that much about the delay. I nevertheless reported it because initially I thought that it could be a symptom of a real and maybe more severe bug. But that does not seem to be the case and you've already spent quiet some time on this issue. I'd be totally fine with closing this bug. You probably have real issues to work on. I'll definitely let you know if this bug disappears with a future kernel update. :) (In reply to Steffen Weber from comment #34) > Yes, this is just a minor inconvenience. I usually boot my notebook once per > day and therefore don't care that much about the delay. I nevertheless > reported it because initially I thought that it could be a symptom of a real > and maybe more severe bug. Thanks for saying that. :-) > But that does not seem to be the case and you've already spent quiet some > time on this issue. I'd be totally fine with closing this bug. You probably > have real issues to work on. I'll definitely let you know if this bug > disappears with a future kernel update. :) I'm still working on it. I'm writing a tool to convert the trace log into the SVG file like what scripts/bootgraph.pl can do for us. Using the analyzing tool, I found that some opcodes took more time than the others. Maybe there are real bugs. So I'm still validating the output. :-) Thanks and best regards -Lv Lv and Steffen, I'll close it for now, feel free to re-open it if there is a need. |
Created attachment 139251 [details] dmesg On my HP EliteBook 840 G1 (Core i7-4600U, Haswell, latest BIOS 1.11) there is a 1.5 second delay in the boot process before the message "ACPI: Interpreter enabled" appears. Nothing critical but seems like a bug. ... [ 0.135906] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored [ 0.152019] ACPI: SSDT 0x00000000BBDE2918 0003F3 (v01 PmRef Cpu0Cst 00003001 INTL 20110112) [ 0.152747] ACPI: Dynamic OEM Table Load: [ 0.152933] ACPI: SSDT 0x0000000000000000 0003F3 (v01 PmRef Cpu0Cst 00003001 INTL 20110112) [ 0.156157] ACPI: SSDT 0x00000000BBDE3698 0005DB (v01 PmRef ApIst 00003000 INTL 20110112) [ 0.157053] ACPI: Dynamic OEM Table Load: [ 0.157236] ACPI: SSDT 0x0000000000000000 0005DB (v01 PmRef ApIst 00003000 INTL 20110112) [ 0.160032] ACPI: SSDT 0x00000000BBDE1D98 000119 (v01 PmRef ApCst 00003000 INTL 20110112) [ 0.160762] ACPI: Dynamic OEM Table Load: [ 0.160945] ACPI: SSDT 0x0000000000000000 000119 (v01 PmRef ApCst 00003000 INTL 20110112) [ 1.671017] ACPI: Interpreter enabled ... I've attached the full dmesg, lspci, dmidecode and acpidump. I can test kernel patches (preferably for Linux 3.15).