[PATCH 0/3] printk: Remove lockdep_off() and wakeups

[PATCH 0/3] printk: Remove lockdep_off() and wakeups

[Peter Zijlstra]

These three patches rework printk() to remove the lockdep_off() hackery and
remove the need for printk() to do wakeups, which should make it much more
reliable in various contexts.

The first patch is already in -tip, the others are not. Ingo reported some
problems with #2, but I've been unable to reproduce so far.

The third patch has the semaphore trickery in and keeps it private to printk.c
as per Thomas' request.

A kernel with all three applied and lockdep enabled seems to have no problem
booting.

[PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

[-- Attachment #1: printk-up-after-unlock.patch --]
[-- Type: text/plain, Size: 1545 bytes --]

Release console_sem after unlocking the logbuf_lock so that we don't
generate wakeups while holding logbuf_lock. This avoids some lock
inversion troubles once we remove the lockdep_off bits between
logbuf_lock and rq->lock (prints while holding rq->lock vs doing
wakeups while holding logbuf_lock).

There's of course still an actual deadlock where the printk()s under
rq->lock will issue a wakeup from the up() call.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |    8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -782,7 +782,7 @@ static inline int can_use_console(unsign
 static int console_trylock_for_printk(unsigned int cpu)
 	__releases(&logbuf_lock)
 {
-	int retval = 0;
+	int retval = 0, wake = 0;
 
 	if (console_trylock()) {
 		retval = 1;
@@ -795,12 +795,14 @@ static int console_trylock_for_printk(un
 		 */
 		if (!can_use_console(cpu)) {
 			console_locked = 0;
-			up(&console_sem);
+			wake = 1;
 			retval = 0;
 		}
 	}
 	printk_cpu = UINT_MAX;
 	spin_unlock(&logbuf_lock);
+	if (wake)
+		up(&console_sem);
 	return retval;
 }
 static const char recursion_bug_msg [] =
@@ -1271,8 +1273,8 @@ void console_unlock(void)
 	if (unlikely(exclusive_console))
 		exclusive_console = NULL;
 
-	up(&console_sem);
 	spin_unlock_irqrestore(&logbuf_lock, flags);
+	up(&console_sem);
 	if (wake_klogd)
 		wake_up_klogd();
 }

[PATCH 2/3] printk, lockdep: Remove lockdep_off() usage

[Peter Zijlstra]

[-- Attachment #1: printk-remove-lockdep_off.patch --]
[-- Type: text/plain, Size: 1661 bytes --]

Remove the lockdep_off() usage from printk(). Also add a
debug_locks_off() call to zap_locks() since that'll mess up the lock
state in a royal way anyway. Further switch to local_irq_ ops so that
the irq state is properly tracked (raw_local_irq_* isn't tracked by
lockdep, causing confusion). Also drop superfluous preempt_disable(),
disabling IRQs already avoids scheduling.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |    9 +++------
 1 file changed, 3 insertions(+), 6 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/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 */
@@ -838,9 +839,8 @@ asmlinkage int vprintk(const char *fmt,
 	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();
 
 	/*
@@ -861,7 +861,6 @@ asmlinkage int vprintk(const char *fmt,
 		zap_locks();
 	}
 
-	lockdep_off();
 	spin_lock(&logbuf_lock);
 	printk_cpu = this_cpu;
 
@@ -958,11 +957,9 @@ asmlinkage int vprintk(const char *fmt,
 	if (console_trylock_for_printk(this_cpu))
 		console_unlock();
 
-	lockdep_on();
 out_restore_irqs:
-	raw_local_irq_restore(flags);
+	local_irq_restore(flags);
 
-	preempt_enable();
 	return printed_len;
 }
 EXPORT_SYMBOL(printk);

[PATCH 3/3] printk: Avoid all wakeups from printk

[Peter Zijlstra]

[-- Attachment #1: printk-funky-locking.patch --]
[-- Type: text/plain, Size: 6228 bytes --]

Since printk() has to acquire the console_sem in order to write its
data out to the console we have an up() in printk(). Even though
contention on the console_sem is rare under normal circumstances, when
it happens printk() will issue a wakeup. If printk us used from a
context that already owns the scheduler locks or locks that have a
reverse ordering with the scheduler locks this gives potential for
deadlocks.

Avoid the wakeup by creating special semaphore operations that keep
the semaphore internal spinlock held, this ensures console_sem
contention will spin on this lock and not get queued on the wait_list.

For now keep these special semaphore operations private to printk,
if there ever appears another valid user we can move them over to
semaphore.c (along with extending the interface to provide
{_irq,_irqsave} versions, as the current ones assume IRQs are disabled
(as per the use-case in printk).

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |  140 +++++++++++++++++++++++++++-----------------------------
 1 file changed, 69 insertions(+), 71 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -765,47 +765,11 @@ static volatile unsigned int printk_cpu 
  * being able to cope (CON_ANYTIME) don't call them until
  * this CPU is officially up.
  */
-static inline int can_use_console(unsigned int cpu)
+static inline int can_use_console(void)
 {
-	return cpu_online(cpu) || have_callable_console();
+	return cpu_online(smp_processor_id()) || have_callable_console();
 }
 
-/*
- * Try to get console ownership to actually show the kernel
- * 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, wake = 0;
-
-	if (console_trylock()) {
-		retval = 1;
-
-		/*
-		 * If we can't use the console, we need to release
-		 * the console semaphore by hand to avoid flushing
-		 * the buffer. We need to hold the console semaphore
-		 * in order to do this test safely.
-		 */
-		if (!can_use_console(cpu)) {
-			console_locked = 0;
-			wake = 1;
-			retval = 0;
-		}
-	}
-	printk_cpu = UINT_MAX;
-	spin_unlock(&logbuf_lock);
-	if (wake)
-		up(&console_sem);
-	return retval;
-}
 static const char recursion_bug_msg [] =
 		KERN_CRIT "BUG: recent printk recursion!\n";
 static int recursion_bug;
@@ -826,6 +790,38 @@ static inline void printk_delay(void)
 	}
 }
 
+static void __console_flush(void);
+
+/*
+ * Special 'atomic' semaphore operations that mimmick down_trylock() + up(),
+ * except they don't release the semaphore internal lock and optimize the
+ * sem->count fiddling away.
+ *
+ * The advantage is that this construct doesn't generate wakeups on atomic_up()
+ * since any contending semaphore acuiqisition will still be spinning on the
+ * internal lock, instead of having gotten queued on the wait_list.
+ *
+ * printk() uses this to avoid generating wakeups, which would make it unsafe
+ * to use in certain contexts (avoids lock inversion or lock recursion with
+ * the scheduler locks).
+ *
+ * Assumes IRQs are disabled.
+ */
+static int atomic_down_trylock(struct semaphore *sem)
+{
+	spin_lock(&sem->lock);
+	if (sem->count > 0)
+		return 0;
+
+	spin_unlock(&sem->lock);
+	return 1;
+}
+
+static void atomic_up(struct semaphore *sem)
+{
+	spin_unlock(&sem->lock);
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -943,19 +939,14 @@ asmlinkage int vprintk(const char *fmt, 
 		if (*p == '\n')
 			new_text_line = 1;
 	}
+	printk_cpu = UINT_MAX;
+	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();
+	if (!atomic_down_trylock(&console_sem)) {
+		if (can_use_console())
+			__console_flush();
+		atomic_up(&console_sem);
+	}
 
 out_restore_irqs:
 	local_irq_restore(flags);
@@ -1223,31 +1214,12 @@ void wake_up_klogd(void)
 		this_cpu_write(printk_pending, 1);
 }
 
-/**
- * console_unlock - unlock the console system
- *
- * Releases the console_lock which the caller holds on the console system
- * and the console driver list.
- *
- * While the console_lock was held, console output may have been buffered
- * by printk().  If this is the case, console_unlock(); emits
- * the output prior to releasing the lock.
- *
- * If there is output waiting for klogd, we wake it up.
- *
- * console_unlock(); may be called from any context.
- */
-void console_unlock(void)
+static void __console_flush(void)
 {
 	unsigned long flags;
 	unsigned _con_start, _log_end;
 	unsigned wake_klogd = 0;
 
-	if (console_suspended) {
-		up(&console_sem);
-		return;
-	}
-
 	console_may_schedule = 0;
 
 	for ( ; ; ) {
@@ -1271,10 +1243,36 @@ void console_unlock(void)
 		exclusive_console = NULL;
 
 	spin_unlock_irqrestore(&logbuf_lock, flags);
-	up(&console_sem);
+
 	if (wake_klogd)
 		wake_up_klogd();
 }
+
+/**
+ * console_unlock - unlock the console system
+ *
+ * Releases the console_lock which the caller holds on the console system
+ * and the console driver list.
+ *
+ * While the console_lock was held, console output may have been buffered
+ * by printk().  If this is the case, console_unlock(); emits
+ * the output prior to releasing the lock.
+ *
+ * If there is output waiting for klogd, we wake it up.
+ *
+ * console_unlock(); may be called from any context.
+ */
+void console_unlock(void)
+{
+	if (console_suspended) {
+		up(&console_sem);
+		return;
+	}
+
+	__console_flush();
+
+	up(&console_sem);
+}
 EXPORT_SYMBOL(console_unlock);
 
 /**

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> +void console_unlock(void)
> +{
> +	if (console_suspended) {
> +		up(&console_sem);
> +		return;
> +	}
> +
> +	__console_flush();
> +
> +	up(&console_sem);
> +}

Hm, this seems to be a very roundabout way of doing:

void console_unlock(void)
{
	if (!console_suspended)
		__console_flush();

	up(&console_sem);
}

Right?

Thanks,

	Ingo

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Peter Zijlstra]

On Thu, 2011-06-09 at 15:32 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> 
> > +void console_unlock(void)
> > +{
> > +	if (console_suspended) {
> > +		up(&console_sem);
> > +		return;
> > +	}
> > +
> > +	__console_flush();
> > +
> > +	up(&console_sem);
> > +}
> 
> Hm, this seems to be a very roundabout way of doing:
> 
> void console_unlock(void)
> {
> 	if (!console_suspended)
> 		__console_flush();
> 
> 	up(&console_sem);
> }
> 
> Right?

Uhm, yeah. 

---
Subject: printk: Avoid all wakeups from printk
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Wed Jun 08 17:29:59 CEST 2011

Since printk() has to acquire the console_sem in order to write its
data out to the console we have an up() in printk(). Even though
contention on the console_sem is rare under normal circumstances, when
it happens printk() will issue a wakeup. If printk us used from a
context that already owns the scheduler locks or locks that have a
reverse ordering with the scheduler locks this gives potential for
deadlocks.

Avoid the wakeup by creating special semaphore operations that keep
the semaphore internal spinlock held, this ensures console_sem
contention will spin on this lock and not get queued on the wait_list.

For now keep these special semaphore operations private to printk,
if there ever appears another valid user we can move them over to
semaphore.c (along with extending the interface to provide
{_irq,_irqsave} versions, as the current ones assume IRQs are disabled
(as per the use-case in printk).

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |  136 ++++++++++++++++++++++++++------------------------------
 1 file changed, 65 insertions(+), 71 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -765,47 +765,11 @@ static volatile unsigned int printk_cpu 
  * being able to cope (CON_ANYTIME) don't call them until
  * this CPU is officially up.
  */
-static inline int can_use_console(unsigned int cpu)
+static inline int can_use_console(void)
 {
-	return cpu_online(cpu) || have_callable_console();
+	return cpu_online(smp_processor_id()) || have_callable_console();
 }
 
-/*
- * Try to get console ownership to actually show the kernel
- * 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, wake = 0;
-
-	if (console_trylock()) {
-		retval = 1;
-
-		/*
-		 * If we can't use the console, we need to release
-		 * the console semaphore by hand to avoid flushing
-		 * the buffer. We need to hold the console semaphore
-		 * in order to do this test safely.
-		 */
-		if (!can_use_console(cpu)) {
-			console_locked = 0;
-			wake = 1;
-			retval = 0;
-		}
-	}
-	printk_cpu = UINT_MAX;
-	spin_unlock(&logbuf_lock);
-	if (wake)
-		up(&console_sem);
-	return retval;
-}
 static const char recursion_bug_msg [] =
 		KERN_CRIT "BUG: recent printk recursion!\n";
 static int recursion_bug;
