Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755788AbbHLJlh (ORCPT ); Wed, 12 Aug 2015 05:41:37 -0400 Received: from mga11.intel.com ([192.55.52.93]:35398 "EHLO mga11.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755767AbbHLJle (ORCPT ); Wed, 12 Aug 2015 05:41:34 -0400 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.15,660,1432623600"; d="scan'208";a="782572720" Message-ID: <55CB1433.5080501@intel.com> Date: Wed, 12 Aug 2015 17:38:59 +0800 From: Pan Xinhui User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101 Thunderbird/31.5.0 MIME-Version: 1.0 To: "linux-kernel@vger.kernel.org" CC: Andrew Morton , pmladek@suse.cz, gregkh@linuxfoundation.org, tj@kernel.org, joe@perches.com, peter@hurleysoftware.com, vvs@virtuozzo.com, viro@zeniv.linux.org.uk, rostedt@goodmis.org, "mnipxh@163.com" Subject: Re: [PATCH V2] printk: rebalance printk References: <55CB13BE.9090401@intel.com> In-Reply-To: <55CB13BE.9090401@intel.com> Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9007 Lines: 295 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 > > 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 > --- > 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@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/