[PATCH v6 0/2] Make printing of spin_dump() deferred to avoid a deadlock

[PATCH v6 0/2] Make printing of spin_dump() deferred to avoid a deadlock

[Byungchul Park]

changes from v5 to v6
- define the problem clearly and solve it by using irq work.

changes from v4 to v5
- found out a clear scenario which make a system crazy. at least it
  should not be caused by the debug code.

changes from v3 to v4
- reuse a existing code as much as possible for preventing an infinite
  recursive cycle.

changes from v2 to v3
- avoid printk() only in case of lockup suspected, not real lockup in
  which case it does not help at all.
- consider not only console_sem.lock but also logbuf_lock which is used
  by printk().

changes from v1 to v2
- only change comment and commit message esp. replacing "deadlock" with
  "infinite recursive cycle", since it is not an actual deadlock.

Thanks,
Byungchul

Byungchul Park (2):
  printk: Factor out buffering and irq work queuing in printk_deferred
  printk: Make printing of spin_dump() deferred to avoid a deadlock

 include/linux/printk.h          | 11 +++++++++++
 kernel/locking/spinlock_debug.c | 33 ++++++++++++++++++++++++++++++++-
 kernel/printk/printk.c          | 25 ++++++++++++++++++++++---
 3 files changed, 65 insertions(+), 4 deletions(-)

-- 
1.9.1

[PATCH v6 1/2] printk: Factor out buffering and irq work queuing in printk_deferred

[Byungchul Park]

printk_deferred() is a function for seperating between buffering a
message and deferring the actual printing. This patch factors out these
since these are also useful to others, where printk() cannot perform
the actual printing at the moment when printk() is called.

For example, spin_dump() must not perform the actual printing if
console_sem's spinlock has already been held at the moment. In that
case, spinlock debug system must do printk() without the actual printing,
otherwise a deadlock occures.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 include/linux/printk.h | 11 +++++++++++
 kernel/printk/printk.c | 17 ++++++++++++++---
 2 files changed, 25 insertions(+), 3 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 9729565..8a522d7 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -169,6 +169,8 @@ void __init setup_log_buf(int early);
 __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+int vprintk_deferred(const char *fmt, va_list args);
+void printk_pending_output(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -228,6 +230,15 @@ static inline void dump_stack_print_info(const char *log_lvl)
 static inline void show_regs_print_info(const char *log_lvl)
 {
 }
+
+static inline int vprintk_deferred(const char *fmt, va_list args)
+{
+	return 0;
+}
+
+static inline void printk_pending_output(void)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2ce8826..e82fae4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1867,6 +1867,11 @@ int vprintk_default(const char *fmt, va_list args)
 }
 EXPORT_SYMBOL_GPL(vprintk_default);
 
