[PATCH V2] printk: rebalance printk

[Pan Xinhui]

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();
 }
-- 
1.9.1
--
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/