@@ -826,6 +790,38 @@ static inline void printk_delay(void)
 	}
 }
 
+static void __console_flush(void);
+
+/*
+ * Special 'atomic' semaphore operations that mimmick down_trylock() + up(),
+ * except they don't release the semaphore internal lock and optimize the
+ * sem->count fiddling away.
+ *
+ * The advantage is that this construct doesn't generate wakeups on atomic_up()
+ * since any contending semaphore acuiqisition will still be spinning on the
+ * internal lock, instead of having gotten queued on the wait_list.
+ *
+ * printk() uses this to avoid generating wakeups, which would make it unsafe
+ * to use in certain contexts (avoids lock inversion or lock recursion with
+ * the scheduler locks).
+ *
+ * Assumes IRQs are disabled.
+ */
+static int atomic_down_trylock(struct semaphore *sem)
+{
+	spin_lock(&sem->lock);
+	if (sem->count > 0)
+		return 0;
+
+	spin_unlock(&sem->lock);
+	return 1;
+}
+
+static void atomic_up(struct semaphore *sem)
+{
+	spin_unlock(&sem->lock);
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -943,19 +939,14 @@ asmlinkage int vprintk(const char *fmt, 
 		if (*p == '\n')
 			new_text_line = 1;
 	}
+	printk_cpu = UINT_MAX;
+	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();
+	if (!atomic_down_trylock(&console_sem)) {
+		if (can_use_console())
+			__console_flush();
+		atomic_up(&console_sem);
+	}
 
 out_restore_irqs:
 	local_irq_restore(flags);
@@ -1223,31 +1214,12 @@ void wake_up_klogd(void)
 		this_cpu_write(printk_pending, 1);
 }
 
