Re: [PATCH v5 0/2] printk: Console owner and waiter logic cleanup

[Steven Rostedt]

Tejun,

I was thinking about this a bit more, and instead of offloading a
recursive printk, perhaps its best to simply throttle it. Because the
problem may not go away if a printk thread takes over, because the bug
is really the printk infrastructure filling the printk buffer keeping
printk from ever stopping.

This patch detects that printk is causing itself to print more and
throttles it after 3 messages have printed due to recursion. Could you
see if this helps your test cases?

I built this on top of linux-next (yesterday's branch).

It compiles and boots, but I didn't do any other tests on it.

Thanks!

-- Steve

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9cb943c90d98..2c7f18876224 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1826,6 +1826,75 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	/* Store it in the record log */
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
+/*
+ * Used for which context the printk is in.
+ *  NMI     = 0
+ *  IRQ     = 1
+ *  SOFTIRQ = 2
+ *  NORMAL  = 3
+ *
+ * Stack ordered, where the lower number can preempt
+ * the higher number: mask &= mask - 1, will only clear
+ * the lowerest set bit.
+ */
+enum {
+	CTX_NMI,
+	CTX_IRQ,
+	CTX_SOFTIRQ,
+	CTX_NORMAL,
+};
+
+static DEFINE_PER_CPU(int, recursion_bits);
+static DEFINE_PER_CPU(int, recursion_count);
+static atomic_t recursion_overflow;
+static const int recursion_max = 3;
+
+static int __recursion_check_test(int val)
+{
+	unsigned long pc = preempt_count();
+	int bit;
+
+	if (!(pc & (NMI_MASK | HARDIRQ_MASK | SOFTIRQ_OFFSET)))
+		bit = CTX_NORMAL;
+	else
+		bit = pc & NMI_MASK ? CTX_NMI :
+			pc & HARDIRQ_MASK ? CTX_IRQ : CTX_SOFTIRQ;
+
+	return val & (1 << bit);
+}
+
+static bool recursion_check_test(void)
+{
+	int val = this_cpu_read(recursion_bits);
+
+	return __recursion_check_test(val);
+}
+
+static bool recursion_check_start(void)
+{
+	int val = this_cpu_read(recursion_bits);
+	int set;
+
+	set = __recursion_check_test(val);
+
+	if (unlikely(set))
+		return true;
+
+	val |= set;
+	this_cpu_write(recursion_bits, val);
+	return false;
+}
+
+static void recursion_check_finish(bool recursion)
+{
+	int val = this_cpu_read(recursion_bits);
+
+	if (recursion)
+		return;
+
+	val &= val - 1;
+	this_cpu_write(recursion_bits, val);
+}
 
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
@@ -1849,6 +1918,17 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	/* This stops the holder of console_sem just where we want him */
 	logbuf_lock_irqsave(flags);
+
+	if (recursion_check_test()) {
+		/* A printk happened within a printk at the same context */
+		if (this_cpu_inc_return(recursion_count) > recursion_max) {
+			atomic_inc(&recursion_overflow);
+			logbuf_unlock_irqrestore(flags);
+			printed_len = 0;
+			goto out;
+		}
+	}
+
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
@@ -1895,12 +1975,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
+		bool recursion;
 		/*
 		 * Disable preemption to avoid being preempted while holding
 		 * console_sem which would prevent anyone from printing to
 		 * console
 		 */
 		preempt_disable();
+		recursion = recursion_check_start();
 		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
@@ -1908,9 +1990,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (console_trylock_spinning())
 			console_unlock();
+
+		recursion_check_finish(recursion);
+		this_cpu_write(recursion_count, 0);
 		preempt_enable();
 	}
-
+out:
 	return printed_len;
 }
 EXPORT_SYMBOL(vprintk_emit);
@@ -2343,9 +2428,14 @@ void console_unlock(void)
 			seen_seq = log_next_seq;
 		}
 
-		if (console_seq < log_first_seq) {
+		if (console_seq < log_first_seq || atomic_read(&recursion_overflow)) {
+			size_t missed;
+
+			missed = atomic_xchg(&recursion_overflow, 0);
+			missed += log_first_seq - console_seq;
+
 			len = sprintf(text, "** %u printk messages dropped **\n",
-				      (unsigned)(log_first_seq - console_seq));
+				      (unsigned)missed);
 
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;