From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934700AbcJ0Pwa (ORCPT ); Thu, 27 Oct 2016 11:52:30 -0400 Received: from mail-pf0-f194.google.com ([209.85.192.194]:33719 "EHLO mail-pf0-f194.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755937AbcJ0Pv5 (ORCPT ); Thu, 27 Oct 2016 11:51:57 -0400 From: Sergey Senozhatsky To: Petr Mladek , Andrew Morton Cc: Jan Kara , Tejun Heo , Calvin Owens , Thomas Gleixner , Mel Gorman , Steven Rostedt , Ingo Molnar , Peter Zijlstra , Laura Abbott , Andy Lutomirski , Linus Torvalds , Kees Cook , linux-kernel@vger.kernel.org, Sergey Senozhatsky , Sergey Senozhatsky Subject: [RFC][PATCHv4 5/6] printk: use printk_safe buffers Date: Fri, 28 Oct 2016 00:49:32 +0900 Message-Id: <20161027154933.1211-6-sergey.senozhatsky@gmail.com> X-Mailer: git-send-email 2.10.1.502.g6598894 In-Reply-To: <20161027154933.1211-1-sergey.senozhatsky@gmail.com> References: <20161027154933.1211-1-sergey.senozhatsky@gmail.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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: [] warn_slowpath_null+0x1d/0x1f [] vprintk_emit+0x1cd/0x438 [] vprintk_default+0x1d/0x1f [] printk+0x48/0x50 [..] [] 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: [] 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 [..] [] 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: [] 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 [..] [] 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: [] 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 [..] [] 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: [] 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 [..] [] entry_SYSCALL_64_fastpath+0x13/0x94 ---[ end trace ]--- Signed-off-by: Sergey Senozhatsky --- 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