Bug 12004 - ACPI Error Method parse/execution failed with kernel 2.6.27.5
ACPI Error Method parse/execution failed with kernel 2.6.27.5
Status: CLOSED CODE_FIX
Product: ACPI
Classification: Unclassified
Component: EC
All Linux
: P1 normal
Assigned To: Alexey Starikovskiy
:
Depends on:
Blocks: 11808
  Show dependency treegraph
 
Reported: 2008-11-10 10:08 UTC by François Valenduc
Modified: 2008-11-12 21:28 UTC (History)
3 users (show)

See Also:
Kernel Version: 2.6.27.5
Tree: Mainline
Regression: Yes


Attachments
Output of dmesg (30.27 KB, text/plain)
2008-11-10 10:09 UTC, François Valenduc
Details
Output of dmesg | grep ACPI (3.83 KB, text/plain)
2008-11-10 13:16 UTC, François Valenduc
Details
Output of dmesg | grep ACPI with debug enabled (29.88 KB, text/plain)
2008-11-10 13:30 UTC, François Valenduc
Details
complete dmesg output with errors (512.21 KB, application/octet-stream)
2008-11-10 14:41 UTC, François Valenduc
Details
do transaction from GPE handler only in GPE mode (1.20 KB, patch)
2008-11-10 15:11 UTC, Alexey Starikovskiy
Details | Diff
do transaction from GPE handler only in GPE mode (984 bytes, patch)
2008-11-11 01:52 UTC, Alexey Starikovskiy
Details | Diff
Output of dmesg | grep ACPI with the first patch and without time in printk (2.93 KB, text/plain)
2008-11-11 04:04 UTC, François Valenduc
Details
kern.log file (353.79 KB, application/octet-stream)
2008-11-11 07:05 UTC, François Valenduc
Details
set of patches (9.28 KB, application/octet-stream)
2008-11-11 10:26 UTC, Alexey Starikovskiy
Details
Log with patches from your last patchset (69.81 KB, text/plain)
2008-11-11 12:21 UTC, François Valenduc
Details
Log with patches from your last patchset and debug (161.43 KB, application/octet-stream)
2008-11-11 13:04 UTC, François Valenduc
Details
series #2 (9.58 KB, application/octet-stream)
2008-11-11 14:11 UTC, Alexey Starikovskiy
Details

Description François Valenduc 2008-11-10 10:08:12 UTC
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:
Comment 1 François Valenduc 2008-11-10 10:09:10 UTC
Created attachment 18784 [details]
Output of dmesg
Comment 2 Rafael J. Wysocki 2008-11-10 10:43:10 UTC
This is a known issue and the patches for it are on their way to -stable, from what I can tell.
Comment 3 François Valenduc 2008-11-10 11:02:56 UTC
That is a good news but do you know where I can find these patches ?
Comment 4 Alexey Starikovskiy 2008-11-10 11:05:04 UTC
Did you try patches from 11994 bug report?
Comment 5 François Valenduc 2008-11-10 11:30:41 UTC
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.
Comment 6 Alexey Starikovskiy 2008-11-10 11:48:37 UTC
I noticed. Did you try first two patches?
Comment 7 François Valenduc 2008-11-10 11:52:48 UTC
Yes and it seems that these patches also solve this problem. 
Comment 8 Alexey Starikovskiy 2008-11-10 12:10:27 UTC
Could we then mark this bug as duplicate of 11994?
Comment 9 François Valenduc 2008-11-10 12:27:28 UTC
No, I was too optimistic. These two patches don't solve the problem. 
Comment 10 Alexey Starikovskiy 2008-11-10 12:53:13 UTC
please enable time in printk, and DEBUG in drivers/acpi/ec.c and attach dmesg here?
Comment 11 François Valenduc 2008-11-10 13:16:57 UTC
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 ?
Comment 12 Alexey Starikovskiy 2008-11-10 13:19:45 UTC
open file and uncomment #define DEBUG at very beginning of it.
Comment 13 François Valenduc 2008-11-10 13:30:14 UTC
Created attachment 18791 [details]
Output of dmesg | grep ACPI with debug enabled