-/**
- * console_unlock - unlock the console system
- *
- * Releases the console_lock which the caller holds on the console system
- * and the console driver list.
- *
- * While the console_lock was held, console output may have been buffered
- * by printk().  If this is the case, console_unlock(); emits
- * the output prior to releasing the lock.
- *
- * If there is output waiting for klogd, we wake it up.
- *
- * console_unlock(); may be called from any context.
- */
-void console_unlock(void)
+static void __console_flush(void)
 {
 	unsigned long flags;
 	unsigned _con_start, _log_end;
 	unsigned wake_klogd = 0;
 
-	if (console_suspended) {
-		up(&console_sem);
-		return;
-	}
-
 	console_may_schedule = 0;
 
 	for ( ; ; ) {
@@ -1271,10 +1243,32 @@ void console_unlock(void)
 		exclusive_console = NULL;
 
 	spin_unlock_irqrestore(&logbuf_lock, flags);
-	up(&console_sem);
+
 	if (wake_klogd)
 		wake_up_klogd();
 }
+
+/**
+ * console_unlock - unlock the console system
+ *
+ * Releases the console_lock which the caller holds on the console system
+ * and the console driver list.
+ *
+ * While the console_lock was held, console output may have been buffered
+ * by printk().  If this is the case, console_unlock(); emits
+ * the output prior to releasing the lock.
+ *
+ * If there is output waiting for klogd, we wake it up.
+ *
+ * console_unlock(); may be called from any context.
+ */
+void console_unlock(void)
+{
+	if (!console_suspended)
+		__console_flush();
+
+	up(&console_sem);
+}
 EXPORT_SYMBOL(console_unlock);
 
 /**

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> +static void __console_flush(void);

I'd suggest moving this function to the right place, so that no 
prototypes are necessary.

> +/*
> + * Special 'atomic' semaphore operations that mimmick down_trylock() + up(),

mimic

> + * except they don't release the semaphore internal lock and optimize the
> + * sem->count fiddling away.
> + *
> + * The advantage is that this construct doesn't generate wakeups on atomic_up()
> + * since any contending semaphore acuiqisition will still be spinning on the

acquisition.

> + * internal lock, instead of having gotten queued on the wait_list.
> + *
> + * printk() uses this to avoid generating wakeups, which would make it unsafe
> + * to use in certain contexts (avoids lock inversion or lock recursion with
> + * the scheduler locks).
> + *
> + * Assumes IRQs are disabled.

I'd add:

    * Note: We emphatically do *not* want this function exported. Ever.

and maybe:

    * Note2: Even asking for that will likely buy you a nasty response.

> + */
> +static int atomic_down_trylock(struct semaphore *sem)
> +{
> +	spin_lock(&sem->lock);
> +	if (sem->count > 0)
> +		return 0;
> +
> +	spin_unlock(&sem->lock);
> +	return 1;
> +}
> +
> +static void atomic_up(struct semaphore *sem)
> +{
> +	spin_unlock(&sem->lock);
> +}
> +
>  asmlinkage int vprintk(const char *fmt, va_list args)
>  {
>  	int printed_len = 0;
> @@ -943,19 +939,14 @@ asmlinkage int vprintk(const char *fmt, 
>  		if (*p == '\n')
>  			new_text_line = 1;
>  	}
> +	printk_cpu = UINT_MAX;
> +	spin_unlock(&logbuf_lock);

Hm, is that printk_cpu setting inside the critical section safe? What 
happens if we get an NMI on this CPU in that window?

Thanks,

	Ingo

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Peter Zijlstra]

On Thu, 2011-06-09 at 15:55 +0200, Ingo Molnar wrote:

> > @@ -943,19 +939,14 @@ asmlinkage int vprintk(const char *fmt, 
> >  		if (*p == '\n')
> >  			new_text_line = 1;
> >  	}
> > +	printk_cpu = UINT_MAX;
> > +	spin_unlock(&logbuf_lock);
> 
> Hm, is that printk_cpu setting inside the critical section safe? What 
> happens if we get an NMI on this CPU in that window?

That's what the old code did, also NMI really shouldn't printk(), but
yeah, can flip those two lines, but in that same vein I should also flip
the setting of that variable with acquiring the lock.

Lots of churn due to moving __console_flush around.

---
Subject: printk: Avoid all wakeups from printk
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Wed Jun 08 17:29:59 CEST 2011

Since printk() has to acquire the console_sem in order to write its
data out to the console we have an up() in printk(). Even though
contention on the console_sem is rare under normal circumstances, when
it happens printk() will issue a wakeup. If printk us used from a
context that already owns the scheduler locks or locks that have a
reverse ordering with the scheduler locks this gives potential for
deadlocks.

Avoid the wakeup by creating special semaphore operations that keep
the semaphore internal spinlock held, this ensures console_sem
contention will spin on this lock and not get queued on the wait_list.

For now keep these special semaphore operations private to printk,
if there ever appears another valid user we can move them over to
semaphore.c (along with extending the interface to provide
{_irq,_irqsave} versions, as the current ones assume IRQs are disabled
(as per the use-case in printk).

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |  210 +++++++++++++++++++++++++++-----------------------------
 1 file changed, 103 insertions(+), 107 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -765,47 +765,11 @@ static volatile unsigned int printk_cpu 
  * being able to cope (CON_ANYTIME) don't call them until
  * this CPU is officially up.
  */
-static inline int can_use_console(unsigned int cpu)
+static inline int can_use_console(void)
 {
-	return cpu_online(cpu) || have_callable_console();
+	return cpu_online(smp_processor_id()) || have_callable_console();
 }
 
-/*
- * Try to get console ownership to actually show the kernel
- * 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, wake = 0;
-
-	if (console_trylock()) {
-		retval = 1;
-
-		/*
-		 * If we can't use the console, we need to release
-		 * the console semaphore by hand to avoid flushing
-		 * the buffer. We need to hold the console semaphore
-		 * in order to do this test safely.
-		 */
-		if (!can_use_console(cpu)) {
-			console_locked = 0;
-			wake = 1;
-			retval = 0;
-		}
-	}
-	printk_cpu = UINT_MAX;
-	spin_unlock(&logbuf_lock);
-	if (wake)
-		up(&console_sem);
-	return retval;
-}
 static const char recursion_bug_msg [] =
 		KERN_CRIT "BUG: recent printk recursion!\n";
 static int recursion_bug;
@@ -826,6 +790,97 @@ static inline void printk_delay(void)
 	}
 }
 