+int vprintk_deferred(const char *fmt, va_list args)
+{
+	return vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+}
+
 /*
  * This allows printk to be diverted to another function per cpu.
  * This is useful for calling printk functions from within NMI
@@ -2710,18 +2715,24 @@ void wake_up_klogd(void)
 	preempt_enable();
 }
 
+void printk_pending_output(void)
+{
+	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+}
+
 int printk_deferred(const char *fmt, ...)
 {
 	va_list args;
 	int r;
 
 	preempt_disable();
+
 	va_start(args, fmt);
-	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	r = vprintk_deferred(fmt, args);
 	va_end(args);
+	printk_pending_output();
 
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
-	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
 
 	return r;
-- 
1.9.1

Re: [PATCH v6 1/2] printk: Factor out buffering and irq work queuing in printk_deferred

[Sergey Senozhatsky]

Hello Byungchul,

Sorry, I'll make sure I Cc you next time. Jan Kara's updated patch set

http://marc.info/?l=linux-kernel&m=145787625506342

it's quite close to what you have done in this patch, but Jan's
patch also solves a number of more likely to happen cases.

have time to take a look?

the lock debug patch in your series is different. can we settle
down async printk first and then return to it? it's not so simple...


On (03/11/16 19:37), Byungchul Park wrote:
[..]
>  int printk_deferred(const char *fmt, ...)
>  {
>  	va_list args;
>  	int r;
>  
>  	preempt_disable();
> +
>  	va_start(args, fmt);
> -	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> +	r = vprintk_deferred(fmt, args);
>  	va_end(args);
> +	printk_pending_output();
>  
> -	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> -	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>  	preempt_enable();
>  
>  	return r;

vprintk_deferred() does vprintk_emit()->{spin_lock()} again? cosole_lock() is
moved out of sight, but logbug_lock is still there. wouldn't this (in the worst
case) result in endless loop after all? sorry if I'm missing something.

	-ss

Re: [PATCH v6 1/2] printk: Factor out buffering and irq work queuing in printk_deferred

[Byungchul Park]

On Mon, Mar 14, 2016 at 10:21:57AM +0900, Sergey Senozhatsky wrote:
> Hello Byungchul,
> 
> Sorry, I'll make sure I Cc you next time. Jan Kara's updated patch set
> 
> http://marc.info/?l=linux-kernel&m=145787625506342

Hello Sergey,

It would be appreciated if you or Jan Cc me from now.

> 
> it's quite close to what you have done in this patch, but Jan's
> patch also solves a number of more likely to happen cases.
> 
> have time to take a look?

I checked it now. I hope it will be accepted, then I can work mine based on
the Jan's patch.

> 
> the lock debug patch in your series is different. can we settle
> down async printk first and then return to it? it's not so simple...
> 
> 
> On (03/11/16 19:37), Byungchul Park wrote:
> [..]
> >  int printk_deferred(const char *fmt, ...)
> >  {
> >  	va_list args;
> >  	int r;
> >  
> >  	preempt_disable();
> > +
> >  	va_start(args, fmt);
> > -	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> > +	r = vprintk_deferred(fmt, args);
> >  	va_end(args);
> > +	printk_pending_output();
> >  
> > -	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> > -	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> >  	preempt_enable();
> >  
> >  	return r;
> 
> vprintk_deferred() does vprintk_emit()->{spin_lock()} again? cosole_lock() is
> moved out of sight, but logbug_lock is still there. wouldn't this (in the worst

We have to ensure the critical section by logbug_lock will not call
printk() or try to obtain the lock again. Current code works well in those
regards. logbuf_lock is not the thing we have to care when considering
the problem this patch deal with.

What do you think?

> case) result in endless loop after all? sorry if I'm missing something.

As long as we ensure it, the endless loop by logbuf_lock cannot happen.

> 
> 	-ss

[PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Byungchul Park]

In the case that console_sem.lock has already been held, printk() must
not be performed in normal way, otherwise a deadlock can happen because
it tries to acquire the console_sem.lock again, e.i. deadlock. This
patch defers the actual printing of printk(), using irq_work_queue().

The scenario the bad thing can happen is,

printk
  console_trylock
  console_unlock
    up_console_sem
      up
        raw_spin_lock_irqsave(&sem->lock, flags)
        __up
          wake_up_process
            try_to_wake_up
              raw_spin_lock_irqsave(&p->pi_lock)
                __spin_lock_debug
                  spin_dump
                    printk
                      console_trylock
                        raw_spin_lock_irqsave(&sem->lock, flags)
                        >>> DEADLOCK <<<

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 kernel/locking/spinlock_debug.c | 33 ++++++++++++++++++++++++++++++++-
 kernel/printk/printk.c          |  8 ++++++++
 2 files changed, 40 insertions(+), 1 deletion(-)

diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..fd24588 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -49,7 +49,7 @@ void __rwlock_init(rwlock_t *lock, const char *name,
 
 EXPORT_SYMBOL(__rwlock_init);
 
-static void spin_dump(raw_spinlock_t *lock, const char *msg)
+static void __spin_dump(raw_spinlock_t *lock, const char *msg)
 {
 	struct task_struct *owner = NULL;
 
@@ -67,6 +67,37 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 	dump_stack();
 }
 
+extern int console_sem_spin_is_held(void);
+
+static void __spin_dump_deferred(raw_spinlock_t *lock, const char *msg)
+{
+	printk_func_t s;
+
+	s = this_cpu_read(printk_func);
+	this_cpu_write(printk_func, vprintk_deferred);
+
+	/*
+	 * To change printk_func, it must be in preempt disabled and irq
+	 * disabled. WARN_ON() should be called after the change because
+	 * the default printk_func which may be called from WARN_ON()
+	 * is prohibited in this context.
+	 */
+	WARN_ON(!preempt_count() || !irqs_disabled());
+	__spin_dump(lock, msg);
+
+	this_cpu_write(printk_func, s);
+
+	printk_pending_output();
+}
+
+static void spin_dump(raw_spinlock_t *lock, const char *msg)
+{
+	if (unlikely(console_sem_spin_is_held()))
+		__spin_dump_deferred(lock, msg);
+	else
+		__spin_dump(lock, msg);
+}
+
 static void spin_bug(raw_spinlock_t *lock, const char *msg)
 {
 	if (!debug_locks_off())
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e82fae4..2e6b008 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2188,6 +2188,14 @@ int is_console_locked(void)
 	return console_locked;
 }
 
