[PATCH] 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 outputted by other
drivers at same time.

Here is the scenario.
CPUA					CPUB
					local_irq_save(flags);
					printk()
while(..) {					--> console_unlock
	printk(...);			
	//hundreds or thousands loops
}				//all messages flushed out to consoles
					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 solution, if we detect such case above, try to rebalance it.
Let CPUA take the duty to flush messages to consoles.

The idea is simple, but the implementation is a little difficult.
Introduce many help functions to fix it.

Signed-off-by: Pan Xinhui <xinhuix.pan@xxxxxxxxx>
---
 kernel/printk/printk.c | 101 ++++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 100 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cf8c242..3dc2f60 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1652,6 +1652,65 @@ static size_t cont_print_text(char *text, size_t size)
 	return textlen;
 }
 
+static struct {
+	unsigned int request:1;/* set it with logbuf_lock and console_sem held
+				* clear it with logbuf_lock held.
+				*/
+	unsigned int reply:1; /* set/clear it with logbuf_lock held*/
+	struct semaphore help_sem;
+} help_t = {
+	.request = 0,
+	.reply = 0,
+	.help_sem = __SEMAPHORE_INITIALIZER(help_t.help_sem, 0),
+};
+
+/* protected by logbuf_lock*/
+static int check_help(void)
+{
+	return !!help_t.request;
+}
+
+/* protected by logbuf_lock and console_sem*/
+static void request_help(void)
+{
+	help_t.request = 1;
+}
+
+/* protected by logbuf_lock*/
+static void cancel_help(void)
+{
+	help_t.request = 0;
+}
+
+/* protected by logbuf_lock*/
+static void reply_help(void)
+{
+	help_t.request = 0;
+	help_t.reply = 1;
+}
+
+/* protected by logbuf_lock*/
+static int ack_help(void)
+{
+	return !!help_t.reply;
+}
+
+/* protected by logbuf_lock*/
+static void close_help(void)
+{
+	help_t.reply = 0;
+}
+
+static void thanks_help(void)
+{
+	up(&help_t.help_sem);
+}
+
+static int done_help(void)
+{
+	return !down_trylock(&help_t.help_sem);
+}
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
@@ -1667,6 +1726,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 help = 0;
+	bool can_help = !(irqs_disabled() || in_sched || in_interrupt());
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1701,6 +1762,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	lockdep_off();
 	raw_spin_lock(&logbuf_lock);
+	if (can_help && check_help()) {
+		reply_help();
+		help = true;
+	}
 	logbuf_cpu = this_cpu;
 
 	if (unlikely(recursion_bug)) {
@@ -1811,6 +1876,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		preempt_disable();
 
+		if (help)
+			while (!done_help())
+				cpu_relax();
 		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
@@ -2230,6 +2298,8 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool retry;
+	bool help = !!(irqs_disabled() || in_interrupt());
+	bool skip_ack = true;
 
 	if (console_suspended) {
 		up_console_sem();
@@ -2248,6 +2318,21 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		if (help) {
+			if (!skip_ack) {
+				if (ack_help()) {
+					/*
+					* If request got replyed by another
+					* printk-on-going, close the request.
+					*/
+					close_help();
+					break;
+				}
+				cancel_help();
+			}
+			request_help();
+			skip_ack = 0;
+		}
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2265,8 +2350,13 @@ again:
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (console_seq == log_next_seq) {
+			if (help) {
+				cancel_help();
+				help = 0;
+			}
 			break;
+		}
 
 		msg = log_from_idx(console_idx);
 		if (msg->flags & LOG_NOCONS) {
@@ -2318,6 +2408,14 @@ skip:
 
 	up_console_sem();
 
+	if (help) {
+		/*
+		* Need call up_console_sem first.
+		*/
+		thanks_help();
+		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 +2429,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/