Re: [PATCH V2] printk: rebalance printk
From: Pan Xinhui
Date: Wed Aug 12 2015 - 05:41:41 EST
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 <xinhuix.pan@xxxxxxxxx>
>
> 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 <xinhuix.pan@xxxxxxxxx>
> ---
> 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();
> }
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/