+#ifdef CONFIG_DEBUG_SPINLOCK
+int console_sem_spin_is_held(void)
+{
+	return raw_spin_is_locked(&console_sem.lock) &&
+			(console_sem.lock.owner == current);
+}
+#endif
+
 static void console_cont_flush(char *text, size_t size)
 {
 	unsigned long flags;
-- 
1.9.1

Re: [PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Sergey Senozhatsky]

On (03/11/16 19:37), Byungchul Park wrote:
[..]
> +static void __spin_dump_deferred(raw_spinlock_t *lock, const char *msg)
> +{
> +	printk_func_t s;
> +
> +	s = this_cpu_read(printk_func);
> +	this_cpu_write(printk_func, vprintk_deferred);
> +
> +	/*
> +	 * To change printk_func, it must be in preempt disabled and irq
> +	 * disabled. WARN_ON() should be called after the change because
> +	 * the default printk_func which may be called from WARN_ON()
> +	 * is prohibited in this context.
> +	 */
> +	WARN_ON(!preempt_count() || !irqs_disabled());
> +	__spin_dump(lock, msg);
> +
> +	this_cpu_write(printk_func, s);
> +
> +	printk_pending_output();
> +}
>
> +static void spin_dump(raw_spinlock_t *lock, const char *msg)
> +{
> +	if (unlikely(console_sem_spin_is_held()))
> +		__spin_dump_deferred(lock, msg);
> +	else
> +		__spin_dump(lock, msg);
> +}

so can it be

vprintk_emit()
 __spin_dump_deferred()
  vprintk_deferred()
   vprintk_emit()
    __spin_dump_deferred()
     vprintk_deferred()


or am I getting it wrong?

	-ss

Re: [PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Byungchul Park]

On Mon, Mar 14, 2016 at 10:37:52AM +0900, Sergey Senozhatsky wrote:
> On (03/11/16 19:37), Byungchul Park wrote:
> [..]
> > +static void __spin_dump_deferred(raw_spinlock_t *lock, const char *msg)
> > +{
> > +	printk_func_t s;
> > +
> > +	s = this_cpu_read(printk_func);
> > +	this_cpu_write(printk_func, vprintk_deferred);
> > +
> > +	/*
> > +	 * To change printk_func, it must be in preempt disabled and irq
> > +	 * disabled. WARN_ON() should be called after the change because
> > +	 * the default printk_func which may be called from WARN_ON()
> > +	 * is prohibited in this context.
> > +	 */
> > +	WARN_ON(!preempt_count() || !irqs_disabled());
> > +	__spin_dump(lock, msg);
> > +
> > +	this_cpu_write(printk_func, s);
> > +
> > +	printk_pending_output();
> > +}
> >
> > +static void spin_dump(raw_spinlock_t *lock, const char *msg)
> > +{
> > +	if (unlikely(console_sem_spin_is_held()))
> > +		__spin_dump_deferred(lock, msg);
> > +	else
> > +		__spin_dump(lock, msg);
> > +}

Hello, Sergey

> 
> so can it be
> 
> vprintk_emit()
>  __spin_dump_deferred()
>   vprintk_deferred()
>    vprintk_emit()
>     __spin_dump_deferred()
      ^^^
      can be caused by raw_spin_lock(logbug_lock)

>      vprintk_deferred()

Yes, it can happen by raw_spin_lock(logbuf_lock) to print warning or error
message. Are you worrying about an infinite recursion?

1. In the case printing warning, eventually it can fill the buffer without
actual printing using console.

2. In the case printing error, the infinite recursion can be prevented by
debug_locks_off().

Therefore, no problem.

> 
> 
> or am I getting it wrong?

Please let me know if you have any opinion. :-)

Thanks,
Byungchul

> 
> 	-ss

Re: [PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Sergey Senozhatsky]

Hi,

On (03/14/16 11:30), Byungchul Park wrote:
[..]
> > so can it be
> > 
> > vprintk_emit()
> >  __spin_dump_deferred()
> >   vprintk_deferred()
> >    vprintk_emit()
> >     __spin_dump_deferred()
>       ^^^
>       can be caused by raw_spin_lock(logbug_lock)
> 
> >      vprintk_deferred()
> 
> Yes, it can happen by raw_spin_lock(logbuf_lock) to print warning or error
> message. Are you worrying about an infinite recursion?

yes.

> 1. In the case printing warning, eventually it can fill the buffer without
> actual printing using console.

so the worry is that the CPU that spins on __spin_dump_deferred() has IRQs
disabled and `printk_pending' bit set; but IRQ may never be enabled on this
CPU.

> 2. In the case printing error, the infinite recursion can be prevented by
> debug_locks_off().
> 
> Therefore, no problem.

	-ss

Re: [PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Byungchul Park]

On Mon, Mar 14, 2016 at 11:40:55AM +0900, Sergey Senozhatsky wrote:
> Hi,
> 
> On (03/14/16 11:30), Byungchul Park wrote:
> [..]
> > > so can it be
> > > 
> > > vprintk_emit()
> > >  __spin_dump_deferred()
> > >   vprintk_deferred()
> > >    vprintk_emit()
> > >     __spin_dump_deferred()
> >       ^^^
> >       can be caused by raw_spin_lock(logbug_lock)
> > 
> > >      vprintk_deferred()
> > 
> > Yes, it can happen by raw_spin_lock(logbuf_lock) to print warning or error
> > message. Are you worrying about an infinite recursion?
> 
> yes.
> 
> > 1. In the case printing warning, eventually it can fill the buffer without
> > actual printing using console.
> 
> so the worry is that the CPU that spins on __spin_dump_deferred() has IRQs
> disabled and `printk_pending' bit set; but IRQ may never be enabled on this
> CPU.

