[RFC][PATCHv4 5/6] printk: use printk_safe buffers
From: Sergey Senozhatsky
Date: Thu Oct 27 2016 - 11:52:33 EST
Use printk_safe per-CPU buffers in 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.
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+0x1cd/0x438
CPU: 0 PID: 366 Comm: bash
Call Trace:
[<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
[<ffffffff81091527>] vprintk_emit+0x1cd/0x438
[<ffffffff810918fe>] vprintk_default+0x1d/0x1f
[<ffffffff810fdf6a>] printk+0x48/0x50
[..]
[<ffffffff813caaaa>] entry_SYSCALL_64_fastpath+0x18/0xad
---[ end trace ]---
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+0x3d/0x62
CPU: 1 PID: 363 Comm: bash
Call Trace:
[<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
[<ffffffff810838df>] down_trylock+0x3d/0x62
[<ffffffff8109177e>] ? vprintk_emit+0x3f9/0x414
[<ffffffff810905cb>] console_trylock+0x31/0xeb
[<ffffffff8109177e>] vprintk_emit+0x3f9/0x414
[<ffffffff81091905>] vprintk_default+0x1d/0x1f
[<ffffffff810fdf71>] printk+0x48/0x50
[..]
[<ffffffff813caaaa>] entry_SYSCALL_64_fastpath+0x18/0xad
---[ end trace ]---
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+0x12d/0x559
CPU: 1 PID: 329 Comm: bash
Call Trace:
[<ffffffff8103d6ca>] warn_slowpath_null+0x18/0x1a
[<ffffffff8107f917>] console_unlock+0x12d/0x559
[<ffffffff810772c4>] ? trace_hardirqs_on_caller+0x16d/0x189
[<ffffffff810772ed>] ? trace_hardirqs_on+0xd/0xf
[<ffffffff810800a6>] vprintk_emit+0x363/0x374
[<ffffffff81080219>] vprintk_default+0x18/0x1a
[<ffffffff810c7f77>] printk+0x43/0x4b
[..]
[<ffffffff814c2d6a>] entry_SYSCALL_64_fastpath+0x18/0xad
---[ end trace ]---
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+0x7f/0x4f7
CPU: 3 PID: 363 Comm: bash
Call Trace:
[<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
[<ffffffff8106c8d0>] try_to_wake_up+0x7f/0x4f7
[<ffffffff8106cd5d>] wake_up_process+0x15/0x17
[<ffffffff813c82c6>] __up.isra.0+0x56/0x63
[<ffffffff810839a3>] up+0x32/0x42
[<ffffffff8108f624>] __up_console_sem+0x37/0x55
[<ffffffff810910ff>] console_unlock+0x21e/0x4c2
[<ffffffff810917bf>] vprintk_emit+0x41c/0x462
[<ffffffff81091971>] vprintk_default+0x1d/0x1f
[<ffffffff810fdfdd>] printk+0x48/0x50
[..]
[<ffffffff813cab2a>] entry_SYSCALL_64_fastpath+0x18/0xad
---[ end trace ]---
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+0x3a/0xb0
CPU: 2 PID: 305 Comm: bash
Call Trace:
[<ffffffff810399c0>] warn_slowpath_null+0x18/0x1a
[<ffffffff8106b218>] call_console_drivers.isra.6.constprop.16+0x3a/0xb0
[<ffffffff8106cc46>] console_unlock+0x471/0x48e
[<ffffffff8106ce57>] vprintk_emit+0x1f4/0x206
[<ffffffff8106cfcb>] vprintk_default+0x18/0x1a
[<ffffffff8106af66>] vprintk_func+0x6e/0x70
[<ffffffff810abbe3>] printk+0x3e/0x46
[..]
[<ffffffff8145a860>] entry_SYSCALL_64_fastpath+0x13/0x94
---[ end trace ]---
Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
---
kernel/printk/printk.c | 50 ++++++++++++++++++++++++++++++++------------------
1 file changed, 32 insertions(+), 18 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4675b8d..5907e92 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -213,17 +213,31 @@ 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;
+
+ printk_safe_enter(flags);
+ lock_failed = down_trylock(&console_sem);
+ printk_safe_exit(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(flags);
+ up(&console_sem);
+ printk_safe_exit(flags);
+}
+#define up_console_sem() __up_console_sem(_RET_IP_)
/*
* This is used for debugging the mess that is the VT code by
@@ -1807,7 +1821,7 @@ asmlinkage int vprintk_emit(int facility, int level,
boot_delay_msec(level);
printk_delay();
- local_irq_save(flags);
+ printk_safe_enter(flags);
this_cpu = smp_processor_id();
/*
@@ -1823,13 +1837,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(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;
@@ -1889,12 +1902,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(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
@@ -1902,7 +1913,6 @@ asmlinkage int vprintk_emit(int facility, int level,
*/
if (console_trylock())
console_unlock();
- lockdep_on();
}
return printed_len;
@@ -2288,7 +2298,8 @@ static void console_cont_flush(char *text, size_t size)
unsigned long flags;
size_t len;
- raw_spin_lock_irqsave(&logbuf_lock, flags);
+ printk_safe_enter(flags);
+ raw_spin_lock(&logbuf_lock);
if (!cont.len)
goto out;
@@ -2313,10 +2324,11 @@ static void console_cont_flush(char *text, size_t size)
stop_critical_timings();
call_console_drivers(cont.level, NULL, 0, text, len);
start_critical_timings();
- local_irq_restore(flags);
+ printk_safe_exit(flags);
return;
out:
- raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+ raw_spin_unlock(&logbuf_lock);
+ printk_safe_exit(flags);
}
/**
@@ -2381,7 +2393,8 @@ void console_unlock(void)
size_t len;
int level;
- raw_spin_lock_irqsave(&logbuf_lock, flags);
+ printk_safe_enter(flags);
+ raw_spin_lock(&logbuf_lock);
if (seen_seq != log_next_seq) {
wake_klogd = true;
seen_seq = log_next_seq;
@@ -2442,7 +2455,7 @@ void console_unlock(void)
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(flags);
if (do_cond_resched)
cond_resched();
@@ -2465,7 +2478,8 @@ void console_unlock(void)
*/
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(flags);
if (retry && console_trylock())
goto again;
--
2.10.1.502.g6598894