Messages in this thread Patch in this message | | | From | Sergey Senozhatsky <> | Subject | [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk | Date | Thu, 1 Dec 2016 22:55:45 +0900 |
| |
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().
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+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@gmail.com> --- 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 6f7b217..80f0177 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 @@ -1788,7 +1802,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(); /* @@ -1804,13 +1818,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; @@ -1870,12 +1883,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 @@ -1883,7 +1894,6 @@ asmlinkage int vprintk_emit(int facility, int level, */ if (console_trylock()) console_unlock(); - lockdep_on(); } return printed_len; @@ -2263,7 +2273,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; @@ -2288,10 +2299,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); } /** @@ -2356,7 +2368,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; @@ -2417,7 +2430,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(); @@ -2440,7 +2453,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.2
| |