Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-12 Thread Sergey Senozhatsky 
On (12/12/16 17:30), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:45, Sergey Senozhatsky wrote:
> > 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.
> > 
> > Signed-off-by: Sergey Senozhatsky 
> 
> Looks fine and safe to me.
> 
> Reviewed-by: Petr Mladek 

thanks.

-ss

Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-12 Thread Sergey Senozhatsky 
On (12/12/16 17:30), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:45, Sergey Senozhatsky wrote:
> > 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.
> > 
> > Signed-off-by: Sergey Senozhatsky 
> 
> Looks fine and safe to me.
> 
> Reviewed-by: Petr Mladek 

thanks.

-ss

Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-12 Thread Petr Mladek 
On Thu 2016-12-01 22:55:45, Sergey Senozhatsky wrote:
> 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.
> 
> Signed-off-by: Sergey Senozhatsky 

Looks fine and safe to me.

Reviewed-by: Petr Mladek 

Best Regards,
Petr

Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-12 Thread Petr Mladek 
On Thu 2016-12-01 22:55:45, Sergey Senozhatsky wrote:
> 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.
> 
> Signed-off-by: Sergey Senozhatsky 

Looks fine and safe to me.

Reviewed-by: Petr Mladek 

Best Regards,
Petr

[RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-01 Thread Sergey Senozhatsky 
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(_lock);
WARN_ON(1);
raw_spin_unlock(_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(>lock, flags);
WARN_ON(1);
raw_spin_unlock_irqrestore(>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(_lock);
  WARN_ON(1);
  raw_spin_unlock(_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(>pi_lock, flags);
  WARN_ON(1);
  raw_spin_unlock_irqrestore(>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 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(_sem))
+   int lock_failed;
+   unsigned long flags;
+
+   printk_safe_enter(flags);
+   lock_failed = down_trylock(_sem);
+   printk_safe_exit(flags);
+
+   if (lock_failed)
return 1;
mutex_acquire(_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(_lock_dep_map, 1, _RET_IP_);\
-   up(_sem);\
-} while (0)
+static void __up_console_sem(unsigned long ip)
+{

[RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

2016-12-01 Thread Sergey Senozhatsky 
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(_lock);
WARN_ON(1);
raw_spin_unlock(_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(>lock, flags);
WARN_ON(1);
raw_spin_unlock_irqrestore(>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(_lock);
  WARN_ON(1);
  raw_spin_unlock(_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(>pi_lock, flags);
  WARN_ON(1);
  raw_spin_unlock_irqrestore(>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 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(_sem))
+   int lock_failed;
+   unsigned long flags;
+
+   printk_safe_enter(flags);
+   lock_failed = down_trylock(_sem);
+   printk_safe_exit(flags);
+
+   if (lock_failed)
return 1;
mutex_acquire(_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(_lock_dep_map, 1, _RET_IP_);\
-   up(_sem);\
-} while (0)
+static void __up_console_sem(unsigned long ip)
+{
+   unsigned long flags;
+