p71924506
/
linux_old1
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

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>
This commit is contained in:
Sergey Senozhatsky 2016-12-27 23:16:09 +09:00 committed by Petr Mladek
parent ddb9baa822
commit f975237b76
1 changed files with 32 additions and 15 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

47
kernel/printk/printk.c
View File

@ -213,17 +213,36 @@ static int nr_ext_console_drivers;
static int __down_trylock_console_sem(unsigned long ip) 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; return 1;
mutex_acquire(&console_lock_dep_map, 0, 1, ip); mutex_acquire(&console_lock_dep_map, 0, 1, ip);
return 0; return 0;
} }
#define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_) #define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)
#define up_console_sem() do { \ static void __up_console_sem(unsigned long ip)
mutex_release(&console_lock_dep_map, 1, _RET_IP_);\ {
up(&console_sem);\ unsigned long flags;
} while (0)
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 * 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); boot_delay_msec(level);
printk_delay(); printk_delay();
local_irq_save(flags); printk_safe_enter_irqsave(flags);
this_cpu = smp_processor_id(); this_cpu = smp_processor_id();
/* /*
@ -1705,13 +1724,12 @@ asmlinkage int vprintk_emit(int facility, int level,
*/ */
if (!oops_in_progress && !lockdep_recursing(current)) { if (!oops_in_progress && !lockdep_recursing(current)) {
recursion_bug = true; recursion_bug = true;
local_irq_restore(flags); printk_safe_exit_irqrestore(flags);
return 0; return 0;
} }
zap_locks(); zap_locks();
} }
lockdep_off();
/* This stops the holder of console_sem just where we want him */ /* This stops the holder of console_sem just where we want him */
raw_spin_lock(&logbuf_lock); raw_spin_lock(&logbuf_lock);
logbuf_cpu = this_cpu; logbuf_cpu = this_cpu;
@ -1771,12 +1789,10 @@ asmlinkage int vprintk_emit(int facility, int level,
logbuf_cpu = UINT_MAX; logbuf_cpu = UINT_MAX;
raw_spin_unlock(&logbuf_lock); raw_spin_unlock(&logbuf_lock);
lockdep_on(); printk_safe_exit_irqrestore(flags);
local_irq_restore(flags);
/* If called from the scheduler, we can not call up(). */ /* If called from the scheduler, we can not call up(). */
if (!in_sched) { if (!in_sched) {
lockdep_off();
/* /*
* Try to acquire and then immediately release the console * Try to acquire and then immediately release the console
* semaphore. The release will print out buffers and wake up * 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()) if (console_trylock())
console_unlock(); console_unlock();
lockdep_on();
} }
return printed_len; return printed_len;
@ -2209,7 +2224,8 @@ void console_unlock(void)
size_t len; size_t len;
int level; 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) { if (seen_seq != log_next_seq) {
wake_klogd = true; wake_klogd = true;
seen_seq = log_next_seq; seen_seq = log_next_seq;
@ -2259,7 +2275,7 @@ void console_unlock(void)
stop_critical_timings(); /* don't trace print latency */ stop_critical_timings(); /* don't trace print latency */
call_console_drivers(level, ext_text, ext_len, text, len); call_console_drivers(level, ext_text, ext_len, text, len);
start_critical_timings(); start_critical_timings();
local_irq_restore(flags); printk_safe_exit_irqrestore(flags);
if (do_cond_resched) if (do_cond_resched)
cond_resched(); cond_resched();
@ -2282,7 +2298,8 @@ void console_unlock(void)
*/ */
raw_spin_lock(&logbuf_lock); raw_spin_lock(&logbuf_lock);
retry = console_seq != log_next_seq; 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()) if (retry && console_trylock())
goto again; goto again;