+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);
+}
+
+static void __console_flush(void)
+{
+	unsigned long flags;
+	unsigned _con_start, _log_end;
+	unsigned wake_klogd = 0;
+
+	console_may_schedule = 0;
+
+	for ( ; ; ) {
+		spin_lock_irqsave(&logbuf_lock, flags);
+		wake_klogd |= log_start - log_end;
+		if (con_start == log_end)
+			break;			/* Nothing to print */
+		_con_start = con_start;
+		_log_end = log_end;
+		con_start = log_end;		/* Flush */
+		spin_unlock(&logbuf_lock);
+		stop_critical_timings();	/* don't trace print latency */
+		call_console_drivers(_con_start, _log_end);
+		start_critical_timings();
+		local_irq_restore(flags);
+	}
+	console_locked = 0;
+
+	/* Release the exclusive_console once it is used */
+	if (unlikely(exclusive_console))
+		exclusive_console = NULL;
+
+	spin_unlock_irqrestore(&logbuf_lock, flags);
+
+	if (wake_klogd)
+		wake_up_klogd();
+}
+
+
+/*
+ * Special 'atomic' semaphore operations that mimic down_trylock() + up(),
+ * except they don't release the semaphore internal lock and optimize the
+ * sem->count fiddling away.
+ *
+ * The advantage is that this construct doesn't generate wakeups on atomic_up()
+ * since any contending semaphore acquisition will still be spinning on the
+ * internal lock, instead of having gotten queued on the wait_list.
+ *
+ * printk() uses this to avoid generating wakeups, which would make it unsafe
+ * to use in certain contexts (avoids lock inversion or lock recursion with
+ * the scheduler locks).
+ *
+ * Assumes IRQs are disabled.
+ *
+ * Note:  We emphatically do *not* want this function exported. Ever.
+ * Note2: Even asking for that will likely buy you a nasty response.
+ */
+static int atomic_down_trylock(struct semaphore *sem)
+{
+	spin_lock(&sem->lock);
+	if (sem->count > 0)
+		return 0;
+
+	spin_unlock(&sem->lock);
+	return 1;
+}
+
+static void atomic_up(struct semaphore *sem)
+{
+	spin_unlock(&sem->lock);
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -861,8 +916,8 @@ asmlinkage int vprintk(const char *fmt, 
 		zap_locks();
 	}
 
-	spin_lock(&logbuf_lock);
 	printk_cpu = this_cpu;
+	spin_lock(&logbuf_lock);
 
 	if (recursion_bug) {
 		recursion_bug = 0;
@@ -943,19 +998,14 @@ asmlinkage int vprintk(const char *fmt, 
 		if (*p == '\n')
 			new_text_line = 1;
 	}
+	spin_unlock(&logbuf_lock);
+	printk_cpu = UINT_MAX;
 
-	/*
-	 * 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();
+	if (!atomic_down_trylock(&console_sem)) {
+		if (can_use_console())
+			__console_flush();
+		atomic_up(&console_sem);
+	}
 
 out_restore_irqs:
 	local_irq_restore(flags);
@@ -1200,29 +1250,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
  *
@@ -1239,41 +1266,10 @@ void wake_up_klogd(void)
  */
 void console_unlock(void)
 {
-	unsigned long flags;
-	unsigned _con_start, _log_end;
-	unsigned wake_klogd = 0;
+	if (!console_suspended)
+		__console_flush();
 
-	if (console_suspended) {
-		up(&console_sem);
-		return;
-	}
-
-	console_may_schedule = 0;
-
-	for ( ; ; ) {
-		spin_lock_irqsave(&logbuf_lock, flags);
-		wake_klogd |= log_start - log_end;
-		if (con_start == log_end)
-			break;			/* Nothing to print */
-		_con_start = con_start;
-		_log_end = log_end;
-		con_start = log_end;		/* Flush */
-		spin_unlock(&logbuf_lock);
-		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(_con_start, _log_end);
-		start_critical_timings();
-		local_irq_restore(flags);
-	}
-	console_locked = 0;
-
-	/* Release the exclusive_console once it is used */
-	if (unlikely(exclusive_console))
-		exclusive_console = NULL;
-
-	spin_unlock_irqrestore(&logbuf_lock, flags);
 	up(&console_sem);
-	if (wake_klogd)
-		wake_up_klogd();
 }
 EXPORT_SYMBOL(console_unlock);
 

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> On Thu, 2011-06-09 at 15:55 +0200, Ingo Molnar wrote:
> 
> > > @@ -943,19 +939,14 @@ asmlinkage int vprintk(const char *fmt, 
> > >  		if (*p == '\n')
> > >  			new_text_line = 1;
> > >  	}
> > > +	printk_cpu = UINT_MAX;
> > > +	spin_unlock(&logbuf_lock);
> > 
> > Hm, is that printk_cpu setting inside the critical section safe? What 
> > happens if we get an NMI on this CPU in that window?
> 
> That's what the old code did, also NMI really shouldn't printk(), but
> yeah, can flip those two lines, but in that same vein I should also flip
> the setting of that variable with acquiring the lock.

Flipping it won't be enough - we could override another CPU's 
protection ...

Thanks,

	Ingo

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Peter Zijlstra]

On Thu, 2011-06-09 at 16:19 +0200, Ingo Molnar wrote:

> Flipping it won't be enough - we could override another CPU's 
> protection ...

Gah,. well then don't printk() from NMIs ;-) There's way more problems
than just this one variable when you do that.


---
Subject: printk: Avoid all wakeups from printk
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Wed Jun 08 17:29:59 CEST 2011

Since printk() has to acquire the console_sem in order to write its
data out to the console we have an up() in printk(). Even though
contention on the console_sem is rare under normal circumstances, when
it happens printk() will issue a wakeup. If printk us used from a
context that already owns the scheduler locks or locks that have a
reverse ordering with the scheduler locks this gives potential for
deadlocks.

Avoid the wakeup by creating special semaphore operations that keep
the semaphore internal spinlock held, this ensures console_sem
contention will spin on this lock and not get queued on the wait_list.

For now keep these special semaphore operations private to printk,
if there ever appears another valid user we can move them over to
semaphore.c (along with extending the interface to provide
{_irq,_irqsave} versions, as the current ones assume IRQs are disabled
(as per the use-case in printk).

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |  208 +++++++++++++++++++++++++++-----------------------------
 1 file changed, 102 insertions(+), 106 deletions(-)

Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -765,47 +765,11 @@ static volatile unsigned int printk_cpu 
  * being able to cope (CON_ANYTIME) don't call them until
  * this CPU is officially up.
  */
-static inline int can_use_console(unsigned int cpu)
+static inline int can_use_console(void)
 {
-	return cpu_online(cpu) || have_callable_console();
+	return cpu_online(smp_processor_id()) || have_callable_console();
 }
 
-/*
- * Try to get console ownership to actually show the kernel
- * 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, wake = 0;
-
-	if (console_trylock()) {
-		retval = 1;
-
-		/*
-		 * If we can't use the console, we need to release
-		 * the console semaphore by hand to avoid flushing
-		 * the buffer. We need to hold the console semaphore
-		 * in order to do this test safely.
-		 */
-		if (!can_use_console(cpu)) {
-			console_locked = 0;
-			wake = 1;
-			retval = 0;
-		}
-	}
-	printk_cpu = UINT_MAX;
-	spin_unlock(&logbuf_lock);
-	if (wake)
-		up(&console_sem);
-	return retval;
-}
 static const char recursion_bug_msg [] =
 		KERN_CRIT "BUG: recent printk recursion!\n";
 static int recursion_bug;
@@ -826,6 +790,97 @@ static inline void printk_delay(void)
 	}
 }
 
+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);
+}
+
+static void __console_flush(void)
+{
+	unsigned long flags;
+	unsigned _con_start, _log_end;
+	unsigned wake_klogd = 0;
+
+	console_may_schedule = 0;
+
+	for ( ; ; ) {
+		spin_lock_irqsave(&logbuf_lock, flags);
+		wake_klogd |= log_start - log_end;
+		if (con_start == log_end)
+			break;			/* Nothing to print */
+		_con_start = con_start;
+		_log_end = log_end;
+		con_start = log_end;		/* Flush */
+		spin_unlock(&logbuf_lock);
+		stop_critical_timings();	/* don't trace print latency */
+		call_console_drivers(_con_start, _log_end);
+		start_critical_timings();
+		local_irq_restore(flags);
+	}
+	console_locked = 0;
+
+	/* Release the exclusive_console once it is used */
+	if (unlikely(exclusive_console))
+		exclusive_console = NULL;
+
+	spin_unlock_irqrestore(&logbuf_lock, flags);
+
+	if (wake_klogd)
+		wake_up_klogd();
+}
+
+
+/*
+ * Special 'atomic' semaphore operations that mimic down_trylock() + up(),
+ * except they don't release the semaphore internal lock and optimize the
+ * sem->count fiddling away.
+ *
+ * The advantage is that this construct doesn't generate wakeups on atomic_up()
+ * since any contending semaphore acquisition will still be spinning on the
+ * internal lock, instead of having gotten queued on the wait_list.
+ *
+ * printk() uses this to avoid generating wakeups, which would make it unsafe
+ * to use in certain contexts (avoids lock inversion or lock recursion with
+ * the scheduler locks).
+ *
+ * Assumes IRQs are disabled.
+ *
+ * Note:  We emphatically do *not* want this function exported. Ever.
+ * Note2: Even asking for that will likely buy you a nasty response.
+ */
+static int atomic_down_trylock(struct semaphore *sem)
+{
+	spin_lock(&sem->lock);
+	if (sem->count > 0)
+		return 0;
+
+	spin_unlock(&sem->lock);
+	return 1;
+}
+
+static void atomic_up(struct semaphore *sem)
+{
+	spin_unlock(&sem->lock);
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -943,19 +998,14 @@ asmlinkage int vprintk(const char *fmt, 
 		if (*p == '\n')
 			new_text_line = 1;
 	}
+	printk_cpu = UINT_MAX;
+	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();
+	if (!atomic_down_trylock(&console_sem)) {
+		if (can_use_console())
+			__console_flush();
+		atomic_up(&console_sem);
+	}
 
 out_restore_irqs:
 	local_irq_restore(flags);
@@ -1200,29 +1250,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
  *
@@ -1239,41 +1266,10 @@ void wake_up_klogd(void)
  */
 void console_unlock(void)
 {
-	unsigned long flags;
-	unsigned _con_start, _log_end;
-	unsigned wake_klogd = 0;
-
-	if (console_suspended) {
-		up(&console_sem);
-		return;
-	}
-
-	console_may_schedule = 0;
-
-	for ( ; ; ) {
-		spin_lock_irqsave(&logbuf_lock, flags);
-		wake_klogd |= log_start - log_end;
-		if (con_start == log_end)
-			break;			/* Nothing to print */
-		_con_start = con_start;
-		_log_end = log_end;
-		con_start = log_end;		/* Flush */
-		spin_unlock(&logbuf_lock);
-		stop_critical_timings();	/* don't trace print latency */
-		call_console_drivers(_con_start, _log_end);
-		start_critical_timings();
-		local_irq_restore(flags);
-	}
-	console_locked = 0;
+	if (!console_suspended)
+		__console_flush();
 
-	/* Release the exclusive_console once it is used */
-	if (unlikely(exclusive_console))
-		exclusive_console = NULL;
-
-	spin_unlock_irqrestore(&logbuf_lock, flags);
 	up(&console_sem);
-	if (wake_klogd)
-		wake_up_klogd();
 }
 EXPORT_SYMBOL(console_unlock);
 

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Linus Torvalds]

