From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934084AbcI0OY7 (ORCPT ); Tue, 27 Sep 2016 10:24:59 -0400 Received: from mail-pf0-f196.google.com ([209.85.192.196]:33843 "EHLO mail-pf0-f196.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S933772AbcI0OYD (ORCPT ); Tue, 27 Sep 2016 10:24:03 -0400 From: Sergey Senozhatsky To: Petr Mladek , Jan Kara Cc: Andrew Morton , Tejun Heo , Calvin Owens , linux-kernel@vger.kernel.org, Sergey Senozhatsky , Sergey Senozhatsky Subject: [RFC][PATCH 6/7] printk: use alternative printk buffers Date: Tue, 27 Sep 2016 23:22:36 +0900 Message-Id: <20160927142237.5539-7-sergey.senozhatsky@gmail.com> X-Mailer: git-send-email 2.10.0.372.g6fe1b14 In-Reply-To: <20160927142237.5539-1-sergey.senozhatsky@gmail.com> References: <20160927142237.5539-1-sergey.senozhatsky@gmail.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Use alt_printk buffer 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 it addresses deadlocks caused by recursiove printk() 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: [] dump_stack+0x68/0x92 [] __warn+0xc2/0xdd [] 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: [] dump_stack+0x68/0x92 [] __warn+0xc2/0xdd [] 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: [] dump_stack+0x68/0x92 [] __warn+0xb8/0xd3 [] 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: [] dump_stack+0x68/0x92 [] __warn+0xc2/0xdd [] 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 ]--- another example of WARN_ON() from scheduler code: ------------[ cut here ]------------ WARNING: CPU: 1 PID: 361 at kernel/sched/core.c:2026 try_to_wake_up+0x6c/0x4e4 CPU: 1 PID: 361 Comm: bash Call Trace: [] dump_stack+0x68/0x92 [] __warn+0xc2/0xdd [] warn_slowpath_null+0x1d/0x1f [] try_to_wake_up+0x6c/0x4e4 [] ? lock_acquire+0x130/0x1c4 [] wake_up_process+0x15/0x17 [] wake_up_worker+0x28/0x2a [] insert_work+0xa5/0xb1 [] __queue_work+0x374/0x509 [] queue_work_on+0x3a/0x64 [] dbs_irq_work+0x24/0x27 [] irq_work_run_list+0x43/0x67 [] irq_work_run+0x2a/0x44 [] smp_irq_work_interrupt+0x2e/0x35 [] irq_work_interrupt+0x89/0x90 [] ? __do_softirq+0x96/0x434 [] ? __do_softirq+0x9f/0x434 [] irq_exit+0x40/0x90 [] smp_apic_timer_interrupt+0x42/0x4d [] apic_timer_interrupt+0x89/0x90 [] ? native_sched_clock+0x7/0xbc [] ? sched_clock_cpu+0x17/0xc6 [] running_clock+0x10/0x12 [] vprintk_emit+0x448/0x462 [] vprintk_default+0x1d/0x1f [] printk+0x48/0x50 [..] [] entry_SYSCALL_64_fastpath+0x18/0xad ---[ end trace ]--- Signed-off-by: Sergey Senozhatsky --- kernel/printk/printk.c | 27 ++++++++++++++++++++------- 1 file changed, 20 insertions(+), 7 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 2afa16b..e5dacfb 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1791,7 +1791,7 @@ asmlinkage int vprintk_emit(int facility, int level, zap_locks(); } - lockdep_off(); + alt_printk_enter(); /* This stops the holder of console_sem just where we want him */ raw_spin_lock(&logbuf_lock); logbuf_cpu = this_cpu; @@ -1900,12 +1900,11 @@ asmlinkage int vprintk_emit(int facility, int level, logbuf_cpu = UINT_MAX; raw_spin_unlock(&logbuf_lock); - lockdep_on(); + alt_printk_exit(); local_irq_restore(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 @@ -1913,7 +1912,6 @@ asmlinkage int vprintk_emit(int facility, int level, */ if (console_trylock()) console_unlock(); - lockdep_on(); } return printed_len; @@ -2239,8 +2237,18 @@ EXPORT_SYMBOL(console_lock); */ int console_trylock(void) { - if (down_trylock_console_sem()) + unsigned long flags; + int lock_failed; + + local_irq_save(flags); + alt_printk_enter(); + lock_failed = down_trylock_console_sem(); + alt_printk_exit(); + local_irq_restore(flags); + + if (lock_failed) return 0; + if (console_suspended) { up_console_sem(); return 0; @@ -2395,7 +2403,9 @@ void console_unlock(void) size_t len; int level; - raw_spin_lock_irqsave(&logbuf_lock, flags); + local_irq_save(flags); + alt_printk_enter(); + raw_spin_lock(&logbuf_lock); if (seen_seq != log_next_seq) { wake_klogd = true; seen_seq = log_next_seq; @@ -2456,6 +2466,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(); + alt_printk_exit(); local_irq_restore(flags); if (do_cond_resched) @@ -2479,7 +2490,9 @@ 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); + alt_printk_exit(); + local_irq_restore(flags); if (retry && console_trylock()) goto again; -- 2.10.0.372.g6fe1b14