[PATCH] printk: fix recursion of logbuf_lock spinlock

[PATCH] printk: fix recursion of logbuf_lock spinlock

[Andrea Arcangeli]

With flooding printks over (virtual|physical) serial console I've been
noticing hangs. The problem is a recursive deadlock that then hangs
any console output ("recursion" is also shown in the params to
spin_bug below with lockdep enabled but the nested vprintk at #7 hangs
on the same lock as it needs to take that too).

 gdb> bt
 #0  0xffffffff811fe17a in rdtsc_barrier (loops=0x1) at arch/x86/lib/delay.c:57
 #1  delay_tsc (loops=0x1) at arch/x86/lib/delay.c:58
 #2  0xffffffff811fe0ca in __delay (loops=<value optimized out>) at arch/x86/lib/delay.c:112
 #3  0xffffffff81204ff3 in __spin_lock_debug (lock=0xffffffff81686220) at lib/spinlock_debug.c:116
 #4  do_raw_spin_lock (lock=0xffffffff81686220) at lib/spinlock_debug.c:133
 #5  0xffffffff8147cba4 in __raw_spin_lock (lock=0xffffffff81686220) at include/linux/spinlock_api_smp.h:144
 #6  _raw_spin_lock (lock=0xffffffff81686220) at kernel/spinlock.c:137
 #7  0xffffffff8104d4df in vprintk (fmt=0xffffffff815ee3c8 "<0>BUG: spinlock %s on CPU#%d, %s/%d\n", args=0xffff88003b0d fb68) at kernel/printk.c:867
 #8  0xffffffff81479565 in printk (fmt=<value optimized out>) at kernel/printk.c:752
 #9  0xffffffff81204d96 in spin_dump (lock=0xffffffff81686220, msg=<value optimized out>) at lib/spinlock_debug.c:58
 #10 0xffffffff81204e3b in spin_bug (lock=0xffffffff81686220, msg=0xffffffff815ee13a "recursion") at lib/spinlock_debug.c:75
 #11 0xffffffff81205018 in debug_spin_lock_before (lock=0xffffffff81686220) at lib/spinlock_debug.c:84
 #12 do_raw_spin_lock (lock=0xffffffff81686220) at lib/spinlock_debug.c:131
 #13 0xffffffff8147cb5c in __raw_spin_lock_irqsave (lock=0xffffffff81686220) at include/linux/spinlock_api_smp.h:117
 #14 _raw_spin_lock_irqsave (lock=0xffffffff81686220) at kernel/spinlock.c:145
 #15 0xffffffff8104d104 in console_unlock () at kernel/printk.c:1264
 #16 0xffffffff81290602 in do_con_write (tty=0xffff88003c055000, buf=0xffffffff815fe051 "", count=<value optimized out>)  at drivers/tty/vt/vt.c:2368
 #17 0xffffffff81292169 in con_write (tty=0xffff88003c055000, buf=<value optimized out>, count=<value optimized out>) at drivers/tty/vt/vt.c:2704
 #18 0xffffffff8127b72b in do_output_char (c=<value optimized out>, tty=<value optimized out>, space=<value optimized out>) at drivers/tty/n_tty.c:310
 #19 0xffffffff8127b7a1 in process_output (c=0xa, tty=0xffff88003c055000) at drivers/tty/n_tty.c:376
 #20 0xffffffff8127d77b in n_tty_write (tty=0xffff88003c055000, file=0xffff88003c73e440, buf=0xffff88003c3d9400 "Nov 24 19:36:40 kvm kernel: migrate_pages 0\n 240215\npfn 240183, end_pfn 241152\ner root by LOGIN(uid=0)\nput/input2\nIDE ports\n, 504k init)\n4 19:28:49 CET 2011\n", nr=0x1) at drivers/tty/n_tty.c:1983
 #21 0xffffffff81278af5 in do_tty_write (file=0xffff88003c73e440, buf=<value optimized out>, count=<value optimized out>, ppos=<value optimized out>) at drivers/tty/tty_io.c:1068
 #22 tty_write (file=0xffff88003c73e440, buf=<value optimized out>, count=<value optimized out>, ppos=<value optimized out>) at drivers/tty/tty_io.c:1156
 #23 0xffffffff81112036 in vfs_write (file=0xffff88003c73e440, buf=0x1f19780 "Nov 24 19:36:40 kvm kernel: migrate_pages 0\n", count=0x2c, pos=0xffff88003b0dff48) at fs/read_write.c:435
 #24 0xffffffff8111234c in sys_write (fd=<value optimized out>, buf=0x1f19780 "Nov 24 19:36:40 kvm kernel: migrate_pages 0\n", count=0x2c) at fs/read_write.c:487
 #25 <signal handler called>
 #26 0x00007f22d47887c0 in __brk_reservation_fn_dmi_alloc__ ()
 #27 0xffff88003b0de5c0 in __brk_reservation_fn_dmi_alloc__ ()
 #28 0xffffffff81685f20 in ?? ()
 #29 0x0000000000000000 in ?? ()

Signed-off-by: Andrea Arcangeli <aarcange@redhat.com>
---
 kernel/printk.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 1455a0d..fc3c831 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1259,9 +1259,9 @@ void console_unlock(void)
 
 	console_may_schedule = 0;
 
-again:
 	for ( ; ; ) {
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
+again:
 		wake_klogd |= log_start - log_end;
 		if (con_start == log_end)
 			break;			/* Nothing to print */

Re: [PATCH] printk: fix recursion of logbuf_lock spinlock

[Peter Zijlstra]

On Thu, 2011-11-24 at 20:04 +0100, Andrea Arcangeli wrote:
>  kernel/printk.c |    2 +-
>  1 files changed, 1 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index 1455a0d..fc3c831 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -1259,9 +1259,9 @@ void console_unlock(void)
>  
>         console_may_schedule = 0;
>  
> -again:
>         for ( ; ; ) {
>                 raw_spin_lock_irqsave(&logbuf_lock, flags);
> +again:
>                 wake_klogd |= log_start - log_end;
>                 if (con_start == log_end)
>                         break;                  /* Nothing to print */ 

The better change would be the below one, since that avoid doing
console_trylock() while holding logbuf_lock. The problem is that
console_trylock() can do up() and thus result in a wakeup while holding
logbuf_lock and we're trying to get rid of locks nested under
logbug_lock.

---
Subject: printk: Avoid double lock acquire

Commit 4f2a8d3cf5e ("printk: Fix console_sem vs logbuf_lock unlock
race") introduced another silly bug where we would want to acquire an
already held lock. Avoid this.

Reported-by: Andrea Arcangeli <aarcange@redhat.com>
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index dfd8f73..187662f 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1292,10 +1292,11 @@ void console_unlock(void)
 	raw_spin_lock(&logbuf_lock);
 	if (con_start != log_end)
 		retry = 1;
+	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+
 	if (retry && console_trylock())
 		goto again;
 
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 	if (wake_klogd)
 		wake_up_klogd();
 }