On Thu, Jun 9, 2011 at 7:23 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> Subject: printk: Avoid all wakeups from printk
> From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Date: Wed Jun 08 17:29:59 CEST 2011

Looks good to me.  Is it working? You said that some early version of
this caused problems for Ingo?

                      Linus

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Ingo Molnar]

* Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Thu, Jun 9, 2011 at 7:23 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> > Subject: printk: Avoid all wakeups from printk
> > From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > Date: Wed Jun 08 17:29:59 CEST 2011
> 
> Looks good to me.  Is it working? You said that some early version 
> of this caused problems for Ingo?

Yeah, it locked up during lockup in the middle of a printk and i 
bisected it back to the third (most dangerous) commit - will retry 
this version if Peter thinks it's materially different.

Thanks,

	Ingo

Re: [PATCH 3/3] printk: Avoid all wakeups from printk

[Peter Zijlstra]

On Thu, 2011-06-09 at 17:51 +0200, Ingo Molnar wrote:
> * Linus Torvalds <torvalds@linux-foundation.org> wrote:
> 
> > On Thu, Jun 9, 2011 at 7:23 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> > > Subject: printk: Avoid all wakeups from printk
> > > From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > > Date: Wed Jun 08 17:29:59 CEST 2011
> > 
> > Looks good to me.  Is it working? You said that some early version 
> > of this caused problems for Ingo?
> 
> Yeah, it locked up during lockup in the middle of a printk and i 
> bisected it back to the third (most dangerous) commit - will retry 
> this version if Peter thinks it's materially different.

Well, please try again, the patch isn't different, but your .config
didn't want to reproduce at all for me, so if you've got a machine that
reliably fails, we can have a poke at it.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Andrew Morton]

On Thu, 09 Jun 2011 15:06:48 +0200
Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> Release console_sem after unlocking the logbuf_lock so that we don't
> generate wakeups while holding logbuf_lock. This avoids some lock
> inversion troubles once we remove the lockdep_off bits between
> logbuf_lock and rq->lock (prints while holding rq->lock vs doing
> wakeups while holding logbuf_lock).
> 
> There's of course still an actual deadlock where the printk()s under
> rq->lock will issue a wakeup from the up() call.
> 
> ...
>
> @@ -1271,8 +1273,8 @@ void console_unlock(void)
>  	if (unlikely(exclusive_console))
>  		exclusive_console = NULL;
>  
> -	up(&console_sem);
>  	spin_unlock_irqrestore(&logbuf_lock, flags);
> +	up(&console_sem);
>  	if (wake_klogd)
>  		wake_up_klogd();
>  }

I have a horrible feeling that I put the up() inside logbuf_lock for
Special And Cunning Reasons.  But I'm struggling to work out what they
might have been and my archives only go back to October 2000(!).

Hate it when that happens.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> On Thu, 09 Jun 2011 15:06:48 +0200
> Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> 
> > Release console_sem after unlocking the logbuf_lock so that we don't
> > generate wakeups while holding logbuf_lock. This avoids some lock
> > inversion troubles once we remove the lockdep_off bits between
> > logbuf_lock and rq->lock (prints while holding rq->lock vs doing
> > wakeups while holding logbuf_lock).
> > 
> > There's of course still an actual deadlock where the printk()s under
> > rq->lock will issue a wakeup from the up() call.
> > 
> > ...
> >
> > @@ -1271,8 +1273,8 @@ void console_unlock(void)
> >  	if (unlikely(exclusive_console))
> >  		exclusive_console = NULL;
> >  
> > -	up(&console_sem);
> >  	spin_unlock_irqrestore(&logbuf_lock, flags);
> > +	up(&console_sem);
> >  	if (wake_klogd)
> >  		wake_up_klogd();
> >  }
> 
> I have a horrible feeling that I put the up() inside logbuf_lock for
> Special And Cunning Reasons.  But I'm struggling to work out what they
> might have been and my archives only go back to October 2000(!).
> 
> Hate it when that happens.

Heh, here's what i told Peter two days ago when i saw that chunk:

  => Subject: printk: Release console_sem after logbuf_lock
  => i have some vague memories about some sort of complication in that area ...
  => but don't remember the specifics
  => only a 'there be dragons' mental marker

and i have to say that when i found a boot lockup during testing i 
was not surprised very much :)

Thanks,

	Ingo

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Thu, 2011-06-09 at 22:27 +0200, Ingo Molnar wrote:

> > > @@ -1271,8 +1273,8 @@ void console_unlock(void)
> > >  	if (unlikely(exclusive_console))
> > >  		exclusive_console = NULL;
> > >  
> > > -	up(&console_sem);
> > >  	spin_unlock_irqrestore(&logbuf_lock, flags);
> > > +	up(&console_sem);
> > >  	if (wake_klogd)
> > >  		wake_up_klogd();
> > >  }
> > 
> > I have a horrible feeling that I put the up() inside logbuf_lock for
> > Special And Cunning Reasons.  But I'm struggling to work out what they
> > might have been and my archives only go back to October 2000(!).
> > 
> > Hate it when that happens.
> 
> Heh, here's what i told Peter two days ago when i saw that chunk:
> 
>   => Subject: printk: Release console_sem after logbuf_lock
>   => i have some vague memories about some sort of complication in that area ...
>   => but don't remember the specifics
>   => only a 'there be dragons' mental marker

Right, my reply was that I couldn't convince myself unlock order could
make a difference, but clearly I can easily have missed something
subtle.

> and i have to say that when i found a boot lockup during testing i 
> was not surprised very much :)

But you found a lockup on the second patch, not this one.

Also, this patch is important for #3, where we want to take logbuf_lock
under the semaphore internal lock, that too would preclude us doing that
up() in the old location.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Andrew Morton]