So here is the dmesg output you asked.
Comment 14 Alexey Starikovskiy 2008-11-10 13:57:25 UTC
Could you find parts there either AE_TIME or "switching off interrupt mode" appears? in /var/log/kern.log ?
Comment 15 François Valenduc 2008-11-10 14:02:47 UTC
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 ?
Comment 16 Alexey Starikovskiy 2008-11-10 14:09:01 UTC
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?
Comment 17 François Valenduc 2008-11-10 14:21:08 UTC
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.
Comment 18 François Valenduc 2008-11-10 14:41:43 UTC
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.
Comment 19 Alexey Starikovskiy 2008-11-10 15:11:51 UTC
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.
Comment 20 François Valenduc 2008-11-10 15:35:02 UTC
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 ?
Comment 21 Alexey Starikovskiy 2008-11-11 01:52:44 UTC
Created attachment 18797 [details]
do transaction from GPE handler only in GPE mode

Please test if this patch still works.
Comment 22 François Valenduc 2008-11-11 04:03:44 UTC
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.
Comment 23 François Valenduc 2008-11-11 04:04:29 UTC
Created attachment 18800 [details]
Output of dmesg | grep ACPI with the first patch and without time in printk
Comment 24 Alexey Starikovskiy 2008-11-11 05:32:17 UTC
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?

Comment 25 François Valenduc 2008-11-11 06:04:52 UTC
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.
Comment 26 Alexey Starikovskiy 2008-11-11 06:20:10 UTC
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.
Comment 27 Alexey Starikovskiy 2008-11-11 06:21:57 UTC
With the kernel log is missing some features, please try to increase the size of 
printk buffer -- time does consume it.
Comment 28 François Valenduc 2008-11-11 06:28:49 UTC
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 ?
Comment 29 Alexey Starikovskiy 2008-11-11 06:33:04 UTC
General setup -> Kernel log buffer size. I have 18 (256kb) there.
Comment 30 François Valenduc 2008-11-11 07:05:22 UTC
Created attachment 18802 [details]
kern.log file

So here is the log output you were asking for. The error is at the line 756.
Comment 31 Alexey Starikovskiy 2008-11-11 10:11:59 UTC
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. 
Comment 32 Alexey Starikovskiy 2008-11-11 10:26:48 UTC
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.
Comment 33 François Valenduc 2008-11-11 10:32:35 UTC
You are speaking about 1.patch in the list but I don't find it. Is it normal ?
Comment 34 Alexey Starikovskiy 2008-11-11 10:45:51 UTC
please show comment number...
Comment 35 François Valenduc 2008-11-11 10:56:43 UTC
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]

Comment 36 François Valenduc 2008-11-11 11:06:36 UTC
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
Comment 37 Alexey Starikovskiy 2008-11-11 12:09:41 UTC
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?
Comment 38 François Valenduc 2008-11-11 12:21:04 UTC
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
Comment 39 Alexey Starikovskiy 2008-11-11 12:40:38 UTC
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?
Comment 40 François Valenduc 2008-11-11 13:04:10 UTC
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 ?
Comment 41 Alexey Starikovskiy 2008-11-11 13:07:52 UTC
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...
Comment 42 Alexey Starikovskiy 2008-11-11 14:11:35 UTC
Created attachment 18812 [details]
series #2

Please test with the ec.c from this tarball.
Comment 43 François Valenduc 2008-11-11 14:31:03 UTC
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·
Comment 44 François Valenduc 2008-11-12 14:06:20 UTC
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.
Comment 45 Len Brown 2008-11-12 21:28:24 UTC
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.

Note You need to log in before you can comment on or make changes to this bug.