Re: [debug patch] printk: Add a printk killswitch to robustify NMI watchdog messages

[Peter Zijlstra <peterz@infradead.org>]

On Mon, 2011-06-06 at 18:17 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > On Mon, 2011-06-06 at 18:08 +0200, Ingo Molnar wrote:
> > > * Peter Zijlstra <peterz@infradead.org> wrote:
> > > 
> > > > On Mon, 2011-06-06 at 17:52 +0200, Ingo Molnar wrote:
> > > > > * Peter Zijlstra <peterz@infradead.org> wrote:
> > > > > 
> > > > > > Needs more staring at, preferably by someone who actually 
> > > > > > understands that horrid mess :/ Also, this all still doesn't make 
> > > > > > printk() work reliably while holding rq->lock.
> > > > > 
> > > > > So, what about my suggestion to just *remove* the wakeup from there 
> > > > > and use the deferred wakeup mechanism that klogd uses.
> > > > > 
> > > > > That would make printk() *visibly* more robust in practice.
> > > > 
> > > > That's currently done from the jiffy tick, do you want to effectively
> > > > delay releasing the console_sem for the better part of a jiffy?
> > > 
> > > Yes, and we already do it in some other circumstances. 
> > 
> > We do?
> 
> Yes, see the whole printk_pending logic, it delays:
> 
>                 wake_up_interruptible(&log_wait);
> 
> to the next jiffies tick.

Again, that's not console_sem ("..delay releasing console_sem.."
"..already done.." isn't true).

> > > Can you see 
> > > any problem with that? klogd is an utter slowpath anyway.
> > 
> > but console_sem isn't klogd. We delay klogd and that's perfectly 
> > fine, but afaict we don't delay console_sem.
> 
> But console_sem is really a similar special case as klogd. See, it's 
> about a *printk*. That's rare by definition.

But its not rare, its _the_ lock that serialized the whole console
layer. Pretty much everything a console does goes through that lock.

By delaying this with 10ms (CONFIG_HZ=100) per printk could really delay
the whole boot process.

> If someone on the console sees it he'll be startled by at least 10 
> msecs ;-) So delaying the wakeup to the next jiffy really fits into 
> the same approach as we already do with &log_wait, hm?

Not convinced yet, I mean, don't get me wrong, I'd love to rid us of the
thing, but I'm not sure delaying the release of a resource like this is
the right approach.

Ahh, what we could do is something like the below and delay both the
acquire and release of the console_sem.

---
 kernel/printk.c |   86 +++++++++++++++++++++++++-----------------------------
 1 files changed, 40 insertions(+), 46 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 3518539..d3bdf5a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -686,6 +686,7 @@ static void zap_locks(void)
 
 	oops_timestamp = jiffies;
 
+	debug_locks_off();
 	/* If a crash is occurring, make sure we can't deadlock */
 	spin_lock_init(&logbuf_lock);
 	/* And make sure that we print immediately */
@@ -774,16 +775,13 @@ static inline int can_use_console(unsigned int cpu)
  * messages from a 'printk'. Return true (and with the
  * console_lock held, and 'console_locked' set) if it
  * is successful, false otherwise.
- *
- * This gets called with the 'logbuf_lock' spinlock held and
- * interrupts disabled. It should return with 'lockbuf_lock'
- * released but interrupts still disabled.
  */
 static int console_trylock_for_printk(unsigned int cpu)
 	__releases(&logbuf_lock)
 {
 	int retval = 0;
 
+	spin_lock(&logbuf_lock);
 	if (console_trylock()) {
 		retval = 1;
 
@@ -803,12 +801,27 @@ static int console_trylock_for_printk(unsigned int cpu)
 	spin_unlock(&logbuf_lock);
 	return retval;
 }
+
 static const char recursion_bug_msg [] =
 		KERN_CRIT "BUG: recent printk recursion!\n";
 static int recursion_bug;
 static int new_text_line = 1;
 static char printk_buf[1024];
 
+static DEFINE_PER_CPU(int, printk_pending);
+
+int printk_needs_cpu(int cpu)
+{
+	if (cpu_is_offline(cpu))
+		printk_tick();
+	return __this_cpu_read(printk_pending);
+}
+
+void printk_set_pending(void)
+{
+	this_cpu_write(printk_pending, 1);
+}
+
 int printk_delay_msec __read_mostly;
 
 static inline void printk_delay(void)
@@ -836,9 +849,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	boot_delay_msec();
 	printk_delay();
 
-	preempt_disable();
 	/* This stops the holder of console_sem just where we want him */
-	raw_local_irq_save(flags);
+	local_irq_save(flags);
 	this_cpu = smp_processor_id();
 
 	/*
@@ -859,7 +871,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 		zap_locks();
 	}
 
-	lockdep_off();
 	spin_lock(&logbuf_lock);
 	printk_cpu = this_cpu;
 
@@ -942,25 +953,13 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 		if (*p == '\n')
 			new_text_line = 1;
 	}
+	spin_unlock(&logbuf_lock);
 
-	/*
-	 * Try to acquire and then immediately release the
-	 * console semaphore. The release will do all the
-	 * actual magic (print out buffers, wake up klogd,
-	 * etc). 
-	 *
-	 * The console_trylock_for_printk() function
-	 * will release 'logbuf_lock' regardless of whether it
-	 * actually gets the semaphore or not.
-	 */
-	if (console_trylock_for_printk(this_cpu))
-		console_unlock();
+	printk_set_pending();
 
-	lockdep_on();
 out_restore_irqs:
-	raw_local_irq_restore(flags);
+	local_irq_restore(flags);
 
-	preempt_enable();
 	return printed_len;
 }
 EXPORT_SYMBOL(printk);
@@ -1201,29 +1200,6 @@ int is_console_locked(void)
 	return console_locked;
 }
 
-static DEFINE_PER_CPU(int, printk_pending);
-
-void printk_tick(void)
-{
-	if (__this_cpu_read(printk_pending)) {
-		__this_cpu_write(printk_pending, 0);
-		wake_up_interruptible(&log_wait);
-	}
-}
-
-int printk_needs_cpu(int cpu)
-{
-	if (cpu_is_offline(cpu))
-		printk_tick();
-	return __this_cpu_read(printk_pending);
-}
-
-void wake_up_klogd(void)
-{
-	if (waitqueue_active(&log_wait))
-		this_cpu_write(printk_pending, 1);
-}
-
 /**
  * console_unlock - unlock the console system
  *
@@ -1273,11 +1249,29 @@ void console_unlock(void)
 
 	up(&console_sem);
 	spin_unlock_irqrestore(&logbuf_lock, flags);
+
 	if (wake_klogd)
-		wake_up_klogd();
+		wake_up_interruptible(&log_wait);
 }
 EXPORT_SYMBOL(console_unlock);
 
+void printk_tick(void)
+{
+	if (!__this_cpu_read(printk_pending))
+		return;
+
+	/*
+	 * Try to acquire and then immediately release the
+	 * console semaphore. The release will do all the
+	 * actual magic (print out buffers, wake up klogd,
+	 * etc). 
+	 */
+	if (console_trylock_for_printk(smp_processor_id())) {
+		console_unlock();
+		__this_cpu_write(printk_pending, 0);
+	}
+}
+
 /**
  * console_conditional_schedule - yield the CPU if required
  *