On Thu, 09 Jun 2011 22:54:43 +0200
Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> On Thu, 2011-06-09 at 22:27 +0200, Ingo Molnar wrote:
> 
> > > > @@ -1271,8 +1273,8 @@ void console_unlock(void)
> > > >  	if (unlikely(exclusive_console))
> > > >  		exclusive_console = NULL;
> > > >  
> > > > -	up(&console_sem);
> > > >  	spin_unlock_irqrestore(&logbuf_lock, flags);
> > > > +	up(&console_sem);
> > > >  	if (wake_klogd)
> > > >  		wake_up_klogd();
> > > >  }
> > > 
> > > I have a horrible feeling that I put the up() inside logbuf_lock for
> > > Special And Cunning Reasons.  But I'm struggling to work out what they
> > > might have been and my archives only go back to October 2000(!).
> > > 
> > > Hate it when that happens.
> > 
> > Heh, here's what i told Peter two days ago when i saw that chunk:
> > 
> >   => Subject: printk: Release console_sem after logbuf_lock
> >   => i have some vague memories about some sort of complication in that area ...
> >   => but don't remember the specifics
> >   => only a 'there be dragons' mental marker
> 
> Right, my reply was that I couldn't convince myself unlock order could
> make a difference, but clearly I can easily have missed something
> subtle.

I wish I could find the darned patch.  I have a file here
no-console-lock-2.patch which was last diffed on October 7, 1999 but it
has no changelog :(

But this:
http://lkml.indiana.edu/hypermail/linux/kernel/0109.2/0127.html is Sep
2001 and I have an earlier (unchangelogged) no-console-lock.patch diffed
against 2.4.2 in March 2001.

It's odd that the patch (and changelog) don't appear in my lkml
archives.  Sigh, http://www.youtube.com/watch?v=oO3YmT2d-8k

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Hugh Dickins]

