Re: Linux 2.6.28-rc1] ACPI Warning (nspredef-0852)[...]

Zhao Yakui
2008-10-28T09:37:34Z

[-- Attachment #1: Type: text/plain, Size: 962 bytes --]

On Mon, 2008-10-27 at 13:19 -0700, Maciej Rutecki wrote:
> 2008/10/25 Maciej Rutecki <maciej.rutecki@gmail.com>:
> > Suspend to ram, but another machine (previous PC, now laptop) and
> > another problem:
> >
> > ACPI: EC: missing confirmations, switch off interrupt mode.
> > ACPI Exception (evregion-0419): AE_TIME, Returned by Handler for
> > [EmbeddedControl] [20080926]
> > ACPI Error (psparse-0524): Method parse/execution failed [\_TZ_.C31E]
> > (Node f7019858), AE_TIME
> > ACPI Error (psparse-0524): Method parse/execution failed
> > [\_TZ_.TZ3_._TMP] (Node f7019ed0), AE_TIME
Will you please try the attached patch on the latest kernel(2.6.28-rc1)
and see whether the issue still exists?

After the test, please attach the output of dmesg.
Thanks.
> >
> > It doesn't happened immediately after s2ram but is correlation between
> > s2ram and this error.
>
> I was wrong; it happens not only after suspend to ram but sometimes
> after normal boot.
>
>

[-- Attachment #2: ec_all.patch --]
[-- Type: text/x-patch, Size: 16358 bytes --]

a. EC transaction is divided into several phases.
For example: EC write transaction
a. issue EC write command
b. wait until the input is empty and then write the internal address
c. wait until the input is empty and write the data
d. wait until the input is empty. If it is empty, it indicates
that EC transaction is finished.
At the same time EC driver will be started in EC GEP mode. And when there is
no EC GPE confirmation for some EC transaction on some broken laptops,the EC
driver will be switched to polling mode. But EC GPE is still enabled.

b. Some delay is added in the EC GPE handler on some broken BIOS.
The delay won't be added for most laptops.Only when more than five
interrupts happen in the same jiffies and EC status are the same, OS will add
some delay in the EC GPE handler. If the same issue still happens after adding
delay,the delay time will be increased.But the max delay time is ten
microseconds.

Signed-off-by: Zhao Yakui <yakui.zhao@intel.com>
---
drivers/acpi/ec.c | 333 +++++++++++++++++++++++++++++++++++++-----------------
1 file changed, 233 insertions(+), 100 deletions(-)

Index: linux-2.6/drivers/acpi/ec.c
===================================================================
--- linux-2.6.orig/drivers/acpi/ec.c
+++ linux-2.6/drivers/acpi/ec.c
@@ -65,15 +65,25 @@ enum ec_command {
ACPI_EC_BURST_DISABLE = 0x83,
ACPI_EC_COMMAND_QUERY = 0x84,
};
+/* EC events */
+enum ec_event {
+ ACPI_EC_EVENT_OBF_1 = 1, /* Output buffer full */
+ ACPI_EC_EVENT_IBF_0, /* Input buffer empty */
+};

#define ACPI_EC_DELAY 500 /* Wait 500ms max. during EC ops */
#define ACPI_EC_UDELAY_GLK 1000 /* Wait 1ms max. to get global lock */
#define ACPI_EC_UDELAY 100 /* Wait 100us before polling EC again */

+#define EC_IRQ_NUM 5 /* the EC interrupt storm threshold */
+#define EC_MAX_UDELAY 10 /* the max udelay time */
+
#define ACPI_EC_STORM_THRESHOLD 20 /* number of false interrupts
per one transaction */

enum {
+ EC_FLAGS_WAIT_GPE, /* Don't check EC status
+ * until GPE arrives*/
EC_FLAGS_QUERY_PENDING, /* Query is pending */
EC_FLAGS_GPE_MODE, /* Expect GPE to be sent
* for status change */
@@ -111,11 +121,21 @@ static struct acpi_ec {
unsigned long data_addr;
unsigned long global_lock;
unsigned long flags;
+ unsigned long pre_jiffies;
+ /* record the jiffies when last EC interrupt happens */
struct mutex lock;
wait_queue_head_t wait;
struct list_head list;
struct transaction *curr;
spinlock_t curr_lock;
+ u8 pre_state;
+ /* record the EC status when last EC interrrupt happens */
+ atomic_t ec_irq_count;
+ unsigned long udelay;
+ /*
+ * this is for the input parameter of udelay in EC GPE interrupt.
+ * the max value is IRQ_MAX_UDELAY.(10)
+ */
} *boot_ec, *first_ec;

/*
@@ -210,18 +230,60 @@ unlock:
spin_unlock_irqrestore(&ec->curr_lock, flags);
}

-static int acpi_ec_wait(struct acpi_ec *ec)
+static inline int acpi_ec_check_status(struct acpi_ec *ec,
+ enum ec_event event)
{
- if (wait_event_timeout(ec->wait, ec_transaction_done(ec),
- msecs_to_jiffies(ACPI_EC_DELAY)))
+ if (test_bit(EC_FLAGS_WAIT_GPE, &ec->flags))
return 0;
- /* missing GPEs, switch back to poll mode */
- if (printk_ratelimit())
- pr_info(PREFIX "missing confirmations, "
- "switch off interrupt mode.\n");
- set_bit(EC_FLAGS_NO_GPE, &ec->flags);
- clear_bit(EC_FLAGS_GPE_MODE, &ec->flags);
- return 1;
+ if (event == ACPI_EC_EVENT_OBF_1) {
+ if (acpi_ec_read_status(ec) & ACPI_EC_FLAG_OBF)
+ return 1;
+ } else if (event == ACPI_EC_EVENT_IBF_0) {
+ if (!(acpi_ec_read_status(ec) & ACPI_EC_FLAG_IBF))
+ return 1;
+ }
+
+ return 0;
+}
+
+static int acpi_ec_wait(struct acpi_ec *ec, enum ec_event event, int force_poll)
+{
+ if (likely(test_bit(EC_FLAGS_GPE_MODE, &ec->flags)) &&
+ likely(!force_poll)) {
+ if (wait_event_timeout(ec->wait,
+ acpi_ec_check_status(ec, event),
+ msecs_to_jiffies(ACPI_EC_DELAY)))
+ return 0;
+ /* Check whether the bogus timeout happens */
+ if (!test_bit(EC_FLAGS_WAIT_GPE, &ec->flags) &&
+ acpi_ec_check_status(ec, event))
+ return 0;
+
+ clear_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
+ if (acpi_ec_check_status(ec, event)) {
+ /*
+ * Clear GPE mode flags. When EC internal register is
+ * accessed, EC driver will work in polling mode.
+ * But GPE is still enabled.
+ */
+ clear_bit(EC_FLAGS_GPE_MODE, &ec->flags);
+ return 0;
+ }
+ } else {
+ unsigned long delay = jiffies + msecs_to_jiffies(ACPI_EC_DELAY);
+ clear_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
+ while (time_before(jiffies, delay)) {
+ if (acpi_ec_check_status(ec, event))
+ return 0;
+ msleep(1);
+ }
+ if (acpi_ec_check_status(ec, event))
+ return 0;
+ }
+ pr_err(PREFIX "acpi_ec_wait timeout, status = 0x%2.2x, event = %s\n",
+ acpi_ec_read_status(ec),
+ (event == ACPI_EC_EVENT_OBF_1) ? "\"b0=1\"" : "\"b1=0\"");
+ return -ETIME;
}

static void acpi_ec_gpe_query(void *ec_cxt);
@@ -248,48 +310,51 @@ static int ec_poll(struct acpi_ec *ec)
}
return -ETIME;
}
-
-static int acpi_ec_transaction_unlocked(struct acpi_ec *ec,
- struct transaction *t,
+static int acpi_ec_transaction_unlocked(struct acpi_ec *ec, u8 command,
+ const u8 *wdata, unsigned wdata_len,
+ u8 *rdata, unsigned rdata_len,
int force_poll)
{
- unsigned long tmp;
- int ret = 0;
+ int result = 0;
+ set_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
pr_debug(PREFIX "transaction start\n");
- /* disable GPE during transaction if storm is detected */
- if (test_bit(EC_FLAGS_GPE_STORM, &ec->flags)) {
- clear_bit(EC_FLAGS_GPE_MODE, &ec->flags);
- acpi_disable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
- }
- /* start transaction */
- spin_lock_irqsave(&ec->curr_lock, tmp);
- /* following two actions should be kept atomic */
- t->irq_count = 0;
- ec->curr = t;
- acpi_ec_write_cmd(ec, ec->curr->command);
- if (ec->curr->command == ACPI_EC_COMMAND_QUERY)
+ acpi_ec_write_cmd(ec, command);
+ for (; wdata_len > 0; --wdata_len) {
+ result = acpi_ec_wait(ec, ACPI_EC_EVENT_IBF_0, force_poll);
+ if (result) {
+ pr_err(PREFIX
+ "write_cmd timeout, command = %d\n", command);
+ goto end;
+ }
+ set_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
+ acpi_ec_write_data(ec, *(wdata++));
+ }
+
+ if (!rdata_len) {
+ result = acpi_ec_wait(ec, ACPI_EC_EVENT_IBF_0, force_poll);
+ if (result) {
+ pr_err(PREFIX
+ "finish-write timeout, command = %d\n", command);
+ goto end;
+ }
+ } else if (command == ACPI_EC_COMMAND_QUERY)
clear_bit(EC_FLAGS_QUERY_PENDING, &ec->flags);
- spin_unlock_irqrestore(&ec->curr_lock, tmp);
- /* if we selected poll mode or failed in GPE-mode do a poll loop */
- if (force_poll ||
- !test_bit(EC_FLAGS_GPE_MODE, &ec->flags) ||
- acpi_ec_wait(ec))
- ret = ec_poll(ec);
- pr_debug(PREFIX "transaction end\n");
- spin_lock_irqsave(&ec->curr_lock, tmp);
- ec->curr = NULL;
- spin_unlock_irqrestore(&ec->curr_lock, tmp);
- if (test_bit(EC_FLAGS_GPE_STORM, &ec->flags)) {
- /* check if we received SCI during transaction */
- ec_check_sci(ec, acpi_ec_read_status(ec));
- /* it is safe to enable GPE outside of transaction */
- acpi_enable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
- } else if (test_bit(EC_FLAGS_GPE_MODE, &ec->flags) &&
- t->irq_count > ACPI_EC_STORM_THRESHOLD) {
- pr_debug(PREFIX "GPE storm detected\n");
- set_bit(EC_FLAGS_GPE_STORM, &ec->flags);
+
+ for (; rdata_len > 0; --rdata_len) {
+ result = acpi_ec_wait(ec, ACPI_EC_EVENT_OBF_1, force_poll);
+ if (result) {
+ pr_err(PREFIX "read timeout, command = %d\n", command);
+ goto end;
+ }
+ /* Don't expect GPE after last read */
+ if (rdata_len > 1)
+ set_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
+
+ *(rdata++) = acpi_ec_read_data(ec);
}
- return ret;
+end:
+ pr_debug(PREFIX "transaction end\n");
+ return result;
}

static int ec_check_ibf0(struct acpi_ec *ec)
@@ -310,35 +375,47 @@ static int ec_wait_ibf0(struct acpi_ec *
return -ETIME;
}

-static int acpi_ec_transaction(struct acpi_ec *ec, struct transaction *t,
+static int acpi_ec_transaction(struct acpi_ec *ec, u8 command,
+ const u8 *wdata, unsigned wdata_len,
+ u8 *rdata, unsigned rdata_len,
int force_poll)
{
int status;
u32 glk;
- if (!ec || (!t) || (t->wlen && !t->wdata) || (t->rlen && !t->rdata))
+
+ if (!ec || (wdata_len && !wdata) || (rdata_len && !rdata))
return -EINVAL;
- if (t->rdata)
- memset(t->rdata, 0, t->rlen);
+
+ if (rdata)
+ memset(rdata, 0, rdata_len);
+
mutex_lock(&ec->lock);
if (ec->global_lock) {
status = acpi_acquire_global_lock(ACPI_EC_UDELAY_GLK, &glk);
if (ACPI_FAILURE(status)) {
- status = -ENODEV;
- goto unlock;
+ mutex_unlock(&ec->lock);
+ return -ENODEV;
}
}
- if (ec_wait_ibf0(ec)) {
+
+ status = acpi_ec_wait(ec, ACPI_EC_EVENT_IBF_0, 0);
+ if (status) {
pr_err(PREFIX "input buffer is not empty, "
"aborting transaction\n");
- status = -ETIME;
goto end;
}
- status = acpi_ec_transaction_unlocked(ec, t, force_poll);
+
+ status = acpi_ec_transaction_unlocked(ec, command,
+ wdata, wdata_len,
+ rdata, rdata_len,
+ force_poll);
+
end:
+
if (ec->global_lock)
acpi_release_global_lock(glk);
-unlock:
mutex_unlock(&ec->lock);
+
return status;
}

@@ -349,32 +426,35 @@ unlock:
int acpi_ec_burst_enable(struct acpi_ec *ec)
{
u8 d;
- struct transaction t = {.command = ACPI_EC_BURST_ENABLE,
- .wdata = NULL, .rdata = &d,
- .wlen = 0, .rlen = 1};
-
- return acpi_ec_transaction(ec, &t, 0);
+ /*
+ * When burst enable command is issused, EC will put the EC burst
+ * acknowledge byte (0x90) into output buffer.
+ * Maybe it is worth checking the returned acknowledge bytes.
+ */
+ return acpi_ec_transaction(ec, ACPI_EC_BURST_ENABLE, NULL, 0, &d, 1, 0);
}

int acpi_ec_burst_disable(struct acpi_ec *ec)
{
- struct transaction t = {.command = ACPI_EC_BURST_DISABLE,
- .wdata = NULL, .rdata = NULL,
- .wlen = 0, .rlen = 0};
+ u8 d = acpi_ec_read_status(ec);
+ if (d & ACPI_EC_FLAG_BURST) {
+ /*
+ * Only when EC is in burst mode, it is necessary to disable.
+ */
+ return acpi_ec_transaction(ec, ACPI_EC_BURST_DISABLE, NULL,
+ 0, NULL, 0, 0);
+ }
+ return 0;

- return (acpi_ec_read_status(ec) & ACPI_EC_FLAG_BURST) ?
- acpi_ec_transaction(ec, &t, 0) : 0;
}

static int acpi_ec_read(struct acpi_ec *ec, u8 address, u8 * data)
{
int result;
u8 d;
- struct transaction t = {.command = ACPI_EC_COMMAND_READ,
- .wdata = &address, .rdata = &d,
- .wlen = 1, .rlen = 1};

- result = acpi_ec_transaction(ec, &t, 0);
+ result = acpi_ec_transaction(ec, ACPI_EC_COMMAND_READ,
+ &address, 1, &d, 1, 0);
*data = d;
return result;
}
@@ -382,11 +462,8 @@ static int acpi_ec_read(struct acpi_ec *
static int acpi_ec_write(struct acpi_ec *ec, u8 address, u8 data)
{
u8 wdata[2] = { address, data };
- struct transaction t = {.command = ACPI_EC_COMMAND_WRITE,
- .wdata = wdata, .rdata = NULL,
- .wlen = 2, .rlen = 0};
-
- return acpi_ec_transaction(ec, &t, 0);
+ return acpi_ec_transaction(ec, ACPI_EC_COMMAND_WRITE,
+ wdata, 2, NULL, 0, 0);
}

/*
@@ -448,13 +525,12 @@ int ec_transaction(u8 command,
u8 * rdata, unsigned rdata_len,
int force_poll)
{
- struct transaction t = {.command = command,
- .wdata = wdata, .rdata = rdata,
- .wlen = wdata_len, .rlen = rdata_len};
if (!first_ec)
return -ENODEV;

- return acpi_ec_transaction(first_ec, &t, force_poll);
+ return acpi_ec_transaction(first_ec, command, wdata,
+ wdata_len, rdata, rdata_len,
+ force_poll);
}

EXPORT_SYMBOL(ec_transaction);
@@ -463,9 +539,7 @@ static int acpi_ec_query(struct acpi_ec
{
int result;
u8 d;
- struct transaction t = {.command = ACPI_EC_COMMAND_QUERY,
- .wdata = NULL, .rdata = &d,
- .wlen = 0, .rlen = 1};
+
if (!ec || !data)
return -EINVAL;

@@ -475,7 +549,8 @@ static int acpi_ec_query(struct acpi_ec
* bit to be cleared (and thus clearing the interrupt source).
*/

- result = acpi_ec_transaction(ec, &t, 0);
+ result = acpi_ec_transaction(ec, ACPI_EC_COMMAND_QUERY,
+ NULL, 0, &d, 1, 0);
if (result)
return result;

@@ -549,29 +624,77 @@ static void acpi_ec_gpe_query(void *ec_c
}
mutex_unlock(&ec->lock);
}
+/*******************************************************************************
+*
+* FUNCTION: acpi_ec_gpe_delay
+*
+* PARAMETERS: struct acpi_ec *ec, the EC device
+ u8 state - the EC status when EC GPE interrupt happens
+
+* RETURN: No
+*
+* DESCRIPTION: detect whether there exists EC GPE interrupt storm. If yes, it
+ will try to add some delay to reduce the number of EC GPE
+ interrupts.
+******************************************************************************/
+static void acpi_ec_gpe_delay(struct acpi_ec *ec, u8 state)
+{
+ static int warn_done;
+ if ((jiffies == ec->pre_jiffies) && (state == ec->pre_state)) {
+ atomic_inc(&ec->ec_irq_count);
+ if (atomic_read(&ec->ec_irq_count) > EC_IRQ_NUM) {
+ /*
+ * If the ec_irq_count is above EC_IRQ_NUM, it will
+ * be regarded as EC GPE interrupt storm. We will
+ * try to add some udelay in acpi_ec_gpe_delay.
+ */
+ atomic_set(&ec->ec_irq_count, 0);
+ if (ec->udelay > EC_MAX_UDELAY) {
+ if (!warn_done) {
+ printk(KERN_WARNING "EC GPE interrupt"
+ " storm. And it is hardware issue\n");
+ warn_done++;
+ }
+ } else {
+ /*
+ * the input parameter of udelay will be
+ * increased.
+ */
+ ec->udelay = ec->udelay + 1;
+ }
+ }
+ } else {
+ ec->pre_jiffies = jiffies;
+ ec->pre_state = state;
+ atomic_set(&ec->ec_irq_count, 0);
+ }
+ if (ec->udelay)
+ udelay(ec->udelay);
+}

static u32 acpi_ec_gpe_handler(void *data)
{
struct acpi_ec *ec = data;
- u8 status;
+ u8 status ;
+ acpi_status ec_status = AE_OK;

pr_debug(PREFIX "~~~> interrupt\n");
status = acpi_ec_read_status(ec);

- gpe_transaction(ec, status);
- if (ec_transaction_done(ec) && (status & ACPI_EC_FLAG_IBF) == 0)
+ clear_bit(EC_FLAGS_WAIT_GPE, &ec->flags);
+ if (test_bit(EC_FLAGS_GPE_MODE, &ec->flags))
wake_up(&ec->wait);

- ec_check_sci(ec, status);
- if (!test_bit(EC_FLAGS_GPE_MODE, &ec->flags) &&
- !test_bit(EC_FLAGS_NO_GPE, &ec->flags)) {
- /* this is non-query, must be confirmation */
- if (printk_ratelimit())
- pr_info(PREFIX "non-query interrupt received,"
- " switching to interrupt mode\n");
- set_bit(EC_FLAGS_GPE_MODE, &ec->flags);
+ if (status & ACPI_EC_FLAG_SCI) {
+ if (!test_and_set_bit(EC_FLAGS_QUERY_PENDING, &ec->flags)) {
+ ec_status = acpi_os_execute(OSL_EC_BURST_HANDLER,
+ acpi_ec_gpe_query, ec);
+ }
}
- return ACPI_INTERRUPT_HANDLED;
+ acpi_ec_gpe_delay(ec, status);
+
+ return ACPI_SUCCESS(ec_status) ?
+ ACPI_INTERRUPT_HANDLED : ACPI_INTERRUPT_NOT_HANDLED;
}

/* --------------------------------------------------------------------------
@@ -712,10 +835,22 @@ static struct acpi_ec *make_acpi_ec(void
if (!ec)
return NULL;
ec->flags = 1 << EC_FLAGS_QUERY_PENDING;
+ /*
+ * Start GPE mode.
+ * When EC driver is started, it will work in GPE mode.
+ * It means that the EC GPE interrupt is expected when EC status is
+ * changed.
+ * Of course if there is no EC GPE interrupt in some EC transaction,
+ * it will be cleared and EC will work in polling mode when EC
+ * internal register is accessed.
+ */
+ set_bit(EC_FLAGS_GPE_MODE, &ec->flags);
mutex_init(&ec->lock);
init_waitqueue_head(&ec->wait);
INIT_LIST_HEAD(&ec->list);
spin_lock_init(&ec->curr_lock);
+ ec->pre_jiffies = jiffies;
+ atomic_set(&ec->ec_irq_count, 0);
return ec;
}

@@ -1004,8 +1139,6 @@ int __init acpi_ec_ecdt_probe(void)
static int acpi_ec_suspend(struct acpi_device *device, pm_message_t state)
{
struct acpi_ec *ec = acpi_driver_data(device);
- /* Stop using GPE */
- set_bit(EC_FLAGS_NO_GPE, &ec->flags);
clear_bit(EC_FLAGS_GPE_MODE, &ec->flags);
acpi_disable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
return 0;
@@ -1014,9 +1147,9 @@ static int acpi_ec_suspend(struct acpi_d
static int acpi_ec_resume(struct acpi_device *device)
{
struct acpi_ec *ec = acpi_driver_data(device);
- /* Enable use of GPE back */
- clear_bit(EC_FLAGS_NO_GPE, &ec->flags);
acpi_enable_gpe(NULL, ec->gpe, ACPI_NOT_ISR);
+ /* Enable use of GPE back */
+ set_bit(EC_FLAGS_GPE_MODE, &ec->flags);
return 0;
}