Latest working kernel version: 2.6.27.4 Earliest failing kernel version: 2.6.27.5 Distribution: Gentoo 64 bits Hardware Environment: Packard Bell Easynote MB86, Intel Core 2 Duo Software Environment: Problem Description: With kernel 2.6.27.5, I see frequently the following error in dmesg: ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1.UPBS] (Node ffff8800bf0139e0), AE_TIME ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] As far as I can search, this problem didn't occur with earlier kernel versions. I have looked in the logs and I can't find such errors before having upgraded to the latest kernel. Steps to reproduce:
Created attachment 18784 [details] Output of dmesg
This is a known issue and the patches for it are on their way to -stable, from what I can tell.
That is a good news but do you know where I can find these patches ?
Did you try patches from 11994 bug report?
This is also a bug I reported myself and as I said there, I can't apply the last patch (reset failed transaction) because it gives rejects.
I noticed. Did you try first two patches?
Yes and it seems that these patches also solve this problem.
Could we then mark this bug as duplicate of 11994?
No, I was too optimistic. These two patches don't solve the problem.
please enable time in printk, and DEBUG in drivers/acpi/ec.c and attach dmesg here?
Created attachment 18787 [details] Output of dmesg | grep ACPI In fact, this problem is intermittent, which made me think at first that the patches had solved it. I managed to enable time in printk but how do I enable debug in ec.c ?
open file and uncomment #define DEBUG at very beginning of it.
Created attachment 18791 [details] Output of dmesg | grep ACPI with debug enabled So here is the dmesg output you asked.
Could you find parts there either AE_TIME or "switching off interrupt mode" appears? in /var/log/kern.log ?
I don't understand very well what you asked. These two messages appears in this dmesg output. Do you want the full kernel output not limited to ACPI messages ? What I don't understand very well too is that sometime, EC doesn't seems to be enabled. It happens that I don't find messages related to EC in dmesg and if I reboot, these messages appears. Is it possible that EC gets enabled or not with exactly the same kernel and the same boot options ?
In last log there is no errors, only small part of transaction log (working), while I'm looking for transaction log around error cases. EC should be always enabled, and it should at least print it's "Looking up" string. It could be that your dmesg is too short and rolls over EC messages?
I have currently disabled ec debug but I notice another problem. Sometime, klaptopdaemon briefly stop displaying the state of the battery and indicates that there are no battery plugged. At the same time, I get the following errors in dmesg: Nov 10 23:15:21 pc-francois [ 1742.310306] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:15:21 pc-francois [ 1742.310321] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.THRM._TMP] (Node ffff8800bf013500), AE_TIME Nov 10 23:15:23 pc-francois [ 1744.319334] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:15:23 pc-francois [ 1744.319350] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1.UPBS] (Node ffff8800bf0139e0), AE_TIME Nov 10 23:15:23 pc-francois [ 1744.319385] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:15:23 pc-francois [ 1744.319413] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:15:49 pc-francois [ 1770.310352] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:15:49 pc-francois [ 1770.310365] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.THRM._TMP] (Node ffff8800bf013500), AE_TIME Nov 10 23:16:11 pc-francois [ 1791.607263] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:11 pc-francois [ 1791.607280] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1.UPBS] (Node ffff8800bf0139e0), AE_TIME Nov 10 23:16:11 pc-francois [ 1791.607316] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:16:11 pc-francois [ 1791.607346] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:16:11 pc-francois [ 1792.121351] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:11 pc-francois [ 1792.121366] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1.UPBS] (Node ffff8800bf0139e0), AE_TIME Nov 10 23:16:11 pc-francois [ 1792.121399] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:16:11 pc-francois [ 1792.121426] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:16:17 pc-francois [ 1798.310105] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:17 pc-francois [ 1798.310125] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.THRM._TMP] (Node ffff8800bf013500), AE_TIME Nov 10 23:16:25 pc-francois [ 1806.313039] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:25 pc-francois [ 1806.313053] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:16:25 pc-francois [ 1806.313094] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:16:31 pc-francois [ 1811.612276] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:31 pc-francois [ 1811.612298] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._STA] (Node ffff8800bf013960), AE_TIME Nov 10 23:16:31 pc-francois [ 1811.612340] ACPI Exception (battery-0310): AE_ERROR, Evaluating _STA [20080609] Nov 10 23:16:35 pc-francois [ 1816.310361] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:35 pc-francois [ 1816.310378] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.THRM._TMP] (Node ffff8800bf013500), AE_TIME Nov 10 23:16:49 pc-francois [ 1829.897278] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:16:49 pc-francois [ 1829.897295] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:16:49 pc-francois [ 1829.897332] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:17:05 pc-francois [ 1846.310055] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:17:05 pc-francois [ 1846.310075] ACPI Error (psparse-0530): Method parse/execution failed [\_TZ_.THRM._TMP] (Node ffff8800bf013500), AE_TIME I have filtered kernel messages and I have reenabled EC debug. I hope to find what you are looking for.
Created attachment 18792 [details] complete dmesg output with errors So, I think I found what you were looking for. I see these lines in dmesg when ec debug enabled and when there are errors: Nov 10 23:26:27 pc-francois [ 121.823352] ACPI: EC: transaction end Nov 10 23:26:27 pc-francois [ 121.823356] ACPI: EC: ---> status = 0x00 Nov 10 23:26:27 pc-francois [ 121.823359] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] Nov 10 23:26:27 pc-francois [ 121.823371] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BST] (Node ffff8800bf0139a0), AE_TIME Nov 10 23:26:27 pc-francois [ 121.823416] ACPI Exception (battery-0360): AE_TIME, Evaluating _BST [20080609] Nov 10 23:26:27 pc-francois [ 121.823619] ACPI: EC: ---> status = 0x00 Nov 10 23:26:27 pc-francois [ 121.823628] ACPI: EC: transaction start Nov 10 23:26:27 pc-francois [ 121.823630] ACPI: EC: <--- command = 0x82 Nov 10 23:26:27 pc-francois [ 121.823736] ACPI: EC: ---> status = 0x0a Nov 10 23:26:27 pc-francois [ 121.823840] ACPI: EC: ---> status = 0x0a Nov 10 23:26:27 pc-francois [ 121.823944] ACPI: EC: ---> status = 0x08 Nov 10 23:26:27 pc-francois [ 121.823993] ACPI: EC: ~~~> interrupt Nov 10 23:26:27 pc-francois [ 121.823997] ACPI: EC: ---> status = 0x19 Nov 10 23:26:27 pc-francois [ 121.824001] ACPI: EC: ---> data = 0x90 Nov 10 23:26:27 pc-francois [ 121.824024] ACPI: EC: ~~~> interrupt Nov 10 23:26:27 pc-francois [ 121.824027] ACPI: EC: ---> status = 0x18 Nov 10 23:26:27 pc-francois [ 121.824051] ACPI: EC: ~~~> interrupt Nov 10 23:26:27 pc-francois [ 121.824055] ACPI: EC: ---> status = 0x18 Nov 10 23:26:27 pc-francois [ 121.824061] ACPI: EC: transaction end I also put the full dmesg output copied from /var/log/kern.log in attachment.
Created attachment 18793 [details] do transaction from GPE handler only in GPE mode Could you please check if this patch helps? Should apply on top.
This patch seems to solve the problem. However, with this one, I dont' find any EC related messages in dmesg or in kern.log. Is this really normal ?
Created attachment 18797 [details] do transaction from GPE handler only in GPE mode Please test if this patch still works.
I tried your second patch and the error still occurs. So, I retry the first version and the problem as not yet occured again. What I don't understand is that if I disable time in printk and now, I see the messages related to EC in dmesg or in kern.log. If I enable time in printk, I can never see these messages.
Created attachment 18800 [details] Output of dmesg | grep ACPI with the first patch and without time in printk
Francois, Could you please attach log from the second patch and errors and DEBUG in ec.c and time in printk? I don't quite understand about time in printk -- if you enable it, does the error remain, but it is missing from logs ? Or does the error itself wanish?
So, with debug enabled in ec.c and with the second patch, the error is similar to the one I get without patch (see commennt #18). If I use the first patch, it seems to work correctly with or without time in printk. But with time in printk, the dmesg output seems to be limited and I don't find anything related to EC in kern.log. I also have the impression that using time in printk limit the messaged and errors copied in this file and in dmesg because other logs from the kernel are missing. To sum up, I think that your first patch solves the problem. I don't see the errors anymore and the problem with the battery status (see comment #17) doesn't occur too. What remains strange is the fact that using time in printk limit the kernel logs.
Francois, First patch did two fings, it disabled transition to interrupt mode and disabled doing transaction from interrupt handler if in poll mode. Without the patch or with the second patch your machine should try to enable interrupt mode, then report missing interrupts and switch to poll mode again, then stay in poll mode. After this point first and second patches should behave the same, but you report that first one works, while second fails. It means that I don't understand the problem, and I _need_ to see the log from the second patch. In particular, I need to see the interrupt->poll transition and AE_TIME occurance with second patch. Thanks for understanding.
With the kernel log is missing some features, please try to increase the size of printk buffer -- time does consume it.
But with the second patch, the logs are exactly the same that without any patch. It fails in the same way. How can I increase the since of the printk buffer ?
General setup -> Kernel log buffer size. I have 18 (256kb) there.
Created attachment 18802 [details] kern.log file So here is the log output you were asking for. The error is at the line 756.
Francois, thanks! It is really line 16808, there it gets interesting... EC controller went out of burst mode and abandoned current transaction. Driver did not understood this and waited .5 sec for completion of abandoned transaction. Could you provide 'cat /proc/interrupts' and it looks like the patch #3 from #11994 might be required to handle this situation. I'll attach proper patch for 27.5 ASAP.
Created attachment 18806 [details] set of patches Here is a set of patches and successfully patched 2.6.27.5 ec.c file. I did not find any problem with applying patches. Please check.
You are speaking about 1.patch in the list but I don't find it. Is it normal ?
please show comment number...
I was speaking of the line "1.patch" in the "series" files from your patchset. So I apply all your patches and I compared my ec.c file with the one from your set and it was the same file. However, your patches doesn't solve the problem. This error still occurs approximately 10 seconds after boot: [ 10.928151] ACPI: EC: missing confirmations, switch off interrupt mode. [ 11.428080] ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for [EmbeddedControl] [20080609] [ 11.428106] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.PCI0.LPCB.EC0_.SMRD] (Node ffff8800bf017ea0), AE_TIME [ 11.428197] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1.UPBI] (Node ffff8800bf0139c0), AE_TIME [ 11.428272] ACPI Error (psparse-0530): Method parse/execution failed [\_SB_.BAT1._BIF] (Node ffff8800bf013980), AE_TIME [ 11.428348] ACPI Exception (battery-0330): AE_TIME, Evaluating _BIF [20080609]
So I revert your last patch (dont_do_transaction_from_gpe_handler_in_poll_mode.patch) and I reapply the 1st patch from this bug report and this error doesn't occur. This one seems really to solve the problem, unless the error I mentionned in the previous comment is benign. As you asked in comment #31, I also post the output of cat /proc/interrupts obtained with the first patch of this bug report: CPU0 CPU1 0: 32652 32445 IO-APIC-edge timer 1: 262 223 IO-APIC-edge i8042 8: 0 1 IO-APIC-edge rtc0 9: 9291 9381 IO-APIC-fasteoi acpi 12: 71 65 IO-APIC-edge i8042 14: 1021 1013 IO-APIC-edge ide0 15: 0 0 IO-APIC-edge ide1 16: 6644 6718 IO-APIC-fasteoi uhci_hcd:usb1, ohci1394, nvidia 17: 0 0 IO-APIC-fasteoi mmc0 18: 12 10 IO-APIC-fasteoi ahci, ehci_hcd:usb3, uhci_hcd:usb6 19: 4842 5008 IO-APIC-fasteoi uhci_hcd:usb5 21: 0 0 IO-APIC-fasteoi uhci_hcd:usb2 22: 47 50 IO-APIC-fasteoi HDA Intel 23: 1 2 IO-APIC-fasteoi uhci_hcd:usb4, ehci_hcd:usb7 503: 2382 2309 PCI-MSI-edge iwlagn 504: 0 1 PCI-MSI-edge eth0 505: 5692 5659 PCI-MSI-edge ahci NMI: 0 0 Non-maskable interrupts LOC: 59777 67291 Local timer interrupts RES: 8447 9086 Rescheduling interrupts CAL: 2256 7208 function call interrupts TLB: 2242 2337 TLB shootdowns SPU: 0 0 Spurious interrupts ERR: 0
first patch comments out switch to interrupt mode, so it can not be applied as a generic solution. could you please attach a kernel log from run with the ec.c I've sent you?
Created attachment 18810 [details] Log with patches from your last patchset Here is the log obtain with the patches from your last set. I haven't enabled debug in ec.c
Francois, I understand, that it is boring to help debug some one elses' bug, and more so, if solution that suits you is already found... Problem is, that ACPI does not receive any testing in -mm, -next, and even -rc kernels. So looking innocent patches, would break someones hardware as soon as they hit the -stable series. With ACPI EC driver, there is constant stream of bug reports from cheap Taiwan-made notebooks, and with invention of netbooks this stream gets wider. And, it appears that I'm not aware of the problem until patch hits the -stable kernel as it happens now. I'm trying to resolve this situation, but it gets time. Please send the log with enabled DEBUG, please? Do I understand right, and there is more AE_TIME errors after the first one with the series applied?
Created attachment 18811 [details] Log with patches from your last patchset and debug So here is another log output with debug enabled. If I understand correctly, the first patch you send yesterday is a good solution for my computer but it might not be applicable on other ones ?
Correct. It hurts performance to be in poll mode, and actually, I think your machine does not need to sit in poll mode either -- if we find a problem in the code...
Created attachment 18812 [details] series #2 Please test with the ec.c from this tarball.
I think these patches are better. Now, EC works in interrupt mode and the parse error doesn't occur. However, sometime, I saw this error after a longer time. So, I will continue to test tommorrow. Thanks for your help·
I have noticed that these patches where merged in the mainline kernel and they really solve the problem. I presume we can close this bug.
commit 8517934ef6aaa28d6e055b98df65b31cedbd1372 Author: Alexey Starikovskiy <astarikovskiy@suse.de> Date: Tue Nov 11 12:54:11 2008 +0300 ACPI: EC: Don't do transaction from GPE handler in poll mode. shipped in 2.6.28-rc4-git3 closed.