It's true if another cpu never release the logbug_lock. But it's another
problem which current code already has and must be solved by another way.
IOW, the situation where the logbug_lock is not held yet is not the case
where we need to worry about whether the "IRQ work queue" works or not.

> 
> > 2. In the case printing error, the infinite recursion can be prevented by
> > debug_locks_off().
> > 
> > Therefore, no problem.
> 
> 	-ss

Re: [PATCH v6 2/2] printk: Make printing of spin_dump() deferred to avoid a deadlock

[Byungchul Park]

On Mon, Mar 14, 2016 at 01:17:48PM +0900, Byungchul Park wrote:
> On Mon, Mar 14, 2016 at 11:40:55AM +0900, Sergey Senozhatsky wrote:
> > Hi,
> > 
> > On (03/14/16 11:30), Byungchul Park wrote:
> > [..]
> > > > so can it be
> > > > 
> > > > vprintk_emit()
> > > >  __spin_dump_deferred()
> > > >   vprintk_deferred()
> > > >    vprintk_emit()
> > > >     __spin_dump_deferred()
> > >       ^^^
> > >       can be caused by raw_spin_lock(logbug_lock)
> > > 
> > > >      vprintk_deferred()
> > > 
> > > Yes, it can happen by raw_spin_lock(logbuf_lock) to print warning or error
> > > message. Are you worrying about an infinite recursion?
> > 
> > yes.
> > 
> > > 1. In the case printing warning, eventually it can fill the buffer without
> > > actual printing using console.
> > 
> > so the worry is that the CPU that spins on __spin_dump_deferred() has IRQs
> > disabled and `printk_pending' bit set; but IRQ may never be enabled on this
> > CPU.
> 
> It's true if another cpu never release the logbug_lock. But it's another
> problem which current code already has and must be solved by another way.
> IOW, the situation where the logbug_lock is not held yet is not the case
> where we need to worry about whether the "IRQ work queue" works or not.

To add more explanation,

1. If another cpu never release the logbug_lock, then the both current code
and patched code will suffer from an infinite recursive by vprintk_emit ->
spin_dump -> vprintk_emit -> ... It should be solved by another way if we
define this is a problem (even it's not a problem currently).

2. If another cpu eventually release the logbug_lock, then the both current
code and patched code can obtain the lock and get out of the recursive. And
the "IRQ work queue" can work when the irq is finally enabled. That's no
problem. This is what I wanted to say.

> 
> > 
> > > 2. In the case printing error, the infinite recursion can be prevented by
> > > debug_locks_off().
> > > 
> > > Therefore, no problem.
> > 
> > 	-ss

[PATCH] lib/spinlock_debug: Prevent a unnecessary recursive spin_dump()

[Byungchul Park]

This can protect an infinit recursion by unnecessary warning, too.

-----8<-----
>From 81f06a6f9c7f2e782267a2539c6c869d4214354c Mon Sep 17 00:00:00 2001
From: Byungchul Park <byungchul.park@lge.com>
Date: Fri, 18 Mar 2016 11:35:24 +0900
Subject: [PATCH] lib/spinlock_debug: Prevent a unnecessary recursive
 spin_dump()

Printing "lockup suspected" for the same lock more than once is
meaningless. Furtheremore, it can cause an infinite recursion if it's
on the way printing something by printk().

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 kernel/locking/spinlock_debug.c | 15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index fd24588..30559c6 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -138,14 +138,25 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
 {
 	u64 i;
 	u64 loops = loops_per_jiffy * HZ;
+	static raw_spinlock_t *suspected_lock = NULL;
 
 	for (i = 0; i < loops; i++) {
 		if (arch_spin_trylock(&lock->raw_lock))
 			return;
 		__delay(1);
 	}
-	/* lockup suspected: */
-	spin_dump(lock, "lockup suspected");
+
+	/*
+	 * When we suspect a lockup, it's good enough to inform it once for
+	 * the same lock. Otherwise it could cause an infinite recursion if
+	 * it's within printk().
+	 */
+	if (suspected_lock != lock) {
+		suspected_lock = lock;
+		/* lockup suspected: */
+		spin_dump(lock, "lockup suspected");
+		suspected_lock = NULL;
+	}
 #ifdef CONFIG_SMP
 	trigger_all_cpu_backtrace();
 #endif
-- 
1.9.1