diff options
author | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> | 2016-12-27 23:16:09 +0900 |
---|---|---|
committer | Petr Mladek <pmladek@suse.com> | 2017-02-08 13:51:49 +0100 |
commit | f975237b76827956fe13ecfe993a319158e2c303 (patch) | |
tree | 21687be5c600214ecbf1156bdab96a94852c3b07 /kernel | |
parent | ddb9baa822265b55afffd9815a2758a4b70006c1 (diff) | |
download | linux-f975237b76827956fe13ecfe993a319158e2c303.tar.gz linux-f975237b76827956fe13ecfe993a319158e2c303.tar.bz2 linux-f975237b76827956fe13ecfe993a319158e2c303.zip |
printk: use printk_safe buffers in printk
Use printk_safe per-CPU buffers in printk recursion-prone blocks:
-- around logbuf_lock protected sections in vprintk_emit() and
console_unlock()
-- around down_trylock_console_sem() and up_console_sem()
Note that this solution addresses deadlocks caused by printk()
recursive calls only. That is vprintk_emit() and console_unlock().
The rest will be converted in a followup patch.
Another thing to note is that we now keep lockdep enabled in printk,
because we are protected against the printk recursion caused by
lockdep in vprintk_emit() by the printk-safe mechanism - we first
switch to per-CPU buffers and only then access the deadlock-prone
locks.
Examples:
1) printk() from logbuf_lock spin_lock section
Assume the following code:
printk()
raw_spin_lock(&logbuf_lock);
WARN_ON(1);
raw_spin_unlock(&logbuf_lock);
which now produces:
------------[ cut here ]------------
WARNING: CPU: 0 PID: 366 at kernel/printk/printk.c:1811 vprintk_emit
CPU: 0 PID: 366 Comm: bash
Call Trace:
warn_slowpath_null+0x1d/0x1f
vprintk_emit+0x1cd/0x438
vprintk_default+0x1d/0x1f
printk+0x48/0x50
[..]
2) printk() from semaphore sem->lock spin_lock section
Assume the following code
printk()
console_trylock()
down_trylock()
raw_spin_lock_irqsave(&sem->lock, flags);
WARN_ON(1);
raw_spin_unlock_irqrestore(&sem->lock, flags);
which now produces:
------------[ cut here ]------------
WARNING: CPU: 1 PID: 363 at kernel/locking/semaphore.c:141 down_trylock
CPU: 1 PID: 363 Comm: bash
Call Trace:
warn_slowpath_null+0x1d/0x1f
down_trylock+0x3d/0x62
? vprintk_emit+0x3f9/0x414
console_trylock+0x31/0xeb
vprintk_emit+0x3f9/0x414
vprintk_default+0x1d/0x1f
printk+0x48/0x50
[..]
3) printk() from console_unlock()
Assume the following code:
printk()
console_unlock()
raw_spin_lock(&logbuf_lock);
WARN_ON(1);
raw_spin_unlock(&logbuf_lock);
which now produces:
------------[ cut here ]------------
WARNING: CPU: 1 PID: 329 at kernel/printk/printk.c:2384 console_unlock
CPU: 1 PID: 329 Comm: bash
Call Trace:
warn_slowpath_null+0x18/0x1a
console_unlock+0x12d/0x559
? trace_hardirqs_on_caller+0x16d/0x189
? trace_hardirqs_on+0xd/0xf
vprintk_emit+0x363/0x374
vprintk_default+0x18/0x1a
printk+0x43/0x4b
[..]
4) printk() from try_to_wake_up()
Assume the following code:
printk()
console_unlock()
up()
try_to_wake_up()
raw_spin_lock_irqsave(&p->pi_lock, flags);
WARN_ON(1);
raw_spin_unlock_irqrestore(&p->pi_lock, flags);
which now produces:
------------[ cut here ]------------
WARNING: CPU: 3 PID: 363 at kernel/sched/core.c:2028 try_to_wake_up
CPU: 3 PID: 363 Comm: bash
Call Trace:
warn_slowpath_null+0x1d/0x1f
try_to_wake_up+0x7f/0x4f7
wake_up_process+0x15/0x17
__up.isra.0+0x56/0x63
up+0x32/0x42
__up_console_sem+0x37/0x55
console_unlock+0x21e/0x4c2
vprintk_emit+0x41c/0x462
vprintk_default+0x1d/0x1f
printk+0x48/0x50
[..]
5) printk() from call_console_drivers()
Assume the following code:
printk()
console_unlock()
call_console_drivers()
...
WARN_ON(1);
which now produces:
------------[ cut here ]------------
WARNING: CPU: 2 PID: 305 at kernel/printk/printk.c:1604 call_console_drivers
CPU: 2 PID: 305 Comm: bash
Call Trace:
warn_slowpath_null+0x18/0x1a
call_console_drivers.isra.6.constprop.16+0x3a/0xb0
console_unlock+0x471/0x48e
vprintk_emit+0x1f4/0x206
vprintk_default+0x18/0x1a
vprintk_func+0x6e/0x70
printk+0x3e/0x46
[..]
6) unsupported placeholder in printk() format now prints an actual
warning from vscnprintf(), instead of
'BUG: recent printk recursion!'.
------------[ cut here ]------------
WARNING: CPU: 5 PID: 337 at lib/vsprintf.c:1900 format_decode
Please remove unsupported %
in format string
CPU: 5 PID: 337 Comm: bash
Call Trace:
dump_stack+0x4f/0x65
__warn+0xc2/0xdd
warn_slowpath_fmt+0x4b/0x53
format_decode+0x22c/0x308
vsnprintf+0x89/0x3b7
vscnprintf+0xd/0x26
vprintk_emit+0xb4/0x238
vprintk_default+0x1d/0x1f
vprintk_func+0x6c/0x73
printk+0x43/0x4b
[..]
Link: http://lkml.kernel.org/r/20161227141611.940-7-sergey.senozhatsky@gmail.com
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Jan Kara <jack@suse.cz>
Cc: Tejun Heo <tj@kernel.org>
Cc: Calvin Owens <calvinowens@fb.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Andy Lutomirski <luto@kernel.org>
Cc: Peter Hurley <peter@hurleysoftware.com>
Cc: linux-kernel@vger.kernel.org
Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Diffstat (limited to 'kernel')
-rw-r--r-- | kernel/printk/printk.c | 47 |
1 files changed, 32 insertions, 15 deletions
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 6bb77eff502d..f426a2b12a9b 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -213,17 +213,36 @@ static int nr_ext_console_drivers; static int __down_trylock_console_sem(unsigned long ip) { - if (down_trylock(&console_sem)) + int lock_failed; + unsigned long flags; + + /* + * Here and in __up_console_sem() we need to be in safe mode, + * because spindump/WARN/etc from under console ->lock will + * deadlock in printk()->down_trylock_console_sem() otherwise. + */ + printk_safe_enter_irqsave(flags); + lock_failed = down_trylock(&console_sem); + printk_safe_exit_irqrestore(flags); + + if (lock_failed) return 1; mutex_acquire(&console_lock_dep_map, 0, 1, ip); return 0; } #define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_) -#define up_console_sem() do { \ - mutex_release(&console_lock_dep_map, 1, _RET_IP_);\ - up(&console_sem);\ -} while (0) +static void __up_console_sem(unsigned long ip) +{ + unsigned long flags; + + mutex_release(&console_lock_dep_map, 1, ip); + + printk_safe_enter_irqsave(flags); + up(&console_sem); + printk_safe_exit_irqrestore(flags); +} +#define up_console_sem() __up_console_sem(_RET_IP_) /* * This is used for debugging the mess that is the VT code by @@ -1689,7 +1708,7 @@ asmlinkage int vprintk_emit(int facility, int level, boot_delay_msec(level); printk_delay(); - local_irq_save(flags); + printk_safe_enter_irqsave(flags); this_cpu = smp_processor_id(); /* @@ -1705,13 +1724,12 @@ asmlinkage int vprintk_emit(int facility, int level, */ if (!oops_in_progress && !lockdep_recursing(current)) { recursion_bug = true; - local_irq_restore(flags); + printk_safe_exit_irqrestore(flags); return 0; } zap_locks(); } - lockdep_off(); /* This stops the holder of console_sem just where we want him */ raw_spin_lock(&logbuf_lock); logbuf_cpu = this_cpu; @@ -1771,12 +1789,10 @@ asmlinkage int vprintk_emit(int facility, int level, logbuf_cpu = UINT_MAX; raw_spin_unlock(&logbuf_lock); - lockdep_on(); - local_irq_restore(flags); + printk_safe_exit_irqrestore(flags); /* If called from the scheduler, we can not call up(). */ if (!in_sched) { - lockdep_off(); /* * Try to acquire and then immediately release the console * semaphore. The release will print out buffers and wake up @@ -1784,7 +1800,6 @@ asmlinkage int vprintk_emit(int facility, int level, */ if (console_trylock()) console_unlock(); - lockdep_on(); } return printed_len; @@ -2209,7 +2224,8 @@ again: size_t len; int level; - raw_spin_lock_irqsave(&logbuf_lock, flags); + printk_safe_enter_irqsave(flags); + raw_spin_lock(&logbuf_lock); if (seen_seq != log_next_seq) { wake_klogd = true; seen_seq = log_next_seq; @@ -2259,7 +2275,7 @@ skip: stop_critical_timings(); /* don't trace print latency */ call_console_drivers(level, ext_text, ext_len, text, len); start_critical_timings(); - local_irq_restore(flags); + printk_safe_exit_irqrestore(flags); if (do_cond_resched) cond_resched(); @@ -2282,7 +2298,8 @@ skip: */ raw_spin_lock(&logbuf_lock); retry = console_seq != log_next_seq; - raw_spin_unlock_irqrestore(&logbuf_lock, flags); + raw_spin_unlock(&logbuf_lock); + printk_safe_exit_irqrestore(flags); if (retry && console_trylock()) goto again; |