On Thu, 9 Jun 2011, Andrew Morton wrote:
> On Thu, 09 Jun 2011 22:54:43 +0200
> Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> 
> > On Thu, 2011-06-09 at 22:27 +0200, Ingo Molnar wrote:
> > 
> > > > > @@ -1271,8 +1273,8 @@ void console_unlock(void)
> > > > >  	if (unlikely(exclusive_console))
> > > > >  		exclusive_console = NULL;
> > > > >  
> > > > > -	up(&console_sem);
> > > > >  	spin_unlock_irqrestore(&logbuf_lock, flags);
> > > > > +	up(&console_sem);
> > > > >  	if (wake_klogd)
> > > > >  		wake_up_klogd();
> > > > >  }
> > > > 
> > > > I have a horrible feeling that I put the up() inside logbuf_lock for
> > > > Special And Cunning Reasons.  But I'm struggling to work out what they
> > > > might have been and my archives only go back to October 2000(!).
> > > > 
> > > > Hate it when that happens.
> > > 
> > > Heh, here's what i told Peter two days ago when i saw that chunk:
> > > 
> > >   => Subject: printk: Release console_sem after logbuf_lock
> > >   => i have some vague memories about some sort of complication in that area ...
> > >   => but don't remember the specifics
> > >   => only a 'there be dragons' mental marker
> > 
> > Right, my reply was that I couldn't convince myself unlock order could
> > make a difference, but clearly I can easily have missed something
> > subtle.
> 
> I wish I could find the darned patch.  I have a file here
> no-console-lock-2.patch which was last diffed on October 7, 1999 but it
> has no changelog :(
> 
> But this:
> http://lkml.indiana.edu/hypermail/linux/kernel/0109.2/0127.html is Sep
> 2001 and I have an earlier (unchangelogged) no-console-lock.patch diffed
> against 2.4.2 in March 2001.
> 
> It's odd that the patch (and changelog) don't appear in my lkml
> archives.  Sigh, http://www.youtube.com/watch?v=oO3YmT2d-8k

Does your mail below stir any useful memories?

>From andrewm@uow.edu.au Sun Mar  4 11:19:14 2001
Date: Sun, 04 Mar 2001 18:31:56 +1100
From: Andrew Morton <andrewm@uow.edu.au>
To: linux-fbdev-devel@sourceforge.net, lkml <linux-kernel@vger.kernel.org>, lad <linux-audio-dev@ginette.musique.umontreal.ca>, James Simmons <jsimmons@linux-fbdev.org>, Brad Douglas <brad@neruo.com>
Subject: [prepatches] removal of console_lock


All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
hundreds of milliseconds with fbdevs.  This results in network overruns, audio
dropouts, dropped characters on serial ports and other such nice things.

This patch fixes it.  Interrupts are enabled across all console operations.

It's still somewhat a work-in-progress.

- There are (pre-existing) races around the timer functions in
  console.c. The dirty fix is to push all this stuff into keventd
  context and to use acquire_cosole_sem().  The clean fix is to
  rewrite the timer state machine.

  Or do nothing.  This thing only fires four times a day, the race
  doesn't look like it'll crash the machine and there have been no
  bug reports...

- console_print().   blah.  What's this for?  I just mapped it
  onto printk().  My preferred option is to kill it off altogether.


I'm putting this out now for comments, and for interested parties to
test.  Please.  I'm serious.


Patches against 2.4.3-pre1 and 2.4.2-ac9 are at

	http://www.uow.edu.au/~andrewm/linux/console.html

These patches are ~1600 lines and touch 35 files.



Some notes:

- show_console() had been removed.  It's unused.

- console_tasklet has been replaced with a keventd callback,
  `console_callback'.

- unblank_console() has gone.  It was only used by panic(),
  and...

- ... the call to poke_blanked_console() in vt_console_print() has
  been restored.  It doesn't deadlock during oopses now.

- arch/s390x/kernel/cpprintk.c has been removed.

- bust_spinlocks() has been enhanced (x86 and mips64).

- Major revamp of printk().  The approach taken in printk() is to try
  to acquire the (new) console_sem.  If we succeed, the output is
  placed into the log buffer and is printed to the consoles.  If we fail
  to acquire the semaphore we just buffer the output in the log buffer
  and the current holder of the console_sem will do the printing for us
  prior to releasing console_sem.

  If an oops is in progress we simply reset the locking and print
  things immediately.

- Added a new syslog() mode: syslog(9, ...).  It returns the number
  of characters which are currently queued in the log buffer.  Needed
  to do this for kmsg_poll().

- Being heartily sick of reverse-engineering interface information
  from implementations, I have gratuitously added comments in several
  random parts of the kernel.  Shoot me.

- Several video drivers are using spin_lock() in a timer
  handler.  There's a remote possibility that these can
  deadlock (say, the timer fires again while the lock is held).
  These have been changed to use _irqsave.

- The various low-level drivers have been reviewed to ensure that
  they are safe when interrupts are enabled.  Looks OK.

-

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Andrew Morton]

On Thu, 9 Jun 2011 16:57:29 -0700 (PDT)
Hugh Dickins <hughd@google.com> wrote:

> Does your mail below stir any useful memories?

Thanks.  I did have the email, but it didn't match any of my grep
patterns.

> Some notes:

Stupid thing doesn't explain the magical locking though :( I'm 99.9%
sure that putting an up() inside a spinlock_irq()ed region was
deliberate.

> - Being heartily sick of reverse-engineering interface information
>   from implementations, I have gratuitously added comments in several
>   random parts of the kernel.  Shoot me.

hah.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> >   => only a 'there be dragons' mental marker
> 
> Right, my reply was that I couldn't convince myself unlock order 
> could make a difference, but clearly I can easily have missed 
> something subtle.
> 
> > and i have to say that when i found a boot lockup during testing 
> > i was not surprised very much :)
> 
> But you found a lockup on the second patch, not this one.

Yeah, it's not like my mental markers are overly precise! ;-)

> Also, this patch is important for #3, where we want to take 
> logbuf_lock under the semaphore internal lock, that too would 
> preclude us doing that up() in the old location.

Yeah. I'm not against it or anything (hey i suggested the whole 
thing), but i'll be testing this through carefully.

Thanks,

	Ingo

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> > Some notes:
> 
> Stupid thing doesn't explain the magical locking though :( I'm 
> 99.9% sure that putting an up() inside a spinlock_irq()ed region 
> was deliberate.

My guess would be it's done so that pending irqs that have queued up 
during our current printk-ing activities do not hit us with the 
console still locked.

Thanks,

	Ingo

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 11:33 +0200, Ingo Molnar wrote:
> * Andrew Morton <akpm@linux-foundation.org> wrote:
> 
> > > Some notes:
> > 
> > Stupid thing doesn't explain the magical locking though :( I'm 
> > 99.9% sure that putting an up() inside a spinlock_irq()ed region 
> > was deliberate.
> 
> My guess would be it's done so that pending irqs that have queued up 
> during our current printk-ing activities do not hit us with the 
> console still locked.

Ah, so we already flushed the buffer, but have console_sem locked, so
any interrupt that comes in and prints something will place it in the
buffer but find console_sem is taken, so not flush it.

Then when we're back to doing up() the buffer is filled and nobody will
flush it.

I guess, we can write it like:

	spin_unlock(&logbuf_lock);
	up(&console_sem);
	local_irq_restore(flags);

which would keep interrupt disabled over up(), but have the logbuf_lock
dropped.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 11:40 +0200, Peter Zijlstra wrote:
> On Fri, 2011-06-10 at 11:33 +0200, Ingo Molnar wrote:
> > * Andrew Morton <akpm@linux-foundation.org> wrote:
> > 
> > > > Some notes:
> > > 
> > > Stupid thing doesn't explain the magical locking though :( I'm 
> > > 99.9% sure that putting an up() inside a spinlock_irq()ed region 
> > > was deliberate.
> > 
> > My guess would be it's done so that pending irqs that have queued up 
> > during our current printk-ing activities do not hit us with the 
> > console still locked.
> 
> Ah, so we already flushed the buffer, but have console_sem locked, so
> any interrupt that comes in and prints something will place it in the
> buffer but find console_sem is taken, so not flush it.
> 
> Then when we're back to doing up() the buffer is filled and nobody will
> flush it.
> 
> I guess, we can write it like:
> 
> 	spin_unlock(&logbuf_lock);
> 	up(&console_sem);
> 	local_irq_restore(flags);
> 
> which would keep interrupt disabled over up(), but have the logbuf_lock
> dropped.

Ah, not so, another cpu could start printing stuff.

So what we need is another test of log_start - log_end after up().

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

Subject: printk: Release console_sem after logbuf_lock
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Tue Jun 07 11:15:33 CEST 2011

Release console_sem after unlocking the logbuf_lock so that we don't
generate wakeups while holding logbuf_lock. This avoids some lock
inversion troubles once we remove the lockdep_off bits between
logbuf_lock and rq->lock (prints while holding rq->lock vs doing
wakeups while holding logbuf_lock).

There's of course still an actual deadlock where the printk()s under
rq->lock will issue a wakeup from the up() call.

Since console_unlock() needs to flush the buffer while holding
console_sem unlocking logbuf_lock before dropping console_sem opens a
window in which another cpu could fill the buffer again but wouldn't be
able to flush due to us still owning the console_sem, thus loosing a
flush in the process.

Solve this by dropping logbuf_lock over the up(), but re-acquire it
afterwards and check the buffer is still empty, if not try to re-acquire
the console_sem and redo the whole flush bit.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |   24 +++++++++++++++++++++---
 1 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 3518539..37dff34 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -782,7 +782,7 @@ static inline int can_use_console(unsigned int cpu)
 static int console_trylock_for_printk(unsigned int cpu)
 	__releases(&logbuf_lock)
 {
-	int retval = 0;
+	int retval = 0, wake = 0;
 
 	if (console_trylock()) {
 		retval = 1;
@@ -795,12 +795,14 @@ static int console_trylock_for_printk(unsigned int cpu)
 		 */
 		if (!can_use_console(cpu)) {
 			console_locked = 0;
-			up(&console_sem);
+			wake = 1;
 			retval = 0;
 		}
 	}
 	printk_cpu = UINT_MAX;
 	spin_unlock(&logbuf_lock);
+	if (wake)
+		up(&console_sem);
 	return retval;
 }
 static const char recursion_bug_msg [] =
@@ -1242,7 +1244,7 @@ void console_unlock(void)
 {
 	unsigned long flags;
 	unsigned _con_start, _log_end;
-	unsigned wake_klogd = 0;
+	unsigned wake_klogd = 0, retry = 0;
 
 	if (console_suspended) {
 		up(&console_sem);
@@ -1251,6 +1253,7 @@ void console_unlock(void)
 
 	console_may_schedule = 0;
 
+again:
 	for ( ; ; ) {
 		spin_lock_irqsave(&logbuf_lock, flags);
 		wake_klogd |= log_start - log_end;
@@ -1271,8 +1274,23 @@ void console_unlock(void)
 	if (unlikely(exclusive_console))
 		exclusive_console = NULL;
 
+	spin_unlock(&logbuf_lock);
+
 	up(&console_sem);
+
+	/*
+	 * 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,
+	 * there's a new owner and the console_unlock() from them will do the
+	 * flush, no worries.
+	 */
+	spin_lock(&logbuf_lock);
+	if (con_start != log_end)
+		retry = 1;
 	spin_unlock_irqrestore(&logbuf_lock, flags);
+	if (retry && console_trylock())
+		goto again;
+
 	if (wake_klogd)
 		wake_up_klogd();
 }

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> 
> All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
> This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
> hundreds of milliseconds with fbdevs.  This results in network overruns, audio
> dropouts, dropped characters on serial ports and other such nice things.

Hmm, with these proposed patches we're actually back to that. I wonder
if fbdev is still that crappy..

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:
> On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> > 
> > All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
> > This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
> > hundreds of milliseconds with fbdevs.  This results in network overruns, audio
> > dropouts, dropped characters on serial ports and other such nice things.
> 
> Hmm, with these proposed patches we're actually back to that. I wonder
> if fbdev is still that crappy..

So I tried adding a fbcon to my test box (not that it actually has a
display, but who cares) and disabled lockdep (otherwise that's all I can
catch on the latency tracer) to see if I could see whopping horrid
latencies there, but I'm afraid I either failed to set things up
properly or my fbcon isn't sucky enough.

What I did was enable:

CONFIG_FB=y
CONFIG_FB_SIS=y
CONFIG_FB_SIS_315=y (the board has XGI z7)

and

CONFIG_FRAMEBUFFER_CONSOLE=y

And used:

 debug ignore_loglevel sysrq_always_enabled console=tty0
console=ttyS0,115200 earlyprintk=serial,ttyS0,115200

thinking that that would have my printk stmts appear on both the fbcon
as well as the serial line. But they fail to appear on the latency
tracer (current max was 165us waking an idle cpu).

Paul (and fellow fbcon folks), was my setup above correct, and what's
the current status of suckyness wrt fbcon output?

The idea is to keep IRQs disabled over all of printk() including the
con->write() calls, Andrew seems to be responsible removing that in the
early 2.4 time-frame due to some consoles being waaay crap and taking
like hundreds of ms to write things out, can that still happen or has
stuff improved and is using background flusher threads to write to slow
devices?

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:
> On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> > 
> > All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
> > This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
> > hundreds of milliseconds with fbdevs.  This results in network overruns, audio
> > dropouts, dropped characters on serial ports and other such nice things.
> 
> Hmm, with these proposed patches we're actually back to that. I wonder
> if fbdev is still that crappy..

So I tried adding a fbcon to my test box (not that it actually has a
display, but who cares) and disabled lockdep (otherwise that's all I can
catch on the latency tracer) to see if I could see whopping horrid
latencies there, but I'm afraid I either failed to set things up
properly or my fbcon isn't sucky enough.

What I did was enable:

CONFIG_FB=y
CONFIG_FB_SIS=y
CONFIG_FB_SIS_315=y (the board has XGI z7)

and

CONFIG_FRAMEBUFFER_CONSOLE=y

And used:

 debug ignore_loglevel sysrq_always_enabled console=tty0
console=ttyS0,115200 earlyprintk=serial,ttyS0,115200

thinking that that would have my printk stmts appear on both the fbcon
as well as the serial line. But they fail to appear on the latency
tracer (current max was 165us waking an idle cpu).

Paul (and fellow fbcon folks), was my setup above correct, and what's
the current status of suckyness wrt fbcon output?

The idea is to keep IRQs disabled over all of printk() including the
con->write() calls, Andrew seems to be responsible removing that in the
early 2.4 time-frame due to some consoles being waaay crap and taking
like hundreds of ms to write things out, can that still happen or has
stuff improved and is using background flusher threads to write to slow
devices?

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> thinking that that would have my printk stmts appear on both the 
> fbcon as well as the serial line. But they fail to appear on the 
> latency tracer (current max was 165us waking an idle cpu).

Have you removed this bit:

                spin_unlock(&logbuf_lock);
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(_con_start, _log_end);
                start_critical_timings();
                local_irq_restore(flags);

which hides the latencies from the latency tracer?

Thanks,

	Ingo

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> thinking that that would have my printk stmts appear on both the 
> fbcon as well as the serial line. But they fail to appear on the 
> latency tracer (current max was 165us waking an idle cpu).

Have you removed this bit:

                spin_unlock(&logbuf_lock);
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(_con_start, _log_end);
                start_critical_timings();
                local_irq_restore(flags);

which hides the latencies from the latency tracer?

Thanks,

	Ingo

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > thinking that that would have my printk stmts appear on both the 
> > fbcon as well as the serial line. But they fail to appear on the 
> > latency tracer (current max was 165us waking an idle cpu).
> 
> Have you removed this bit:
> 
>                 spin_unlock(&logbuf_lock);
>                 stop_critical_timings();        /* don't trace print latency */
>                 call_console_drivers(_con_start, _log_end);
>                 start_critical_timings();
>                 local_irq_restore(flags);
> 
> which hides the latencies from the latency tracer?

it shouldn't those flags come from spin_lock_irqsave(), which already
has IRQs disabled, so the restore shouldn't re-enable them.

Hmm,. that might actually already be true for mainline too, yeah, looks
like we call vprintk()->console_unlock() with IRQs-disabled.

Hohumm..

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > thinking that that would have my printk stmts appear on both the 
> > fbcon as well as the serial line. But they fail to appear on the 
> > latency tracer (current max was 165us waking an idle cpu).
> 
> Have you removed this bit:
> 
>                 spin_unlock(&logbuf_lock);
>                 stop_critical_timings();        /* don't trace print latency */
>                 call_console_drivers(_con_start, _log_end);
>                 start_critical_timings();
>                 local_irq_restore(flags);
> 
> which hides the latencies from the latency tracer?

it shouldn't those flags come from spin_lock_irqsave(), which already
has IRQs disabled, so the restore shouldn't re-enable them.

Hmm,. that might actually already be true for mainline too, yeah, looks
like we call vprintk()->console_unlock() with IRQs-disabled.

Hohumm..

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:41 +0200, Peter Zijlstra wrote:
> On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> > * Peter Zijlstra <peterz@infradead.org> wrote:
> > 
> > > thinking that that would have my printk stmts appear on both the 
> > > fbcon as well as the serial line. But they fail to appear on the 
> > > latency tracer (current max was 165us waking an idle cpu).
> > 
> > Have you removed this bit:
> > 
> >                 spin_unlock(&logbuf_lock);
> >                 stop_critical_timings();        /* don't trace print latency */
> >                 call_console_drivers(_con_start, _log_end);
> >                 start_critical_timings();
> >                 local_irq_restore(flags);
> > 
> > which hides the latencies from the latency tracer?
> 
> it shouldn't those flags come from spin_lock_irqsave(), which already
> has IRQs disabled, so the restore shouldn't re-enable them.
> 
> Hmm,. that might actually already be true for mainline too, yeah, looks
> like we call vprintk()->console_unlock() with IRQs-disabled.
> 
> Hohumm..

Also, I used the preemptirqoff tracer, so even if it did re-enable
interrupts we should still have preemption disabled and still catch the
latency.

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Peter Zijlstra]

On Fri, 2011-06-10 at 14:41 +0200, Peter Zijlstra wrote:
> On Fri, 2011-06-10 at 14:34 +0200, Ingo Molnar wrote:
> > * Peter Zijlstra <peterz@infradead.org> wrote:
> > 
> > > thinking that that would have my printk stmts appear on both the 
> > > fbcon as well as the serial line. But they fail to appear on the 
> > > latency tracer (current max was 165us waking an idle cpu).
> > 
> > Have you removed this bit:
> > 
> >                 spin_unlock(&logbuf_lock);
> >                 stop_critical_timings();        /* don't trace print latency */
> >                 call_console_drivers(_con_start, _log_end);
> >                 start_critical_timings();
> >                 local_irq_restore(flags);
> > 
> > which hides the latencies from the latency tracer?
> 
> it shouldn't those flags come from spin_lock_irqsave(), which already
> has IRQs disabled, so the restore shouldn't re-enable them.
> 
> Hmm,. that might actually already be true for mainline too, yeah, looks
> like we call vprintk()->console_unlock() with IRQs-disabled.
> 
> Hohumm..

Also, I used the preemptirqoff tracer, so even if it did re-enable
interrupts we should still have preemption disabled and still catch the
latency.

Re: [PATCH 2/3] printk, lockdep: Remove lockdep_off() usage

[Peter Zijlstra]

On Thu, 2011-06-09 at 15:06 +0200, Peter Zijlstra wrote:
> Remove the lockdep_off() usage from printk(). Also add a
> debug_locks_off() call to zap_locks() since that'll mess up the lock
> state in a royal way anyway. Further switch to local_irq_ ops so that
> the irq state is properly tracked (raw_local_irq_* isn't tracked by
> lockdep, causing confusion). Also drop superfluous preempt_disable(),
> disabling IRQs already avoids scheduling.
> 

OK, so while trying to decipher the irq status of printk() I found
commit 1efc5da3 which explains why we've got lockdep_off() in there,
there still is a recursion problem with trace_hardirqs_*.

/me goes poke at that..

Re: [PATCH 1/3] printk: Release console_sem after logbuf_lock

[Pavel Machek]

vvOn Fri 2011-06-10 14:30:30, Peter Zijlstra wrote:
>On Fri, 2011-06-10 at 13:28 +0200, Peter Zijlstra wrote:
> > On Thu, 2011-06-09 at 16:57 -0700, Hugh Dickins wrote:
> > > 
> > > All console-related activity curently happens under spin_lock_irqsave(&console_lock). 
> > > This causes interrutps to be blocked for 1-2 milliseconds with vgacon, and for
> > > hundreds of milliseconds with fbdevs.  This results in network overruns, audio
> > > dropouts, dropped characters on serial ports and other such nice things.
> > 
> > Hmm, with these proposed patches we're actually back to that. I wonder
> > if fbdev is still that crappy..
> 
> So I tried adding a fbcon to my test box (not that it actually has a
> display, but who cares) and disabled lockdep (otherwise that's all I can
> catch on the latency tracer) to see if I could see whopping horrid
> latencies there, but I'm afraid I either failed to set things up
> properly or my fbcon isn't sucky enough.
> 
> What I did was enable:
> 
> CONFIG_FB=y
> CONFIG_FB_SIS=y
> CONFIG_FB_SIS_315=y (the board has XGI z7)

sis will be accelerated. Try vesafb; scrolling should be horrible.
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html