From: Pan Xinhui <[email protected]>
printk can be called in any context, It's very useful to output debug
info.
But it might cause very bad issues on some special cases. For example,
some driver hit errors, and it dumps many messages like reg values, etc.
Sometimes, printk is called when irqs disabled. This is OKay if there is
a few messages. But What would happen if many messages outputed by other
drivers at same time.
Here is the scenario.
CPUA CPUB
//driver dumps debug info local_irq_save(flags);
printk()
-> console_unlock()
printk() for(;;) {
-> log_store() //log_next_seq++
//many printk() below if (console_seq == log_next_seq)
break;
//did not break in this case
//no printk() now }
local_irq_restore(flags);
printk runs on CPUA just store the messages in the buf and return.
printk runs on CPUB(who owns the console_sem lock) would take the duty
to flush all messages to consoles. It would take a long time to flush
messages out, IOW, irq would be disabled for a long time. Such case is
too bad. We hit many interrupt related panics, for example, cpu did not
respond to IPI.
Here is the soultion, if we detect such case above, try to rebalance it.
Let CPUA take the duty to flush messages to consoles.
Introduce five states, START, REQUEST, REPLY, ACK, CANCEL.
Introduce five actions, request, reply, cancel, ack, start.
Only two kinds of state transition are allowed. They are
1) request reply ack start
-> START ------> REQUEST -----> REPLY -----> ACK ----->
| |
<------------------------------------------------------
2) request cancel start
-> START ------> REQUEST -----> CANCEL ----->
| |
<--------------------------------------------
To implement the five actions, introduce rebalance_try_request(),
rebalance_try_reply(), rebalance_try_cancel(), rebalance_try_ack(). As
action start is always after ack and cancel. rebalance_try_cancel/ack
would do start as well for simplicity.
State transition must be performed with logbuf_lock held.
When we have done the state transition, CPUB who owns the console_sem
will up rebalance_sem as well. CPUA who is going to take duty fo flush
messages will down_trylock rebalance_sem. The seqence to up/down two
sems must be like below, otherwise we might has risks that no one owns
console_sem to do flush job.
CPUA CPUB
down_trylock(&rebalance_sem) up(&console_sem)
up(&rebalance_sem);
down_trylock(&console_sem);
Signed-off-by: Pan Xinhui <[email protected]>
---
change from v1:
rewrite the patch.
---
kernel/printk/printk.c | 100 ++++++++++++++++++++++++++++++++++++++++++++++++-
1 file changed, 99 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cf8c242..1ffbd32 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1652,6 +1652,69 @@ static size_t cont_print_text(char *text, size_t size)
return textlen;
}
+#define START 1
+#define CANCEL 2
+#define ACK 4
+#define REQUEST 8
+#define REPLY 16
+
+static struct semaphore rebalance_sem =
+ __SEMAPHORE_INITIALIZER(rebalance_sem, 0);
+
+static inline bool accept(int *v, int s, int *p)
+{
+ if (*v & s) {
+ *p = *v & s;
+ *v &= ~*p;
+ return true;
+ }
+ return 0;
+}
+
+/* protected by logbuf_lock*/
+static bool rebalance(int v)
+{
+ static int cur = START;
+ int pos = cur;
+ bool ret = 0;
+
+ do {
+ switch (pos) {
+ case START:
+ ret = accept(&v, REQUEST, &pos);
+ break;
+ case CANCEL:
+ ret = accept(&v, START, &pos);
+ break;
+ case ACK:
+ ret = accept(&v, START, &pos);
+ break;
+ case REQUEST:
+ ret = accept(&v, CANCEL | REPLY, &pos);
+ break;
+ case REPLY:
+ ret = accept(&v, ACK, &pos);
+ break;
+ default:
+ ret = 0;
+ break;
+ }
+ } while (ret && v);
+
+ if (ret)
+ cur = pos;
+ return ret;
+}
+
+#define rebalance_try_request() \
+ rebalance(REQUEST)
+#define rebalance_try_reply() \
+ rebalance(REPLY)
+#define rebalance_try_cancel() \
+ rebalance(CANCEL)
+#define rebalance_try_ack() \
+ rebalance(ACK | START)
+
asmlinkage int vprintk_emit(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, va_list args)
@@ -1667,6 +1730,8 @@ asmlinkage int vprintk_emit(int facility, int level,
bool in_sched = false;
/* cpu currently holding logbuf_lock in this function */
static unsigned int logbuf_cpu = UINT_MAX;
+ bool need_rebalance = 0;
+ bool can_rebalance = !(irqs_disabled() || in_interrupt());
if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
@@ -1701,6 +1766,8 @@ asmlinkage int vprintk_emit(int facility, int level,
lockdep_off();
raw_spin_lock(&logbuf_lock);
+ if (!in_sched && can_rebalance && rebalance_try_reply())
+ need_rebalance = true;
logbuf_cpu = this_cpu;
if (unlikely(recursion_bug)) {
@@ -1811,6 +1878,9 @@ asmlinkage int vprintk_emit(int facility, int level,
*/
preempt_disable();
+ if (need_rebalance)
+ while (down_trylock(&rebalance_sem))
+ cpu_relax();
/*
* Try to acquire and then immediately release the console
* semaphore. The release will print out buffers and wake up
@@ -2230,6 +2300,7 @@ void console_unlock(void)
unsigned long flags;
bool wake_klogd = false;
bool retry;
+ bool need_rebalance = !!(irqs_disabled() || in_interrupt());
if (console_suspended) {
up_console_sem();
@@ -2248,6 +2319,15 @@ again:
int level;
raw_spin_lock_irqsave(&logbuf_lock, flags);
+ if (need_rebalance) {
+ if (rebalance_try_ack())
+ break;
+ /*
+ * No need to check the ret value.
+ */
+ rebalance_try_cancel();
+ rebalance_try_request();
+ }
if (seen_seq != log_next_seq) {
wake_klogd = true;
seen_seq = log_next_seq;
@@ -2265,8 +2345,17 @@ again:
len = 0;
}
skip:
- if (console_seq == log_next_seq)
+ if (console_seq == log_next_seq) {
+ if (need_rebalance) {
+ rebalance_try_cancel();
+ /*
+ * break without rebalance, then no need to
+ * up rebalance_sem, set need_rebalance to NULL.
+ */
+ need_rebalance = 0;
+ }
break;
+ }
msg = log_from_idx(console_idx);
if (msg->flags & LOG_NOCONS) {
@@ -2318,6 +2407,14 @@ skip:
up_console_sem();
+ if (need_rebalance) {
+ /*
+ * Need call up_console_sem first.
+ */
+ up(&rebalance_sem);
+ goto wake_up;
+ }
+
/*
* Someone could have filled up the buffer again, so re-check if there's
* something to flush. In case we cannot trylock the console_sem again,
@@ -2331,6 +2428,7 @@ skip:
if (retry && console_trylock())
goto again;
+wake_up:
if (wake_klogd)
wake_up_klogd();
}
--
1.9.1
hi, all
I think you have already known how to reproduce it. Let me still share the debug patch to hit this printk issue in several seconds.
+static int auto_printk(void *data)
+{
+ int irq = (int)data;
+ char b[64] = {
+ [0 ... 61] = 'F',
+ '\n',
+ 0,
+ };
+
+ int bytes_per_second = 115200/8; //minicom console ratelimit
+ int lines_per_second = bytes_per_second/(sizeof(b)+16);//16 is count of extra bytes including log_prefix
+ int lines_with_5sec = lines_per_second * 5;
+ int i = lines_with_5sec;
+
+ if (irq)
+ local_irq_disable();
+ unsigned long j = jiffies;
+ unsigned long k = jiffies;
+ while (i--) {
+ printk("[%1d][%d]%s", irq, i, b);
+ k = jiffies;
+ if (k > j + 5 * HZ) {
+ printk("XINHUI: long time %d,%d\n", irq, irqs_disabled());
+ }
+ j = k;
+ }
+ if (irq)
+ local_irq_enable();
+ return 0;
+}
+static int xh_th(const char *val, struct kernel_param *kp)
+{
+ kthread_run(auto_printk, 1, "XH_T1");
+ kthread_run(auto_printk, 0, "XH_T0");
+}
+module_param_call(th, NULL, xh_th, NULL, 0664);
+
thanks
xinhui
On 2015年08月12日 17:37, Pan Xinhui wrote:
> From: Pan Xinhui <[email protected]>
>
> printk can be called in any context, It's very useful to output debug
> info.
>
> But it might cause very bad issues on some special cases. For example,
> some driver hit errors, and it dumps many messages like reg values, etc.
>
> Sometimes, printk is called when irqs disabled. This is OKay if there is
> a few messages. But What would happen if many messages outputed by other
> drivers at same time.
>
> Here is the scenario.
> CPUA CPUB
> //driver dumps debug info local_irq_save(flags);
> printk()
> -> console_unlock()
> printk() for(;;) {
> -> log_store() //log_next_seq++
>
> //many printk() below if (console_seq == log_next_seq)
> break;
> //did not break in this case
> //no printk() now }
> local_irq_restore(flags);
>
> printk runs on CPUA just store the messages in the buf and return.
> printk runs on CPUB(who owns the console_sem lock) would take the duty
> to flush all messages to consoles. It would take a long time to flush
> messages out, IOW, irq would be disabled for a long time. Such case is
> too bad. We hit many interrupt related panics, for example, cpu did not
> respond to IPI.
>
> Here is the soultion, if we detect such case above, try to rebalance it.
> Let CPUA take the duty to flush messages to consoles.
>
> Introduce five states, START, REQUEST, REPLY, ACK, CANCEL.
> Introduce five actions, request, reply, cancel, ack, start.
> Only two kinds of state transition are allowed. They are
>
> 1) request reply ack start
> -> START ------> REQUEST -----> REPLY -----> ACK ----->
> | |
> <------------------------------------------------------
>
> 2) request cancel start
> -> START ------> REQUEST -----> CANCEL ----->
> | |
> <--------------------------------------------
>
> To implement the five actions, introduce rebalance_try_request(),
> rebalance_try_reply(), rebalance_try_cancel(), rebalance_try_ack(). As
> action start is always after ack and cancel. rebalance_try_cancel/ack
> would do start as well for simplicity.
>
> State transition must be performed with logbuf_lock held.
>
> When we have done the state transition, CPUB who owns the console_sem
> will up rebalance_sem as well. CPUA who is going to take duty fo flush
> messages will down_trylock rebalance_sem. The seqence to up/down two
> sems must be like below, otherwise we might has risks that no one owns
> console_sem to do flush job.
>
> CPUA CPUB
> down_trylock(&rebalance_sem) up(&console_sem)
> up(&rebalance_sem);
> down_trylock(&console_sem);
>
> Signed-off-by: Pan Xinhui <[email protected]>
> ---
> change from v1:
> rewrite the patch.
> ---
> kernel/printk/printk.c | 100 ++++++++++++++++++++++++++++++++++++++++++++++++-
> 1 file changed, 99 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index cf8c242..1ffbd32 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1652,6 +1652,69 @@ static size_t cont_print_text(char *text, size_t size)
> return textlen;
> }
>
> +#define START 1
> +#define CANCEL 2
> +#define ACK 4
> +#define REQUEST 8
> +#define REPLY 16
> +
> +static struct semaphore rebalance_sem =
> + __SEMAPHORE_INITIALIZER(rebalance_sem, 0);
> +
> +static inline bool accept(int *v, int s, int *p)
> +{
> + if (*v & s) {
> + *p = *v & s;
> + *v &= ~*p;
> + return true;
> + }
> + return 0;
> +}
> +
> +/* protected by logbuf_lock*/
> +static bool rebalance(int v)
> +{
> + static int cur = START;
> + int pos = cur;
> + bool ret = 0;
> +
> + do {
> + switch (pos) {
> + case START:
> + ret = accept(&v, REQUEST, &pos);
> + break;
> + case CANCEL:
> + ret = accept(&v, START, &pos);
> + break;
> + case ACK:
> + ret = accept(&v, START, &pos);
> + break;
> + case REQUEST:
> + ret = accept(&v, CANCEL | REPLY, &pos);
> + break;
> + case REPLY:
> + ret = accept(&v, ACK, &pos);
> + break;
> + default:
> + ret = 0;
> + break;
> + }
> + } while (ret && v);
> +
> + if (ret)
> + cur = pos;
> + return ret;
> +}
> +
> +#define rebalance_try_request() \
> + rebalance(REQUEST)
> +#define rebalance_try_reply() \
> + rebalance(REPLY)
> +#define rebalance_try_cancel() \
> + rebalance(CANCEL)
> +#define rebalance_try_ack() \
> + rebalance(ACK | START)
> +
> asmlinkage int vprintk_emit(int facility, int level,
> const char *dict, size_t dictlen,
> const char *fmt, va_list args)
> @@ -1667,6 +1730,8 @@ asmlinkage int vprintk_emit(int facility, int level,
> bool in_sched = false;
> /* cpu currently holding logbuf_lock in this function */
> static unsigned int logbuf_cpu = UINT_MAX;
> + bool need_rebalance = 0;
> + bool can_rebalance = !(irqs_disabled() || in_interrupt());
>
> if (level == LOGLEVEL_SCHED) {
> level = LOGLEVEL_DEFAULT;
> @@ -1701,6 +1766,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>
> lockdep_off();
> raw_spin_lock(&logbuf_lock);
> + if (!in_sched && can_rebalance && rebalance_try_reply())
> + need_rebalance = true;
> logbuf_cpu = this_cpu;
>
> if (unlikely(recursion_bug)) {
> @@ -1811,6 +1878,9 @@ asmlinkage int vprintk_emit(int facility, int level,
> */
> preempt_disable();
>
> + if (need_rebalance)
> + while (down_trylock(&rebalance_sem))
> + cpu_relax();
> /*
> * Try to acquire and then immediately release the console
> * semaphore. The release will print out buffers and wake up
> @@ -2230,6 +2300,7 @@ void console_unlock(void)
> unsigned long flags;
> bool wake_klogd = false;
> bool retry;
> + bool need_rebalance = !!(irqs_disabled() || in_interrupt());
>
> if (console_suspended) {
> up_console_sem();
> @@ -2248,6 +2319,15 @@ again:
> int level;
>
> raw_spin_lock_irqsave(&logbuf_lock, flags);
> + if (need_rebalance) {
> + if (rebalance_try_ack())
> + break;
> + /*
> + * No need to check the ret value.
> + */
> + rebalance_try_cancel();
> + rebalance_try_request();
> + }
> if (seen_seq != log_next_seq) {
> wake_klogd = true;
> seen_seq = log_next_seq;
> @@ -2265,8 +2345,17 @@ again:
> len = 0;
> }
> skip:
> - if (console_seq == log_next_seq)
> + if (console_seq == log_next_seq) {
> + if (need_rebalance) {
> + rebalance_try_cancel();
> + /*
> + * break without rebalance, then no need to
> + * up rebalance_sem, set need_rebalance to NULL.
> + */
> + need_rebalance = 0;
> + }
> break;
> + }
>
> msg = log_from_idx(console_idx);
> if (msg->flags & LOG_NOCONS) {
> @@ -2318,6 +2407,14 @@ skip:
>
> up_console_sem();
>
> + if (need_rebalance) {
> + /*
> + * Need call up_console_sem first.
> + */
> + up(&rebalance_sem);
> + goto wake_up;
> + }
> +
> /*
> * Someone could have filled up the buffer again, so re-check if there's
> * something to flush. In case we cannot trylock the console_sem again,
> @@ -2331,6 +2428,7 @@ skip:
> if (retry && console_trylock())
> goto again;
>
> +wake_up:
> if (wake_klogd)
> wake_up_klogd();
> }
>
From: Pan Xinhui <[email protected]>
printk can be called in any context, It's very useful to output debug
info.
But it might cause very bad issues on some special cases. For example,
some driver hit errors, and it dumps many messages like reg values, etc.
Sometimes, printk is called when irqs disabled. This is OKay if there is
a few messages. But What would happen if many messages outputed by other
drivers at same time.
Here is the scenario.
CPUA CPUB
//driver dumps debug info local_irq_save(flags);
printk()
-> console_unlock()
printk() for(;;) {
-> log_store() //log_next_seq++
//many printk() below if (console_seq == log_next_seq)
break;
//did not break in this case
//no printk() now }
local_irq_restore(flags);
printk runs on CPUA just store the messages in the buf and return.
printk runs on CPUB(who owns the console_sem lock) would take the duty
to flush all messages to consoles. It would take a long time to flush
messages out, IOW, irq would be disabled for a long time. Such case is
too bad. We hit many interrupt related panics, for example, cpu did not
respond to IPI.
Here is the soultion, if we detect such case above, try to rebalance it.
Let CPUA take the duty to flush messages to consoles.
Introduce five states, START, REQUEST, REPLY, ACK, CANCEL.
Introduce five actions, request, reply, cancel, ack, start.
Only two kinds of state transition are allowed. They are
1) request reply ack start
-> START ------> REQUEST -----> REPLY -----> ACK ----->
| |
<------------------------------------------------------
2) request cancel start
-> START ------> REQUEST -----> CANCEL ----->
| |
<--------------------------------------------
To implement the five actions, introduce rebalance_try_request(),
rebalance_try_reply(), rebalance_try_cancel(), rebalance_try_ack(). As
action start is always after ack and cancel. rebalance_try_cancel/ack
would do start as well for simplicity.
State transition must be performed with logbuf_lock held.
When we have done the state transition, CPUB who owns the console_sem
will up rebalance_sem as well. CPUA who is going to take duty fo flush
messages will down_trylock rebalance_sem. The seqence to up/down two
sems must be like below, otherwise we might has risks that no one owns
console_sem to do flush job.
CPUA CPUB
down_trylock(&rebalance_sem) up(&console_sem)
up(&rebalance_sem);
down_trylock(&console_sem);
Signed-off-by: Pan Xinhui <[email protected]>
---
change from V2:
rebalance_try_cancel() should defined as rebalance(CANCEL | START)
change from V1:
rewrite the patch
---
kernel/printk/printk.c | 100 ++++++++++++++++++++++++++++++++++++++++++++++++-
1 file changed, 99 insertions(+), 1 deletion(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cf8c242..1ffbd32 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1652,6 +1652,69 @@ static size_t cont_print_text(char *text, size_t size)
return textlen;
}
+#define START 1
+#define CANCEL 2
+#define ACK 4
+#define REQUEST 8
+#define REPLY 16
+
+static struct semaphore rebalance_sem =
+ __SEMAPHORE_INITIALIZER(rebalance_sem, 0);
+
+static inline bool accept(int *v, int s, int *p)
+{
+ if (*v & s) {
+ *p = *v & s;
+ *v &= ~*p;
+ return true;
+ }
+ return 0;
+}
+
+/* protected by logbuf_lock*/
+static bool rebalance(int v)
+{
+ static int cur = START;
+ int pos = cur;
+ bool ret = 0;
+
+ do {
+ switch (pos) {
+ case START:
+ ret = accept(&v, REQUEST, &pos);
+ break;
+ case CANCEL:
+ ret = accept(&v, START, &pos);
+ break;
+ case ACK:
+ ret = accept(&v, START, &pos);
+ break;
+ case REQUEST:
+ ret = accept(&v, CANCEL | REPLY, &pos);
+ break;
+ case REPLY:
+ ret = accept(&v, ACK, &pos);
+ break;
+ default:
+ ret = 0;
+ break;
+ }
+ } while (ret && v);
+
+ if (ret)
+ cur = pos;
+ return ret;
+}
+
+#define rebalance_try_request() \
+ rebalance(REQUEST)
+#define rebalance_try_reply() \
+ rebalance(REPLY)
+#define rebalance_try_cancel() \
+ rebalance(CANCEL | START)
+#define rebalance_try_ack() \
+ rebalance(ACK | START)
+
asmlinkage int vprintk_emit(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, va_list args)
@@ -1667,6 +1730,8 @@ asmlinkage int vprintk_emit(int facility, int level,
bool in_sched = false;
/* cpu currently holding logbuf_lock in this function */
static unsigned int logbuf_cpu = UINT_MAX;
+ bool need_rebalance = 0;
+ bool can_rebalance = !(irqs_disabled() || in_interrupt());
if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
@@ -1701,6 +1766,8 @@ asmlinkage int vprintk_emit(int facility, int level,
lockdep_off();
raw_spin_lock(&logbuf_lock);
+ if (!in_sched && can_rebalance && rebalance_try_reply())
+ need_rebalance = true;
logbuf_cpu = this_cpu;
if (unlikely(recursion_bug)) {
@@ -1811,6 +1878,9 @@ asmlinkage int vprintk_emit(int facility, int level,
*/
preempt_disable();
+ if (need_rebalance)
+ while (down_trylock(&rebalance_sem))
+ cpu_relax();
/*
* Try to acquire and then immediately release the console
* semaphore. The release will print out buffers and wake up
@@ -2230,6 +2300,7 @@ void console_unlock(void)
unsigned long flags;
bool wake_klogd = false;
bool retry;
+ bool need_rebalance = !!(irqs_disabled() || in_interrupt());
if (console_suspended) {
up_console_sem();
@@ -2248,6 +2319,15 @@ again:
int level;
raw_spin_lock_irqsave(&logbuf_lock, flags);
+ if (need_rebalance) {
+ if (rebalance_try_ack())
+ break;
+ /*
+ * No need to check the ret value.
+ */
+ rebalance_try_cancel();
+ rebalance_try_request();
+ }
if (seen_seq != log_next_seq) {
wake_klogd = true;
seen_seq = log_next_seq;
@@ -2265,8 +2345,17 @@ again:
len = 0;
}
skip:
- if (console_seq == log_next_seq)
+ if (console_seq == log_next_seq) {
+ if (need_rebalance) {
+ rebalance_try_cancel();
+ /*
+ * break without rebalance, then no need to
+ * up rebalance_sem, set need_rebalance to NULL.
+ */
+ need_rebalance = 0;
+ }
break;
+ }
msg = log_from_idx(console_idx);
if (msg->flags & LOG_NOCONS) {
@@ -2318,6 +2407,14 @@ skip:
up_console_sem();
+ if (need_rebalance) {
+ /*
+ * Need call up_console_sem first.
+ */
+ up(&rebalance_sem);
+ goto wake_up;
+ }
+
/*
* Someone could have filled up the buffer again, so re-check if there's
* something to flush. In case we cannot trylock the console_sem again,
@@ -2331,6 +2428,7 @@ skip:
if (retry && console_trylock())
goto again;
+wake_up:
if (wake_klogd)
wake_up_klogd();
}
--
1.9.1