Bug 12004

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.