[PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

changes form 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

-----8<-----
>From 7b0c6e48625632fa1732b619083dc550b5d924c6 Mon Sep 17 00:00:00 2001
From: Byungchul Park <byungchul.park@lge.com>
Date: Wed, 27 Jan 2016 18:11:55 +0900
Subject: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the
 debug code

It causes an infinite recursive cycle when using CONFIG_DEBUG_SPINLOCK,
in the spin_dump(). Backtrace prints printk() -> console_trylock() ->
do_raw_spin_lock() -> spin_dump() -> printk()... infinitely.

When the debug spinlock code is called from printk(), we should prevent
calling spin_dump() and the like, calling printk() again in that context.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 include/linux/debug_locks.h     |  4 ++++
 kernel/locking/spinlock_debug.c | 14 +++++++++++---
 2 files changed, 15 insertions(+), 3 deletions(-)

diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
index 822c135..b0f977e 100644
--- a/include/linux/debug_locks.h
+++ b/include/linux/debug_locks.h
@@ -10,6 +10,10 @@ struct task_struct;
 extern int debug_locks;
 extern int debug_locks_silent;
 
+static inline void __debug_locks_on(void)
+{
+	debug_locks = 1;
+}
 
 static inline int __debug_locks_off(void)
 {
diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..65177ba 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
 			return;
 		__delay(1);
 	}
-	/* lockup suspected: */
-	spin_dump(lock, "lockup suspected");
+
+	/*
+	 * We should prevent calling printk() further, since it would cause
+	 * an infinite recursive cycle if it's called from printk()!
+	 */
+	if (__debug_locks_off()) {
+		/* lockup suspected: */
+		spin_dump(lock, "lockup suspected");
 #ifdef CONFIG_SMP
-	trigger_all_cpu_backtrace();
+		trigger_all_cpu_backtrace();
 #endif
+		__debug_locks_on();
+	}
 
 	/*
 	 * The trylock above was causing a livelock.  Give the lower level arch
-- 
1.9.1

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Peter Hurley]

On 01/27/2016 04:01 AM, Byungchul Park wrote:
> changes form 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
> 
> -----8<-----
> From 7b0c6e48625632fa1732b619083dc550b5d924c6 Mon Sep 17 00:00:00 2001
> From: Byungchul Park <byungchul.park@lge.com>
> Date: Wed, 27 Jan 2016 18:11:55 +0900
> Subject: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the
>  debug code
> 
> It causes an infinite recursive cycle when using CONFIG_DEBUG_SPINLOCK,
> in the spin_dump(). Backtrace prints printk() -> console_trylock() ->
> do_raw_spin_lock() -> spin_dump() -> printk()... infinitely.

printk() is potentially recursive in many situations.
What about spinlocks used by console drivers?

And we already have lockdep turned off to avoid triggering a recursive
lockdep report (which I think is a mistake).

I think we should be working toward properly handling recursion
in printk().

Regards,
Peter Hurley


> When the debug spinlock code is called from printk(), we should prevent
> calling spin_dump() and the like, calling printk() again in that context.
> 
> Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> ---
>  include/linux/debug_locks.h     |  4 ++++
>  kernel/locking/spinlock_debug.c | 14 +++++++++++---
>  2 files changed, 15 insertions(+), 3 deletions(-)
> 
> diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> index 822c135..b0f977e 100644
> --- a/include/linux/debug_locks.h
> +++ b/include/linux/debug_locks.h
> @@ -10,6 +10,10 @@ struct task_struct;
>  extern int debug_locks;
>  extern int debug_locks_silent;
>  
> +static inline void __debug_locks_on(void)
> +{
> +	debug_locks = 1;
> +}
>  
>  static inline int __debug_locks_off(void)
>  {
> diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
> index 0374a59..65177ba 100644
> --- a/kernel/locking/spinlock_debug.c
> +++ b/kernel/locking/spinlock_debug.c
> @@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
>  			return;
>  		__delay(1);
>  	}
> -	/* lockup suspected: */
> -	spin_dump(lock, "lockup suspected");
> +
> +	/*
> +	 * We should prevent calling printk() further, since it would cause
> +	 * an infinite recursive cycle if it's called from printk()!
> +	 */
> +	if (__debug_locks_off()) {
> +		/* lockup suspected: */
> +		spin_dump(lock, "lockup suspected");
>  #ifdef CONFIG_SMP
> -	trigger_all_cpu_backtrace();
> +		trigger_all_cpu_backtrace();
>  #endif
> +		__debug_locks_on();
> +	}
>  
>  	/*
>  	 * The trylock above was causing a livelock.  Give the lower level arch
> 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

+cc peter@hurleysoftware.com
+cc sergey.senozhatsky.work@gmail.com

On Wed, Jan 27, 2016 at 09:01:01PM +0900, Byungchul Park wrote:
> changes form 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
> 
> -----8<-----
> >From 7b0c6e48625632fa1732b619083dc550b5d924c6 Mon Sep 17 00:00:00 2001
> From: Byungchul Park <byungchul.park@lge.com>
> Date: Wed, 27 Jan 2016 18:11:55 +0900
> Subject: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the
>  debug code
> 
> It causes an infinite recursive cycle when using CONFIG_DEBUG_SPINLOCK,
> in the spin_dump(). Backtrace prints printk() -> console_trylock() ->
> do_raw_spin_lock() -> spin_dump() -> printk()... infinitely.
> 
> When the debug spinlock code is called from printk(), we should prevent
> calling spin_dump() and the like, calling printk() again in that context.
> 
> Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> ---
>  include/linux/debug_locks.h     |  4 ++++
>  kernel/locking/spinlock_debug.c | 14 +++++++++++---
>  2 files changed, 15 insertions(+), 3 deletions(-)
> 
> diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> index 822c135..b0f977e 100644
> --- a/include/linux/debug_locks.h
> +++ b/include/linux/debug_locks.h
> @@ -10,6 +10,10 @@ struct task_struct;
>  extern int debug_locks;
>  extern int debug_locks_silent;
>  
> +static inline void __debug_locks_on(void)
> +{
> +	debug_locks = 1;
> +}
>  
>  static inline int __debug_locks_off(void)
>  {
> diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
> index 0374a59..65177ba 100644
> --- a/kernel/locking/spinlock_debug.c
> +++ b/kernel/locking/spinlock_debug.c
> @@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
>  			return;
>  		__delay(1);
>  	}
> -	/* lockup suspected: */
> -	spin_dump(lock, "lockup suspected");
> +
> +	/*
> +	 * We should prevent calling printk() further, since it would cause
> +	 * an infinite recursive cycle if it's called from printk()!
> +	 */
> +	if (__debug_locks_off()) {
> +		/* lockup suspected: */
> +		spin_dump(lock, "lockup suspected");
>  #ifdef CONFIG_SMP
> -	trigger_all_cpu_backtrace();
> +		trigger_all_cpu_backtrace();
>  #endif
> +		__debug_locks_on();
> +	}
>  
>  	/*
>  	 * The trylock above was causing a livelock.  Give the lower level arch
> -- 
> 1.9.1

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

Hello,

On (01/28/16 10:42), Byungchul Park wrote:
> +cc peter@hurleysoftware.com
> +cc sergey.senozhatsky.work@gmail.com

thanks for Cc-ing.

> On Wed, Jan 27, 2016 at 09:01:01PM +0900, Byungchul Park wrote:
> > changes form 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.

[..]
> > It causes an infinite recursive cycle when using CONFIG_DEBUG_SPINLOCK,
> > in the spin_dump(). Backtrace prints printk() -> console_trylock() ->
> > do_raw_spin_lock() -> spin_dump() -> printk()... infinitely.
> > 
> > When the debug spinlock code is called from printk(), we should prevent
> > calling spin_dump() and the like, calling printk() again in that context.


ok, I'll repeat the questions.

under what circumstances you hit this problem? ...memory corruption, cpu
core has been powered off, while it owned the spin_lock... your irqsave
didn't work?

the thing is, it's really-really hard to lockup in console_trylock()...

int down_trylock(struct semaphore *sem)
{
        unsigned long flags;
        int count;

        raw_spin_lock_irqsave(&sem->lock, flags);   <<<<<<  um...
        count = sem->count - 1;
        if (likely(count >= 0))
                sem->count = count;
        raw_spin_unlock_irqrestore(&sem->lock, flags);

        return (count < 0);
}

was not able to dereference sem->count? `*sem' was corrupted? or because
sem->lock was corrupted? in any of those cases you solve the problem from
the wrong side. if you have a memory corruption then it can corrupt anything,
including, for example, console driver spin_lock.


suppose, that you hit do_raw_spin_lock()->spin_dump(), which means that the
spin_lock was not corrupted, it passed debug_spin_lock_before() after all.
and that spin_lock was taken for longer than `loops_per_jiffy * HZ', while
other CPU was doing

        count = sem->count - 1;
        if (likely(count >= 0))
                sem->count = count;

???

was the CPU that owned the lock alive? (h/w fault, perhaps?).


dunno... yes, this
	printk()->console_trylock()->do_raw_spin_lock()->spin_dump()->printk()
is possible, but it's possible only when your system is screwed up badly, so
badly that this spin_dump() loop is not really a problem, IMHO.

if I'm missing something terribly obvious here, then please give more details.

	-ss

> > Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> > ---
> >  include/linux/debug_locks.h     |  4 ++++
> >  kernel/locking/spinlock_debug.c | 14 +++++++++++---
> >  2 files changed, 15 insertions(+), 3 deletions(-)
> > 
> > diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> > index 822c135..b0f977e 100644
> > --- a/include/linux/debug_locks.h
> > +++ b/include/linux/debug_locks.h
> > @@ -10,6 +10,10 @@ struct task_struct;
> >  extern int debug_locks;
> >  extern int debug_locks_silent;
> >  
> > +static inline void __debug_locks_on(void)
> > +{
> > +	debug_locks = 1;
> > +}
> >  
> >  static inline int __debug_locks_off(void)
> >  {
> > diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
> > index 0374a59..65177ba 100644
> > --- a/kernel/locking/spinlock_debug.c
> > +++ b/kernel/locking/spinlock_debug.c
> > @@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
> >  			return;
> >  		__delay(1);
> >  	}
> > -	/* lockup suspected: */
> > -	spin_dump(lock, "lockup suspected");
> > +
> > +	/*
> > +	 * We should prevent calling printk() further, since it would cause
> > +	 * an infinite recursive cycle if it's called from printk()!
> > +	 */
> > +	if (__debug_locks_off()) {
> > +		/* lockup suspected: */
> > +		spin_dump(lock, "lockup suspected");
> >  #ifdef CONFIG_SMP
> > -	trigger_all_cpu_backtrace();
> > +		trigger_all_cpu_backtrace();
> >  #endif
> > +		__debug_locks_on();
> > +	}
> >  
> >  	/*
> >  	 * The trylock above was causing a livelock.  Give the lower level arch
> > -- 
> > 1.9.1
> 

RE: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[byungchul.park]

> From: Sergey Senozhatsky [mailto:sergey.senozhatsky.work@gmail.com]
> Sent: Thursday, January 28, 2016 11:38 AM
> To: Byungchul Park
> Cc: akpm@linux-foundation.org; mingo@kernel.org; linux-
> kernel@vger.kernel.org; akinobu.mita@gmail.com; jack@suse.cz;
> torvalds@linux-foundation.org; peter@hurleysoftware.com;
> sergey.senozhatsky.work@gmail.com; sergey.senozhatsky@gmail.com
> Subject: Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in
> the debug code
> 
> ok, I'll repeat the questions.
> 
> under what circumstances you hit this problem? ...memory corruption, cpu
> core has been powered off, while it owned the spin_lock... your irqsave
> didn't work?

I think these are not the my case.

> 
> the thing is, it's really-really hard to lockup in console_trylock()...
> 
> int down_trylock(struct semaphore *sem)
> {
>         unsigned long flags;
>         int count;
> 
>         raw_spin_lock_irqsave(&sem->lock, flags);   <<<<<<  um...

I also think it's hard, but a backtrace said the lockup happened here.

>         count = sem->count - 1;
>         if (likely(count >= 0))
>                 sem->count = count;
>         raw_spin_unlock_irqrestore(&sem->lock, flags);
> 
>         return (count < 0);
> }
> 
> was not able to dereference sem->count? `*sem' was corrupted? or because
> sem->lock was corrupted? in any of those cases you solve the problem from
> the wrong side. if you have a memory corruption then it can corrupt

What I solved here is to make it possible to print what the problem is, by
the spinlock debug code instead of system lockup while printing a debug
message. I think it's not wrong.

> anything,
> including, for example, console driver spin_lock.
> 
> 
> suppose, that you hit do_raw_spin_lock()->spin_dump(), which means that
> the
> spin_lock was not corrupted, it passed debug_spin_lock_before() after all.
> and that spin_lock was taken for longer than `loops_per_jiffy * HZ', while
> other CPU was doing
> 
>         count = sem->count - 1;
>         if (likely(count >= 0))
>                 sem->count = count;
> 
> ???
> 
> was the CPU that owned the lock alive? (h/w fault, perhaps?).

I am just curious.. Is it impossible but by h/w fault? e.g. timing to
allocate
virtual cpus to a guest machine when using virtual machine and so on.

> 
> 
> dunno... yes, this
> 	printk()->console_trylock()->do_raw_spin_lock()->spin_dump()-
> >printk()
> is possible, but it's possible only when your system is screwed up badly,
> so
> badly that this spin_dump() loop is not really a problem, IMHO.

IMHO, even though a system is screwed up badly, the spinlock debug code have
to print the information about the problem without lockup.

> 
> if I'm missing something terribly obvious here, then please give more
> details.

There are already codes to prevent the recursive cycle in the bug case,
but not for the just suspected case. I just made it possible for the
latter case. That's all this patch is doing, now. :)

thanks,
byungchul

> 
> 	-ss
> 
> > > Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> > > ---
> > >  include/linux/debug_locks.h     |  4 ++++
> > >  kernel/locking/spinlock_debug.c | 14 +++++++++++---
> > >  2 files changed, 15 insertions(+), 3 deletions(-)
> > >
> > > diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> > > index 822c135..b0f977e 100644
> > > --- a/include/linux/debug_locks.h
> > > +++ b/include/linux/debug_locks.h
> > > @@ -10,6 +10,10 @@ struct task_struct;
> > >  extern int debug_locks;
> > >  extern int debug_locks_silent;
> > >
> > > +static inline void __debug_locks_on(void)
> > > +{
> > > +	debug_locks = 1;
> > > +}
> > >
> > >  static inline int __debug_locks_off(void)
> > >  {
> > > diff --git a/kernel/locking/spinlock_debug.c
> b/kernel/locking/spinlock_debug.c
> > > index 0374a59..65177ba 100644
> > > --- a/kernel/locking/spinlock_debug.c
> > > +++ b/kernel/locking/spinlock_debug.c
> > > @@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t
> *lock)
> > >  			return;
> > >  		__delay(1);
> > >  	}
> > > -	/* lockup suspected: */
> > > -	spin_dump(lock, "lockup suspected");
> > > +
> > > +	/*
> > > +	 * We should prevent calling printk() further, since it would cause
> > > +	 * an infinite recursive cycle if it's called from printk()!
> > > +	 */
> > > +	if (__debug_locks_off()) {
> > > +		/* lockup suspected: */
> > > +		spin_dump(lock, "lockup suspected");
> > >  #ifdef CONFIG_SMP
> > > -	trigger_all_cpu_backtrace();
> > > +		trigger_all_cpu_backtrace();
> > >  #endif
> > > +		__debug_locks_on();
> > > +	}
> > >
> > >  	/*
> > >  	 * The trylock above was causing a livelock.  Give the lower level
> arch
> > > --
> > > 1.9.1
> >

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 13:36), byungchul.park wrote:
[..]
> > the thing is, it's really-really hard to lockup in console_trylock()...
> > 
> > int down_trylock(struct semaphore *sem)
> > {
> >         unsigned long flags;
> >         int count;
> > 
> >         raw_spin_lock_irqsave(&sem->lock, flags);   <<<<<<  um...
> 
> I also think it's hard, but a backtrace said the lockup happened here.

what was the state of `struct semaphore *sem' and especially of `sem->lock'?
what was the lock->owner_cpu doing? (addr2line of its pc registe, for example).


> >         count = sem->count - 1;
> >         if (likely(count >= 0))
> >                 sem->count = count;
> >         raw_spin_unlock_irqrestore(&sem->lock, flags);
> > 
> >         return (count < 0);
> > }
> > 
> > was not able to dereference sem->count? `*sem' was corrupted? or because
> > sem->lock was corrupted? in any of those cases you solve the problem from
> > the wrong side. if you have a memory corruption then it can corrupt
> 
> What I solved here is to make it possible to print what the problem is, by
> the spinlock debug code instead of system lockup while printing a debug
> message. I think it's not wrong.

none of the CPUs will print anything anymore. it's done.


your CPUa - CPUx are spinning in down_trylock()

	vprintk_emit()
		down_trylock()
			raw_spin_lock_irqsave()   << spin here

and they are spinnig because CPUz is keeping the sem->lock and is
_not_ going to release it. and this is the root cause, not spin_dump().


CPUz was expected to do a quick thing in down_trylock()

	raw_spin_lock_irqsave(&sem->lock, flags);
	count = sem->count - 1;
	if (likely(count >= 0))
		sem->count = count;
	raw_spin_unlock_irqrestore(&sem->lock, flags);


or down()/down_common()


	raw_spin_lock_irqsave(&sem->lock, flags);
	if (likely(sem->count > 0))
		sem->count--;
	else
		down_common()
		{
			...
			for (;;) {
				if (signal_pending_state(state, task))
					goto interrupted;
				if (unlikely(timeout <= 0))
					goto timed_out;
				__set_task_state(task, state);
				raw_spin_unlock_irq(&sem->lock);
				timeout = schedule_timeout(timeout);
				raw_spin_lock_irq(&sem->lock);
				if (waiter.up)
					return 0;
			}
			...
		}
	raw_spin_unlock_irqrestore(&sem->lock, flags);


I can't see how it's even possible to keep that spin_lock locked
longer than `loops_per_jiffy * HZ'.

and the fact that you saw N recursive
   printk()->down_trylock()->spin_lock()->spin_dump()->printk()->...

sounds like a good prove of the fact the your CPUz was either dead,
or gone crazy, and took the spin_lock with it. but this is not
spinlock_debug's business.


console_flush_on_panic() _probably_ would help in this particular
case -- it does not care about console_sem state and goes to
console_unlock() directly -- but it still locks the logbuf_lock.
so if CPUz died with logbuf_lock being locked, then nothing will
save your day.


do you have any reproducer or you've seen it once?

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Wed, Jan 27, 2016 at 02:49:35PM -0800, Peter Hurley wrote:
> And we already have lockdep turned off to avoid triggering a recursive
> lockdep report (which I think is a mistake).

Yes, we already have a way to turn off the lock debug so that we can
avoid it. So I used it in v4.

thanks,
byungchul

> 
> I think we should be working toward properly handling recursion
> in printk().
> 
> Regards,
> Peter Hurley
> 
> 
> > When the debug spinlock code is called from printk(), we should prevent
> > calling spin_dump() and the like, calling printk() again in that context.
> > 
> > Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> > ---
> >  include/linux/debug_locks.h     |  4 ++++
> >  kernel/locking/spinlock_debug.c | 14 +++++++++++---
> >  2 files changed, 15 insertions(+), 3 deletions(-)
> > 
> > diff --git a/include/linux/debug_locks.h b/include/linux/debug_locks.h
> > index 822c135..b0f977e 100644
> > --- a/include/linux/debug_locks.h
> > +++ b/include/linux/debug_locks.h
> > @@ -10,6 +10,10 @@ struct task_struct;
> >  extern int debug_locks;
> >  extern int debug_locks_silent;
> >  
> > +static inline void __debug_locks_on(void)
> > +{
> > +	debug_locks = 1;
> > +}
> >  
> >  static inline int __debug_locks_off(void)
> >  {
> > diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
> > index 0374a59..65177ba 100644
> > --- a/kernel/locking/spinlock_debug.c
> > +++ b/kernel/locking/spinlock_debug.c
> > @@ -113,11 +113,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
> >  			return;
> >  		__delay(1);
> >  	}
> > -	/* lockup suspected: */
> > -	spin_dump(lock, "lockup suspected");
> > +
> > +	/*
> > +	 * We should prevent calling printk() further, since it would cause
> > +	 * an infinite recursive cycle if it's called from printk()!
> > +	 */
> > +	if (__debug_locks_off()) {
> > +		/* lockup suspected: */
> > +		spin_dump(lock, "lockup suspected");
> >  #ifdef CONFIG_SMP
> > -	trigger_all_cpu_backtrace();
> > +		trigger_all_cpu_backtrace();
> >  #endif
> > +		__debug_locks_on();
> > +	}
> >  
> >  	/*
> >  	 * The trylock above was causing a livelock.  Give the lower level arch
> > 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Thu, Jan 28, 2016 at 03:05:30PM +0900, Sergey Senozhatsky wrote:
> On (01/28/16 13:36), byungchul.park wrote:
> [..]
> > > the thing is, it's really-really hard to lockup in console_trylock()...
> > > 
> > > int down_trylock(struct semaphore *sem)
> > > {
> > >         unsigned long flags;
> > >         int count;
> > > 
> > >         raw_spin_lock_irqsave(&sem->lock, flags);   <<<<<<  um...
> > 
> > I also think it's hard, but a backtrace said the lockup happened here.
> 
> what was the state of `struct semaphore *sem' and especially of `sem->lock'?
> what was the lock->owner_cpu doing? (addr2line of its pc registe, for example).

Unfortunately, it's not reproduced anymore.

If it's clearly a spinlock caller's bug as you said, modifying the
spinlock debug code does not help it at all. But I found there's a
possiblity in the debug code *itself* to cause a lockup. So I tried
to fix it. What do you think about it?

> 
> > >         count = sem->count - 1;
> > >         if (likely(count >= 0))
> > >                 sem->count = count;
> > >         raw_spin_unlock_irqrestore(&sem->lock, flags);
> > > 
> > >         return (count < 0);
> > > }
> > > 
> > > was not able to dereference sem->count? `*sem' was corrupted? or because
> > > sem->lock was corrupted? in any of those cases you solve the problem from
> > > the wrong side. if you have a memory corruption then it can corrupt
> > 
> > What I solved here is to make it possible to print what the problem is, by
> > the spinlock debug code instead of system lockup while printing a debug
> > message. I think it's not wrong.
> 
> none of the CPUs will print anything anymore. it's done.

You are right if it's a real lockup situation. But it will print proper
debug messages if it's just a suspect case, which works with this patch.

I will also try to reproduce it and check if there's a bug on use of
spinlock. In this case, we should fix the root cause. But since the
possiblity I mentioned can *also* cause the lockup problem, I think it
must be fixed at first.

> 
> 
> your CPUa - CPUx are spinning in down_trylock()
> 
> 	vprintk_emit()
> 		down_trylock()
> 			raw_spin_lock_irqsave()   << spin here
> 
> and they are spinnig because CPUz is keeping the sem->lock and is
> _not_ going to release it. and this is the root cause, not spin_dump().

If it's not going to release it then it's a problem. But IMHO,
arch_spin_trylock() in __spin_lock_debug() can fail even though the owner
of the spinlock releases it properly, if there's heavy use on printk() at
the moment. Is there something I missed here? If what I mention can happen,
then it's not a spinlock user's problem. It's just a debug code's problem.

> 
> 
> CPUz was expected to do a quick thing in down_trylock()
> 
> 	raw_spin_lock_irqsave(&sem->lock, flags);
> 	count = sem->count - 1;
> 	if (likely(count >= 0))
> 		sem->count = count;
> 	raw_spin_unlock_irqrestore(&sem->lock, flags);

This may be done quickly, but if the use of printk() on the system is
heavy?

> 
> 
> or down()/down_common()
> 
> 
> 	raw_spin_lock_irqsave(&sem->lock, flags);
> 	if (likely(sem->count > 0))
> 		sem->count--;
> 	else
> 		down_common()
> 		{
> 			...
> 			for (;;) {
> 				if (signal_pending_state(state, task))
> 					goto interrupted;
> 				if (unlikely(timeout <= 0))
> 					goto timed_out;
> 				__set_task_state(task, state);
> 				raw_spin_unlock_irq(&sem->lock);
> 				timeout = schedule_timeout(timeout);
> 				raw_spin_lock_irq(&sem->lock);
> 				if (waiter.up)
> 					return 0;
> 			}
> 			...
> 		}
> 	raw_spin_unlock_irqrestore(&sem->lock, flags);
> 
> 
> I can't see how it's even possible to keep that spin_lock locked
> longer than `loops_per_jiffy * HZ'.

No need to keep that spinlock longer than it to cause the problem..

> 
> and the fact that you saw N recursive
>    printk()->down_trylock()->spin_lock()->spin_dump()->printk()->...
> 
> sounds like a good prove of the fact the your CPUz was either dead,
> or gone crazy, and took the spin_lock with it. but this is not

My system esp. qemu might have been crazy because printk() business.

> spinlock_debug's business.

I think it could be exactly a spinlock debug's business.

> 
> console_flush_on_panic() _probably_ would help in this particular
> case -- it does not care about console_sem state and goes to
> console_unlock() directly -- but it still locks the logbuf_lock.
> so if CPUz died with logbuf_lock being locked, then nothing will
> save your day.
> 
> 
> do you have any reproducer or you've seen it once?

Just once.

thanks,
byungchul

> 
> 	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 17:13), Byungchul Park wrote:
[..]
> > > > int down_trylock(struct semaphore *sem)
> > > > {
> > > >         unsigned long flags;
> > > >         int count;
> > > > 
> > > >         raw_spin_lock_irqsave(&sem->lock, flags);   <<<<<<  um...
> > > 
> > > I also think it's hard, but a backtrace said the lockup happened here.
> > 
> > what was the state of `struct semaphore *sem' and especially of `sem->lock'?
> > what was the lock->owner_cpu doing? (addr2line of its pc registe, for example).
> 
> Unfortunately, it's not reproduced anymore.
> 
> If it's clearly a spinlock caller's bug as you said, modifying the
> spinlock debug code does not help it at all. But I found there's a
> possiblity in the debug code *itself* to cause a lockup. So I tried
> to fix it. What do you think about it?

ah... silly me... you mean the first CPU that triggers the spin_dump() will
deadlock itself, so the rest of CPUs will see endless recursive
spin_lock()->spin_dump()->spin_lock()->spin_dump() calls?

like the one below?


CPUZ is doing vprintk_emit()->spin_lock(), CPUA is the spin_lock's owner

CPUZ -> vprintk_emit()
	__spin_lock_debug()
		for (i = 0; i < `loops_per_jiffy * HZ'; i++) {   << wait for the lock
			if (arch_spin_trylock())
				return;
			__delay(1);
			}
		spin_dump()       << lock is still owned by CPUA
		{   -> vprintk_emit()
			__spin_lock_debug()
				for (...) {
					if (arch_spin_trylock())
						return;
					__delay(1);
				}
		<< CPUA unlocked the lock
				spin_dump()
				{   -> vprintk_emit()
					__spin_lock_debug()
						for (...) {
							if (arch_spin_trylock())   << success!!
							/* CPUZ now owns the lock */
								return;
						}
				}

			<< we return here with the spin_lock being owned by this CPUZ

				trigger_all_cpu_backtrace()

			<< and... now it does the arch_spin_lock()
				/*
				 * The trylock above was causing a livelock.  Give the lower level arch
				 * specific lock code a chance to acquire the lock. We have already
				 * printed a warning/backtrace at this point. The non-debug arch
				 * specific code might actually succeed in acquiring the lock.  If it is
				 * not successful, the end-result is the same - there is no forward
				 * progress.
				 */
				arch_spin_lock(&lock->raw_lock);

			<< which obviously dealocks this CPU...
		}

		trigger_all_cpu_backtrace()

		arch_spin_lock()




so
	"the CPUZ is now keeping the lock forever, and not going to release it"
and
	"CPUA-CPUX will do vprintk_emit()->spin_lock()->spin_dump()->vprintk_emit()->..."



My apologies for not getting it right the first time. Sorry!

Can you please update your bug description in the commit message?
It's the deadlock that is causing the recursion on other CPUs in the
first place.


	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

two small corrections.

On (01/28/16 19:41), Sergey Senozhatsky wrote:
[..]
> > Unfortunately, it's not reproduced anymore.
> > 
> > If it's clearly a spinlock caller's bug as you said, modifying the
> > spinlock debug code does not help it at all. But I found there's a
> > possiblity in the debug code *itself* to cause a lockup. So I tried
> > to fix it. What do you think about it?
> 
> ah... silly me... you mean the first CPU that triggers the spin_dump() will
					^^^ this, of course, is true for
					console_sem->lock and logbuf_lock
					only.

> deadlock itself, so the rest of CPUs will see endless recursive
> spin_lock()->spin_dump()->spin_lock()->spin_dump() calls?
> 
> like the one below?
> 
> 
> CPUZ is doing vprintk_emit()->spin_lock(), CPUA is the spin_lock's owner
> 
> CPUZ -> vprintk_emit()
> 	__spin_lock_debug()
> 		for (i = 0; i < `loops_per_jiffy * HZ'; i++) {   << wait for the lock
> 			if (arch_spin_trylock())
> 				return;
> 			__delay(1);
> 			}
> 		spin_dump()       << lock is still owned by CPUA
> 		{   -> vprintk_emit()
> 			__spin_lock_debug()
> 				for (...) {
> 					if (arch_spin_trylock())
> 						return;
> 					__delay(1);
> 				}
- 		<< CPUA unlocked the lock
> 				spin_dump()
> 				{   -> vprintk_emit()
> 					__spin_lock_debug()
      the "<< CPUA unlocked the lock" line better be here. to make it correct.

+		<< CPUA unlocked the lock
> 						for (...) {
> 							if (arch_spin_trylock())   << success!!
> 							/* CPUZ now owns the lock */
> 								return;
> 						}
> 				}
> 
> 			<< we return here with the spin_lock being owned by this CPUZ
> 
> 				trigger_all_cpu_backtrace()
> 
> 			<< and... now it does the arch_spin_lock()
> 				/*
> 				 * The trylock above was causing a livelock.  Give the lower level arch
> 				 * specific lock code a chance to acquire the lock. We have already
> 				 * printed a warning/backtrace at this point. The non-debug arch
> 				 * specific code might actually succeed in acquiring the lock.  If it is
> 				 * not successful, the end-result is the same - there is no forward
> 				 * progress.
> 				 */
> 				arch_spin_lock(&lock->raw_lock);
> 
> 			<< which obviously dealocks this CPU...
> 		}
> 
> 		trigger_all_cpu_backtrace()
> 
> 		arch_spin_lock()
> 
> 
> 
> 
> so
> 	"the CPUZ is now keeping the lock forever, and not going to release it"
> and
> 	"CPUA-CPUX will do vprintk_emit()->spin_lock()->spin_dump()->vprintk_emit()->..."
> 
> 
> 
> My apologies for not getting it right the first time. Sorry!
> 
> Can you please update your bug description in the commit message?
> It's the deadlock that is causing the recursion on other CPUs in the
> first place.

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 19:53), Sergey Senozhatsky wrote:
> > ah... silly me... you mean the first CPU that triggers the spin_dump() will
> 					^^^ this, of course, is true for
> 					console_sem->lock and logbuf_lock
> 					only.
> 
> > deadlock itself, so the rest of CPUs will see endless recursive
> > spin_lock()->spin_dump()->spin_lock()->spin_dump() calls?
[..]
> > Can you please update your bug description in the commit message?
> > It's the deadlock that is causing the recursion on other CPUs in the
> > first place.

no, don't update anything. I was completely wrong. it's not a deadlock
that is the root cause here.

even if at some level of recursion (nested printk calls)
spin_dump()->__spin_lock_debug()->arch_spin_trylock() acquires the
lock, it returns back with the spin lock unlocked anyway.

vprintk_emit()
 console_trylock()
  spin_lock()
   spin_dump()
    vprintk_emit()
     console_trylock()
      spin_lock()
       spin_dump()
        vprintk_emit()
         console_trylock()
          spin_lock()     << OK, got the lock finally
           sem->count--
          spin_unlock()   << unlock, return
       arch_spin_lock()   << got the lock, return
      sem->count--
      spin_unlock() << unlock, return
   arch_spin_lock() << got the lock, return
  sem->count--
  spin_unlock() << unlock, return


...um


> But I found there's a possiblity in the debug code *itself* to cause a
> lockup.

please explain.

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Peter Hurley]

On 01/28/2016 07:42 AM, Sergey Senozhatsky wrote:
> On (01/28/16 19:53), Sergey Senozhatsky wrote:
>>> ah... silly me... you mean the first CPU that triggers the spin_dump() will
>> 					^^^ this, of course, is true for
>> 					console_sem->lock and logbuf_lock
>> 					only.
>>
>>> deadlock itself, so the rest of CPUs will see endless recursive
>>> spin_lock()->spin_dump()->spin_lock()->spin_dump() calls?
> [..]
>>> Can you please update your bug description in the commit message?
>>> It's the deadlock that is causing the recursion on other CPUs in the
>>> first place.
> 
> no, don't update anything. I was completely wrong. it's not a deadlock
> that is the root cause here.
> 
> even if at some level of recursion (nested printk calls)
> spin_dump()->__spin_lock_debug()->arch_spin_trylock() acquires the
> lock, it returns back with the spin lock unlocked anyway.
> 
> vprintk_emit()
>  console_trylock()
>   spin_lock()
>    spin_dump()
>     vprintk_emit()
>      console_trylock()
>       spin_lock()
>        spin_dump()
>         vprintk_emit()
>          console_trylock()
>           spin_lock()     << OK, got the lock finally

The problem is you have postulated a very shallow recursion.
This looks much worse if this happens 1000 times, and
probably won't recover to output anything.

Additionally, what if the console_sem is simply corrupted?
A livelock with no output ever is not very helpful.

As I wrote earlier, I don't think this is the way to fix
recursion problems with printk() [by eliding output].

Rather, a way to effectively determine a recursion is in progress,
and _at a minimum_ guaranteeing that the recursive output will
eventually be output should be the goal.

Including dumb recursion like a console driver printing
an error :/

Then, lockdep could remain enabled while calling console drivers.

Regards,
Peter Hurley

>            sem->count--
>           spin_unlock()   << unlock, return
>        arch_spin_lock()   << got the lock, return
>       sem->count--
>       spin_unlock() << unlock, return
>    arch_spin_lock() << got the lock, return
>   sem->count--
>   spin_unlock() << unlock, return
> 
> 
> ...um
> 
> 
>> But I found there's a possiblity in the debug code *itself* to cause a
>> lockup.
> 
> please explain.
> 
> 	-ss
> 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Thu, Jan 28, 2016 at 03:08:19PM -0800, Peter Hurley wrote:
> The problem is you have postulated a very shallow recursion.
> This looks much worse if this happens 1000 times, and
> probably won't recover to output anything.
> 
> Additionally, what if the console_sem is simply corrupted?
> A livelock with no output ever is not very helpful.
> 
> As I wrote earlier, I don't think this is the way to fix
> recursion problems with printk() [by eliding output].

I think you are currently misunderstading about this patch. Or I'm
misunderstanding you.. The patch was changed in v4 so that it can print
a debug message even in the recursive cycle case, at the first time.

I also thought printing nothing in the case was not helpful at all which I
did in v1,2,3. But it's changed in v4, that is, this patch.

thanks,
byungchul

> 
> Rather, a way to effectively determine a recursion is in progress,
> and _at a minimum_ guaranteeing that the recursive output will
> eventually be output should be the goal.
> 
> Including dumb recursion like a console driver printing
> an error :/
> 
> Then, lockdep could remain enabled while calling console drivers.
> 
> Regards,
> Peter Hurley
> 
> >            sem->count--
> >           spin_unlock()   << unlock, return
> >        arch_spin_lock()   << got the lock, return
> >       sem->count--
> >       spin_unlock() << unlock, return
> >    arch_spin_lock() << got the lock, return
> >   sem->count--
> >   spin_unlock() << unlock, return
> > 
> > 
> > ...um
> > 
> > 
> >> But I found there's a possiblity in the debug code *itself* to cause a
> >> lockup.
> > 
> > please explain.
> > 
> > 	-ss
> > 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 15:08), Peter Hurley wrote:
[..]
> > even if at some level of recursion (nested printk calls)
> > spin_dump()->__spin_lock_debug()->arch_spin_trylock() acquires the
> > lock, it returns back with the spin lock unlocked anyway.
> > 
> > vprintk_emit()
> >  console_trylock()
> >   spin_lock()
> >    spin_dump()
> >     vprintk_emit()
> >      console_trylock()
> >       spin_lock()
> >        spin_dump()
> >         vprintk_emit()
> >          console_trylock()
> >           spin_lock()     << OK, got the lock finally
> 
> The problem is you have postulated a very shallow recursion.
> This looks much worse if this happens 1000 times, and
> probably won't recover to output anything.

well, the stack is surely limited, but on every
spin_dump()->spin_lock() recursive call it does another
round of

	u64 loops = loops_per_jiffy * HZ;

	for (i = 0; i < loops; i++) {
		if (arch_spin_trylock(&lock->raw_lock))
			return;
		__delay(1);
	}

so if you have 1000 spin_dump()->spin_lock() then, well,
something has been holding the lock for '1000 * loops_per_jiffy * HZ'.

and in particularly this case that somethign was holding the
spin lock doing trivial operations like

	count = sem->count - 1;
	if (likely(count >= 0))
		sem->count = count;

(or a bit more if it was in down()). but still.

and it's kinda hard to imagine console_sem lock being soooooooo
congested and unfair. on each given point of time in the worst
case there are `num_online_cpus() - 1' cpus spinning on that spin_lock
and 1 cpu holding that spinlock. which in Byungchul's case is, what,
3 spinning cpus, or 7 spinnign cpus?...


> Additionally, what if the console_sem is simply corrupted?
> A livelock with no output ever is not very helpful.

if it's corrupted then this is not a spinlock debug problem.
at all.


> As I wrote earlier, I don't think this is the way to fix
> recursion problems with printk() [by eliding output].
> 
> Rather, a way to effectively determine a recursion is in progress,
> and _at a minimum_ guaranteeing that the recursive output will
> eventually be output should be the goal.
> 
> Including dumb recursion like a console driver printing
> an error :/

this is not a case of printk recursion and it should be handled
just fine. console drivers are called under console_sem only.
logbuf lock is unlocked. vprintk_emit() adds message to the logbuf,
calls console_trylock() (which of course does not lock anything)
and returns back to console_driver code.

the only case when we really have a printk recursion is when
someone calls printk() from within the vprintk_emit() logbuf_lock
area.

print()
 spin_lock logbuf
   printk()
     spin_lock logbuf <<< recursion
 spin_unlock logbuf


	-ss

> Then, lockdep could remain enabled while calling console drivers.
> 
> Regards,
> Peter Hurley
> 
> >            sem->count--
> >           spin_unlock()   << unlock, return
> >        arch_spin_lock()   << got the lock, return
> >       sem->count--
> >       spin_unlock() << unlock, return
> >    arch_spin_lock() << got the lock, return
> >   sem->count--
> >   spin_unlock() << unlock, return
> > 
> > 
> > ...um
> > 
> > 
> >> But I found there's a possiblity in the debug code *itself* to cause a
> >> lockup.
> > 
> > please explain.
> > 
> > 	-ss
> > 
> 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/29/16 08:54), Byungchul Park wrote:
> > The problem is you have postulated a very shallow recursion.
> > This looks much worse if this happens 1000 times, and
> > probably won't recover to output anything.
> > 
> > Additionally, what if the console_sem is simply corrupted?
> > A livelock with no output ever is not very helpful.
> > 
> > As I wrote earlier, I don't think this is the way to fix
> > recursion problems with printk() [by eliding output].
> 
> I think you are currently misunderstading about this patch. Or I'm
> misunderstanding you.. The patch was changed in v4 so that it can print
> a debug message even in the recursive cycle case, at the first time.
> 
> I also thought printing nothing in the case was not helpful at all which I
> did in v1,2,3. But it's changed in v4, that is, this patch.

because you don't give any details and don't answer any questions.
it took a while to even find out that you are reporting this issues
not against a real H/W, but a qemu. I suppose qemu-arm running on
x86_64 box.

now, what else we don't know?

explain STEP-BY-STEP why do you think spinlock debug code can lockup
itself. not just "I don't think this is the case, I don't think that
is the case".

on very spin_dump recursive call it waits for the spin_lock and when
it eventually grabs it, it does the job that it wanted to do under
that spin lock, unlock it and return back. and the only case when it
never "return back" is when it never "eventually grabs it".

so I still don't see what issue you fix here -- the possibility to
consume the entire kernel stack doing recursive spin_dump->spin_lock()
calls because:
  a) something never unlocks the lock (no matter why.. corruption, HW
fault, etc.)
or
  b) everything was OK, but we attempted to printk() already
being in a very-very deep callstack, so doing 5 extra
printk->spin_dump->printk->spin_dump would simply kill it.


if none of the above. then what you report and fix is simply non
realistic. spin_dump must eventually unwind the stack back. yes,
you'll see a lot of dump_stack() and all cpus backtraces done on
every roollback stack. but you would still see some of them anyway,
even w/o the spinlock debug code -- because you'd just
raw_spin_lock_irqsave() on that lock for a very long time; which
does upset watchdog, etc.


please start explaining the things.

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Fri, Jan 29, 2016 at 09:54:06AM +0900, Sergey Senozhatsky wrote:
> because you don't give any details and don't answer any questions.

There are 2 ways to make the kernel better and stabler.

1) Remove the possiblity which make the system go crazy, even though it
would hardly happen since the possiblity is too low.

2) Fix it after facing some problems in practice and debugging it.

I started to write this patch due to the 2nd reason after seeing the
backtrace in gdb. But I lost the data with which I can debug it now,
since I was mis-convinced that it was done. So I could not answer it for
the your questions about memory corruption and cpu off. Sorry for not
informing you these facts in advance. But please remind that I was in
progress by the 1st way.

> it took a while to even find out that you are reporting this issues
> not against a real H/W, but a qemu. I suppose qemu-arm running on
> x86_64 box.

No matter what kind of box I used because I only kept talking about the
possiblity. It does not depend on a box at all.

> 
> now, what else we don't know?
> 
> explain STEP-BY-STEP why do you think spinlock debug code can lockup
> itself. not just "I don't think this is the case, I don't think that
> is the case".

I did explaining the reason in detail even though there's something I
missed. I've never said "I don't think this is the case" on the
description explaining the problem. Anyway, I am not sure about my patch
now, thank to your advice.

> 
> on very spin_dump recursive call it waits for the spin_lock and when
> it eventually grabs it, it does the job that it wanted to do under
> that spin lock, unlock it and return back. and the only case when it
> never "return back" is when it never "eventually grabs it".

Right. I missed it.

> 
> so I still don't see what issue you fix here -- the possibility to
> consume the entire kernel stack doing recursive spin_dump->spin_lock()
> calls because:
>   a) something never unlocks the lock (no matter why.. corruption, HW
> fault, etc.)
> or
>   b) everything was OK, but we attempted to printk() already
> being in a very-very deep callstack, so doing 5 extra
> printk->spin_dump->printk->spin_dump would simply kill it.
> 
> 
> if none of the above. then what you report and fix is simply non
> realistic. spin_dump must eventually unwind the stack back. yes,
> you'll see a lot of dump_stack() and all cpus backtraces done on
> every roollback stack. but you would still see some of them anyway,
> even w/o the spinlock debug code -- because you'd just
> raw_spin_lock_irqsave() on that lock for a very long time; which
> does upset watchdog, etc.

I am not sure now, if it can be fixed by the 1st way, that is, removing
the possiblity which make the system go crazy. There's something I missed.
Now I have to solve this problem by the 2nd way after reproducing it and
debugging it in detail. I still keep trying to reproduce it now.

Anyway. Thank you very much.

Thanks,
Byungchul

> 
> 
> please start explaining the things.
> 
> 	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/29/16 12:00), Byungchul Park wrote:
[..]
> > it took a while to even find out that you are reporting this issues
> > not against a real H/W, but a qemu. I suppose qemu-arm running on
> > x86_64 box.
> 
> No matter what kind of box I used because I only kept talking about the
> possiblity. It does not depend on a box at all.

well, qemu completely invalidates all of the H/W theories - powered off,
etc. so in a way it's important.


> > on very spin_dump recursive call it waits for the spin_lock and when
> > it eventually grabs it, it does the job that it wanted to do under
> > that spin lock, unlock it and return back. and the only case when it
> > never "return back" is when it never "eventually grabs it".
> 
> Right. I missed it.

hm... we also can hit problems in spin_unlock() path. AND there are chances
that spin_unlock() can explode WITH OUT any memory corruption on sight, but
due to a coding error... a theoretical one:

we do unlock logbuf_lock, and debug_spin_unlock() is performed on a 
locked logbuf_lock spin_lock

	static inline void debug_spin_unlock(raw_spinlock_t *lock)
	{
		SPIN_BUG_ON(lock->magic != SPINLOCK_MAGIC, lock, "bad magic");
		SPIN_BUG_ON(!raw_spin_is_locked(lock), lock, "already unlocked");
		SPIN_BUG_ON(lock->owner != current, lock, "wrong owner");
		SPIN_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
								lock, "wrong CPU");
		lock->owner = SPINLOCK_OWNER_INIT;
		lock->owner_cpu = -1;
	}

	void do_raw_spin_unlock(raw_spinlock_t *lock)
	{
		debug_spin_unlock(lock);
		arch_spin_unlock(&lock->raw_lock);
	}

so if there was a coding error (schedule while atomic, or unlock from another
CPU) which resulted in faulty
	lock->owner_cpu != raw_smp_processor_id()
OR
	lock->owner != current

then this will explode:

printk
 spin_lock
  >> coding error <<
 spin_unlock
  printk
   spin_lock
    printk
     spin_lock
      printk
       spin_lock
        ... boom

vprintk_emit() recursion detection code will not work for logbuf_lock here.
because the only criteria how vprintk_emit() can detect a recursion is via
static `logbuf_cpu' which is set to UINT_MAX right before it
raw_spin_unlock(&logbuf_lock). so from vprintk_emit() POV the logbuf_lock is
already unlocked. which is not true.


in case of memory corruption I don't think we must care, 'coding error case'
is _probably/may be_ something that can be improved, but I'm not really 100%
sure... and this still doesn't explain your console_sem.lock case.

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Peter Hurley]

On 01/28/2016 04:27 PM, Sergey Senozhatsky wrote:
> On (01/28/16 15:08), Peter Hurley wrote:
> [..]
>>> even if at some level of recursion (nested printk calls)
>>> spin_dump()->__spin_lock_debug()->arch_spin_trylock() acquires the
>>> lock, it returns back with the spin lock unlocked anyway.
>>>
>>> vprintk_emit()
>>>  console_trylock()
>>>   spin_lock()
>>>    spin_dump()
>>>     vprintk_emit()
>>>      console_trylock()
>>>       spin_lock()
>>>        spin_dump()
>>>         vprintk_emit()
>>>          console_trylock()
>>>           spin_lock()     << OK, got the lock finally
>>
>> The problem is you have postulated a very shallow recursion.
>> This looks much worse if this happens 1000 times, and
>> probably won't recover to output anything.
> 
> well, the stack is surely limited, but on every
> spin_dump()->spin_lock() recursive call it does another
> round of
> 
> 	u64 loops = loops_per_jiffy * HZ;
> 
> 	for (i = 0; i < loops; i++) {
> 		if (arch_spin_trylock(&lock->raw_lock))
> 			return;
> 		__delay(1);
> 	}
> 
> so if you have 1000 spin_dump()->spin_lock() then, well,
> something has been holding the lock for '1000 * loops_per_jiffy * HZ'.
> 
> and in particularly this case that somethign was holding the
> spin lock doing trivial operations like
> 
> 	count = sem->count - 1;
> 	if (likely(count >= 0))
> 		sem->count = count;
> 
> (or a bit more if it was in down()). but still.
> 
> and it's kinda hard to imagine console_sem lock being soooooooo
> congested and unfair. on each given point of time in the worst
> case there are `num_online_cpus() - 1' cpus spinning on that spin_lock
> and 1 cpu holding that spinlock. which in Byungchul's case is, what,
> 3 spinning cpus, or 7 spinnign cpus?...


You're assuming that Byungchul's patch is relevant to the recursion
he witnessed. There are several paths into spin_dump().

Here's one that doesn't wait at all:

vprintk_emit()
  console_trylock()
    down_trylock()
      raw_spin_lock_irqsave()
        ...             
          do_raw_spin_lock()
            debug_spin_lock_before()
              SPIN_BUG_ON()
                spin_bug()
                   spin_dump()
                     printk()
                       ** RINSE AND REPEAT **



>> Additionally, what if the console_sem is simply corrupted?
>> A livelock with no output ever is not very helpful.
> 
> if it's corrupted then this is not a spinlock debug problem.
> at all.

I don't follow you.

The whole point of SPIN_BUG_ON() is to catch problems that should never
happen, but nevertheless, have.

IOW, following your logic, we should remove the SPIN_BUG_ON() because
these situations should not happen.


>> As I wrote earlier, I don't think this is the way to fix
>> recursion problems with printk() [by eliding output].
>>
>> Rather, a way to effectively determine a recursion is in progress,
>> and _at a minimum_ guaranteeing that the recursive output will
>> eventually be output should be the goal.
>>
>> Including dumb recursion like a console driver printing
>> an error :/

This was in reference to a problem with spin lock recursion that
can't print. The spin lock recursion deadlocks, but you'll never
see the diagnostic because the driver is already holding the lock
(not from printk() but from some other code).

The printk doesn't even need to be directly related to the
console driver itself, but some other thing that the console driver
depends on while holding the spin lock that it claims for console output.

Deadlock, no output.

For example,

  serial8250_do_set_termios()
    spin_lock_irqsave()  ** claim port lock **
    ...
    serial_port_out(port, UART_LCR, ....);
      dw8250_serial_out()
        dev_err()
          vprintk_emit()
            console_trylock()
              call_console_drivers()
                serial8250_console_write()
                  spin_lock_irqsave()  ** port lock **
                  ** DEADLOCK **
 

> this is not a case of printk recursion and it should be handled
> just fine. console drivers are called under console_sem only.
> logbuf lock is unlocked. vprintk_emit() adds message to the logbuf,
> calls console_trylock() (which of course does not lock anything)
> and returns back to console_driver code.

Not if locks are zapped because printk() recognizes a recursion.
Note console driver's locks are not zapped. For example,

vprintk_emit()
   ...
   call_console_drivers()
      /* inside some console driver */
      claim some lock
      printk("%s\n", NULL);  /* you get the idea */
         vprintk_emit()
         logbuf_lock
         vscnprintf()
            ** oops **
            vprintk_emit()
               recursion detected
               zap_locks()
               ....
                  call_console_drivers()
                     /* inside same console driver */
                     claim same lock
                     ** DEADLOCK **
            
         

> the only case when we really have a printk recursion is when
> someone calls printk() from within the vprintk_emit() logbuf_lock
> area.

Not true.

A while back, Jan Kara reworked the call site around
console_trylock_from_printk(). Hung with no output under unknown
conditions [1].

Never solved, but obviously means there are unhandled recursions.

So lockdep remains disabled when calling console drivers.

Regards,
Peter Hurley

[1] https://lkml.org/lkml/2014/6/11/591


> print()
>  spin_lock logbuf
>    printk()
>      spin_lock logbuf <<< recursion
>  spin_unlock logbuf
> 
> 
> 	-ss
> 
>> Then, lockdep could remain enabled while calling console drivers.
>>
>> Regards,
>> Peter Hurley
>>
>>>            sem->count--
>>>           spin_unlock()   << unlock, return
>>>        arch_spin_lock()   << got the lock, return
>>>       sem->count--
>>>       spin_unlock() << unlock, return
>>>    arch_spin_lock() << got the lock, return
>>>   sem->count--
>>>   spin_unlock() << unlock, return
>>>
>>>
>>> ...um
>>>
>>>
>>>> But I found there's a possiblity in the debug code *itself* to cause a
>>>> lockup.
>>>
>>> please explain.
>>>
>>> 	-ss
>>>
>>

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 20:32), Peter Hurley wrote:
[..]
> You're assuming that Byungchul's patch is relevant to the recursion
> he witnessed. There are several paths into spin_dump().

yes. I was speaking in the context of Byungchul's report.

> Here's one that doesn't wait at all:
> 
> vprintk_emit()
>   console_trylock()
>     down_trylock()
>       raw_spin_lock_irqsave()
>         ...             
>           do_raw_spin_lock()
>             debug_spin_lock_before()
>               SPIN_BUG_ON()
>                 spin_bug()
>                    spin_dump()
>                      printk()
>                        ** RINSE AND REPEAT **

ah, yes, agree.

> >> Additionally, what if the console_sem is simply corrupted?
> >> A livelock with no output ever is not very helpful.
> > 
> > if it's corrupted then this is not a spinlock debug problem.
> > at all.
> 
> I don't follow you.
> 

indeed very misleading, sorry, almost didn't sleep last nigh.
removing SPIN_BUG_ON entirely is not my logic, not all. printk locks are
special, I agree. in context of the proposed patch - we can't disable
spin_dump() for printk locks if they were corrupted. for printk locks it's
over, nothing will be printed anymore. the only thing that _may be_ will
help is zap_locks(), but not 100% guaranteed... we can panic the system,
probably, if printk locks are getting corrupted, but panic() will not do the
trick in general case, at this point -- console_unlock() takes the logbuf_lock,
which can be corrupted. apart from that console driver can be in a weird state.

I sort of proposed to update console_flush_on_panic()  (called from panic())
function a while ago to do zap_locks(), so in this case declaring BUG() from
spinlock debug when we see 'bad' printk-related locks will have better
chances to work out (assuming that console driver(-s) is (are) not against
us).

[..]
> This was in reference to a problem with spin lock recursion that
> can't print. The spin lock recursion deadlocks, but you'll never
> see the diagnostic because the driver is already holding the lock
> (not from printk() but from some other code).
> 
> The printk doesn't even need to be directly related to the
> console driver itself, but some other thing that the console driver
> depends on while holding the spin lock that it claims for console output.

aha, ok. yes, this is certainly possible.

> > this is not a case of printk recursion and it should be handled
> > just fine. console drivers are called under console_sem only.
> > logbuf lock is unlocked. vprintk_emit() adds message to the logbuf,
> > calls console_trylock() (which of course does not lock anything)
> > and returns back to console_driver code.
> 
> Not if locks are zapped because printk() recognizes a recursion.
> Note console driver's locks are not zapped. For example,

yes, I proposed to add a ->reset callback to struct console
a while ago, and to do a console reset loop in zap_locks()

zap_locks:
...
	for_each_console(con)
		if (con->reset)
			con->reset(con)

that would re-init console drivers (locks, etc.).


IOW, panic() does zap_locks(), zap_locks() zap the locks and
resets the console drivers. that's sort of what I have in my
private kernels.

[..]
> > the only case when we really have a printk recursion is when
> > someone calls printk() from within the vprintk_emit() logbuf_lock
> > area.
> 
> Not true.
> 
> A while back, Jan Kara reworked the call site around
> console_trylock_from_printk(). Hung with no output under unknown
> conditions [1].
> 
> Never solved, but obviously means there are unhandled recursions.

aha, ok.

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Peter Hurley]

On 01/28/2016 09:28 PM, Sergey Senozhatsky wrote:
> On (01/28/16 20:32), Peter Hurley wrote:
> [..]
>> You're assuming that Byungchul's patch is relevant to the recursion
>> he witnessed. There are several paths into spin_dump().
> 
> yes. I was speaking in the context of Byungchul's report.
> 
>> Here's one that doesn't wait at all:
>>
>> vprintk_emit()
>>   console_trylock()
>>     down_trylock()
>>       raw_spin_lock_irqsave()
>>         ...             
>>           do_raw_spin_lock()
>>             debug_spin_lock_before()
>>               SPIN_BUG_ON()
>>                 spin_bug()
>>                    spin_dump()
>>                      printk()
>>                        ** RINSE AND REPEAT **
> 
> ah, yes, agree.
> 
>>>> Additionally, what if the console_sem is simply corrupted?
>>>> A livelock with no output ever is not very helpful.
>>>
>>> if it's corrupted then this is not a spinlock debug problem.
>>> at all.
>>
>> I don't follow you.
>>
> 
> indeed very misleading, sorry, almost didn't sleep last nigh.
> removing SPIN_BUG_ON entirely is not my logic, not all. printk locks are
> special, I agree. in context of the proposed patch - we can't disable
> spin_dump() for printk locks if they were corrupted. for printk locks it's
> over, nothing will be printed anymore. the only thing that _may be_ will
> help is zap_locks(), but not 100% guaranteed... we can panic the system,
> probably, if printk locks are getting corrupted, but panic() will not do the
> trick in general case, at this point -- console_unlock() takes the logbuf_lock,
> which can be corrupted. apart from that console driver can be in a weird state.
> 
> I sort of proposed to update console_flush_on_panic()  (called from panic())
> function a while ago to do zap_locks(), so in this case declaring BUG() from
> spinlock debug when we see 'bad' printk-related locks will have better
> chances to work out (assuming that console driver(-s) is (are) not against
> us).

Yeah, exactly, something that improves the chances of successful output.


> [..]
>> This was in reference to a problem with spin lock recursion that
>> can't print. The spin lock recursion deadlocks, but you'll never
>> see the diagnostic because the driver is already holding the lock
>> (not from printk() but from some other code).
>>
>> The printk doesn't even need to be directly related to the
>> console driver itself, but some other thing that the console driver
>> depends on while holding the spin lock that it claims for console output.
> 
> aha, ok. yes, this is certainly possible.
> 
>>> this is not a case of printk recursion and it should be handled
>>> just fine. console drivers are called under console_sem only.
>>> logbuf lock is unlocked. vprintk_emit() adds message to the logbuf,
>>> calls console_trylock() (which of course does not lock anything)
>>> and returns back to console_driver code.
>>
>> Not if locks are zapped because printk() recognizes a recursion.
>> Note console driver's locks are not zapped. For example,
> 
> yes, I proposed to add a ->reset callback to struct console
> a while ago, and to do a console reset loop in zap_locks()

What was the patch series title? I'd like to review that.

That would solve the recursive deadlock from console driver as well
(at least with CONFIG_DEBUG_SPINLOCK) because the printk() recursion
would zap the locks including the console driver's lock and
at least get the last output so that we'd know there was a recursion,
and fix it.


> zap_locks:
> ...
> 	for_each_console(con)
> 		if (con->reset)
> 			con->reset(con)
> 
> that would re-init console drivers (locks, etc.).
> 
> 
> IOW, panic() does zap_locks(), zap_locks() zap the locks and
> resets the console drivers. that's sort of what I have in my
> private kernels.
> 
> [..]
>>> the only case when we really have a printk recursion is when
>>> someone calls printk() from within the vprintk_emit() logbuf_lock
>>> area.
>>
>> Not true.
>>
>> A while back, Jan Kara reworked the call site around
>> console_trylock_from_printk(). Hung with no output under unknown
>> conditions [1].
>>
>> Never solved, but obviously means there are unhandled recursions.

I'd still like to enable lockdep for console drivers, but I need a
better plan to debug unknown printk() recursions.


> aha, ok.
> 
> 	-ss
> 

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/28/16 21:48), Peter Hurley wrote:
[..]
> > yes, I proposed to add a ->reset callback to struct console
> > a while ago, and to do a console reset loop in zap_locks()
> 
> What was the patch series title? I'd like to review that.

Thanks.

it was deep in the thread where Jan Kara proposed v1 of his
printk offloading support
"Re: [PATCH 1/7] printk: Hand over printing to console if printing too long"

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

I never ended up sending this out as a separate patch. my bad.

the panic()->zap_locks() was here (well, not even a patch set):
 http://marc.info/?l=linux-kernel&m=145260677129044

> That would solve the recursive deadlock from console driver as well
> (at least with CONFIG_DEBUG_SPINLOCK) because the printk() recursion
> would zap the locks including the console driver's lock and
> at least get the last output so that we'd know there was a recursion,
> and fix it.

yes, if printk() has a chance to detect a recursion and invoke zap_locks()
(which is based on logbuf_cpu check). in my other email there is a scenario
when printk() has no such a chance -- because 'logbuf_cpu' is set to UINT_MAX
right before raw_spin_unlock(&logbuf_lock). and if debug_spin_unlock() detects
a coding error (not even a corruption) (->owner != current, or
->owner_cpu != raw_smp_processor_id()) then things are turning bad quickly.

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

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/29/16 15:16), Sergey Senozhatsky wrote:
> 
>  http://marc.info/?l=linux-kernel&m=144976121529901
> 

hm... I don't like that patch. ->reset() loop must be done outside
of zap_locks(). we can have a printk() recursion in CPU1, but console
driver lock may be owned by CPU2 in driver's handle_IRQ(), for example.
stealing its lock CPU1 is not really good. in my kernels I do this from
panic() path only, where I know that things are already bad.

panic()->console_panic_mode()->{for_each_console()->reset(), zap_locks()}->console_trelock()->console_unlock().

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Fri, Jan 29, 2016 at 09:27:03AM +0900, Sergey Senozhatsky wrote:
> 
> well, the stack is surely limited, but on every
> spin_dump()->spin_lock() recursive call it does another
> round of
> 
> 	u64 loops = loops_per_jiffy * HZ;
> 
> 	for (i = 0; i < loops; i++) {
> 		if (arch_spin_trylock(&lock->raw_lock))
> 			return;
> 		__delay(1);
> 	}
> 
> so if you have 1000 spin_dump()->spin_lock() then, well,
> something has been holding the lock for '1000 * loops_per_jiffy * HZ'.

Or the printk() is heavily called and the lock is congested.

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/29/16 15:54), Byungchul Park wrote:
> On Fri, Jan 29, 2016 at 09:27:03AM +0900, Sergey Senozhatsky wrote:
> > 
> > well, the stack is surely limited, but on every
> > spin_dump()->spin_lock() recursive call it does another
> > round of
> > 
> > 	u64 loops = loops_per_jiffy * HZ;
> > 
> > 	for (i = 0; i < loops; i++) {
> > 		if (arch_spin_trylock(&lock->raw_lock))
> > 			return;
> > 		__delay(1);
> > 	}
> > 
> > so if you have 1000 spin_dump()->spin_lock() then, well,
> > something has been holding the lock for '1000 * loops_per_jiffy * HZ'.
> 
> Or the printk() is heavily called and the lock is congested.

well, isn't it the case that ticket-based locking assumes at least
some sort of fairness? how many cpus do you have there? you can
have `num_online_cpus() - 1' tasks spinning on the spin lock and
1 owning the spin lock... if your lock is in correct state (no
before/after spinlock debug errors) even most unlucky task should
get the lock eventually...

	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Fri, Jan 29, 2016 at 04:13:30PM +0900, Sergey Senozhatsky wrote:
> On (01/29/16 15:54), Byungchul Park wrote:
> > On Fri, Jan 29, 2016 at 09:27:03AM +0900, Sergey Senozhatsky wrote:
> > > 
> > > well, the stack is surely limited, but on every
> > > spin_dump()->spin_lock() recursive call it does another
> > > round of
> > > 
> > > 	u64 loops = loops_per_jiffy * HZ;
> > > 
> > > 	for (i = 0; i < loops; i++) {
> > > 		if (arch_spin_trylock(&lock->raw_lock))
                       ^^^
		       this is a trylock.

> > > 			return;
> > > 		__delay(1);
> > > 	}
> > > 
> > > so if you have 1000 spin_dump()->spin_lock() then, well,
> > > something has been holding the lock for '1000 * loops_per_jiffy * HZ'.
> > 
> > Or the printk() is heavily called and the lock is congested.
> 
> well, isn't it the case that ticket-based locking assumes at least
> some sort of fairness? how many cpus do you have there? you can

It's true for a congestion between arch_spin_lock()s, not trylock(). And I
cannot remember how many online cpus there are, since I frequently change
the number. Sorry. But the range is from 2 to 4.

> have `num_online_cpus() - 1' tasks spinning on the spin lock and
> 1 owning the spin lock... if your lock is in correct state (no
> before/after spinlock debug errors) even most unlucky task should
> get the lock eventually...
> 
> 	-ss

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Thu, Jan 28, 2016 at 04:15:02PM +0900, Byungchul Park wrote:
> On Wed, Jan 27, 2016 at 02:49:35PM -0800, Peter Hurley wrote:
> > And we already have lockdep turned off to avoid triggering a recursive
> > lockdep report (which I think is a mistake).
> 
> Yes, we already have a way to turn off the lock debug so that we can
> avoid it. So I used it in v4.
> 
> thanks,
> byungchul
> 
> > 
> > I think we should be working toward properly handling recursion
> > in printk().

And it would be better once it is done to handle the recursion properly.
But I think, not now..

> > 
> > Regards,
> > Peter Hurley

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Byungchul Park]

On Fri, Jan 29, 2016 at 01:05:00PM +0900, Sergey Senozhatsky wrote:
> then this will explode:
> 
> printk
>  spin_lock
>   >> coding error <<
>  spin_unlock
>   printk
>    spin_lock
>     printk
>      spin_lock
>       printk
>        spin_lock
>         ... boom
> 
> vprintk_emit() recursion detection code will not work for logbuf_lock here.
> because the only criteria how vprintk_emit() can detect a recursion is via
> static `logbuf_cpu' which is set to UINT_MAX right before it
> raw_spin_unlock(&logbuf_lock). so from vprintk_emit() POV the logbuf_lock is
> already unlocked. which is not true.
> 
> 
> in case of memory corruption I don't think we must care, 'coding error case'
> is _probably/may be_ something that can be improved, but I'm not really 100%
> sure... and this still doesn't explain your console_sem.lock case.

Hello, I found the case this bad thing can happen. So the thought occurred
struck me that we need a patch, similar to my v3 patch, even though the
consideration of logbug_lock in the v3 patch may not be necessary now.

cpu0
====
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 // once it happened
                    printk
                      console_trylock
                        raw_spin_lock_irqsave(&sem->lock, flags)

                        <=== DEADLOCK

cpu1
====
printk
  console_trylock
    raw_spin_lock_irqsave(&sem->lock, flags)
    __spin_lock_debug
      spin_dump
        printk
          ...

          <=== repeat the recursive cycle infinitely

This was the my v3 patch.
-----8<-----
>From 92c84ea45ac18010804aa09eeb9e03f797a4b2b0 Mon Sep 17 00:00:00 2001
From: Byungchul Park <byungchul.park@lge.com>
Date: Wed, 27 Jan 2016 13:33:24 +0900
Subject: [PATCH v3] lib/spinlock_debug.c: prevent an infinite recursive cycle
 in spin_dump()

It causes an infinite recursive cycle when using CONFIG_DEBUG_SPINLOCK,
in the spin_dump(). Backtrace prints printk() -> console_trylock() ->
do_raw_spin_lock() -> spin_dump() -> printk()... infinitely.

When the spin_dump() is called from printk(), we should prevent the
debug spinlock code from calling printk() again in that context. It's
reasonable to avoid printing "lockup suspected" which is just a warning
message but it would cause a real lockup definitely.

However, this patch does not deal with spin_bug(), since avoiding it in
the spin_bug() does not help it at all. Calling spin_bug() nearly means a
real lockup happened!. In that case, it's not helpful.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 kernel/locking/spinlock_debug.c | 16 +++++++++++++---
 kernel/printk/printk.c          |  6 ++++++
 2 files changed, 19 insertions(+), 3 deletions(-)

diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..fefc76c 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -103,6 +103,8 @@ static inline void debug_spin_unlock(raw_spinlock_t *lock)
 	lock->owner_cpu = -1;
 }
 
+extern int is_printk_lock(raw_spinlock_t *lock);
+
 static void __spin_lock_debug(raw_spinlock_t *lock)
 {
 	u64 i;
@@ -113,11 +115,19 @@ static void __spin_lock_debug(raw_spinlock_t *lock)
 			return;
 		__delay(1);
 	}
-	/* lockup suspected: */
-	spin_dump(lock, "lockup suspected");
+
+	/*
+	 * If this function is called from printk(), then we should
+	 * not call printk() more. Or it will cause an infinite
+	 * recursive cycle!
+	 */
+	if (likely(!is_printk_lock(lock))) {
+		/* lockup suspected: */
+		spin_dump(lock, "lockup suspected");
 #ifdef CONFIG_SMP
-	trigger_all_cpu_backtrace();
+		trigger_all_cpu_backtrace();
 #endif
+	}
 
 	/*
 	 * The trylock above was causing a livelock.  Give the lower level arch
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2ce8826..657f8dd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1981,6 +1981,12 @@ asmlinkage __visible void early_printk(const char *fmt, ...)
 }
 #endif
 
+int is_printk_lock(raw_spinlock_t *lock)
+{
+	return	(lock == &console_sem.lock) ||
+		(lock == &logbuf_lock)      ;
+}
+
 static int __add_preferred_console(char *name, int idx, char *options,
 				   char *brl_options)
 {
-- 
1.9.1

Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code

[Sergey Senozhatsky]

On (01/29/16 15:37), Sergey Senozhatsky wrote:
> 
> panic()->console_panic_mode()->{for_each_console()->reset(), zap_locks()}->console_trelock()->console_unlock().

Hello,

This is not a final submission, just a RFC, so we can settle a better
plan. the patches are not signed off, have known problems (and likely
some unknown). I put a summary in here and send them out as a reply to
this email, so it'll be easier to review/comment/discuss.

patch 0001
***************
CPU stop IPI issued from panic() on CPUA, can leave console_sem locked
on CPUB if that cpu was holding the console_sem lock at the time when
IPI arrived. console_flush_on_panic() is trying to workaround it by
ignoring the return status of console_trylock() and unconditionally
executing console_unlock().

console_unlock() has a dependency on at least one more
lock - `logbuf_lock', which can be corrupted, for example, thus
console_unlock() may not be able to print anything afterall.

Introduce console_reset_on_panic() function to zap (re-init) printk
locks and call this function from panic().

WARNING
=======
This must be improved. console_reset_on_panic() is called before
smp_send_stop(), so:
a) we can have several CPU looping in console_unlock(), which is not
so critical.
b) we can re-init logbuf_lock while other CPU is holding it. Which
is more serious and needs to fixed.

The reason why console_reset_on_panic() is called this early is that
panicing CPU does pr_emerg("Kernel panic...") and dump_stack()
before it sends out smp_send_stop(). So if console_sem or logbug_lock,
or some console device driver lock is/are corrupted then panic() may
never smp_send_stop().




patch 0002
***************
Console driver(-s) can be in any state when CPU stop IPI
arrives from panic() issued on another CPU, so
console_flush_on_panic()->console_unlock() can call
con->write() callback on a locked console driver.

Introduce reset_console_drivers() that attempts to reset()
every console in via a console driver specific ->reset()
call.

Invoke reset_console_drivers() from console_reset_on_panic().

WARNING
=======
console_reset_on_panic() needs to be fixed.




patch 0003 -- detect recursive spin_dump() and panic() the system
***************
spin_dump() calls printk() which can attempt to reacquire the
'buggy' lock (one of printk's lock, or console device driver lock,
etc.) and thus spin_dump() will recursive into itself. Steal most
significant bit of spin_lock->owner_cpu to keep there a mark
that spin_dump() is in progress for that particular spin_lock.
spin_dump() will now set SPIN_DUMP_IN_PROGRESS bit at the
beginning of spin_dump() and clear it at the end, so it's
possible to detect recursive spin_dump() calls by checking if
lock's owner_cpu already has SPIN_DUMP_IN_PROGRESS bit already
set. panic() the system when spin_dump() recursion occurs.



	-ss

[PATCH 1/3] printk: introduce console_reset_on_panic() function

[Sergey Senozhatsky]

CPU stop IPI issued from panic() on CPUA, can leave console_sem locked
on CPUB if that cpu was holding the console_sem lock at the time when
IPI arrived. console_flush_on_panic() is trying to workaround it by
ignoring the return status of console_trylock() and unconditionally
executing console_unlock().

console_unlock() has a dependency on at least one more
lock - `logbuf_lock', which can be corrupted, for example, thus
console_unlock() may not be able to print anything afterall.

Introduce console_reset_on_panic() function to zap (re-init) printk
locks and call this function from panic().

WARNING
=======
This must be improved. console_reset_on_panic() is called before
smp_send_stop(), so:
a) we can have several CPU looping in console_unlock(), which is not
so critical.
b) we can re-init logbuf_lock while other CPU is holding it. Which
is more serious and needs to fixed.

The reason why console_reset_on_panic() is called this early is that
panicing CPU does pr_emerg("Kernel panic...") and dump_stack()
before it sends out smp_send_stop(). So if console_sem or logbug_lock,
or some console device driver lock is/are corrupted then panic() may
never smp_send_stop().

Not-Yet-Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h | 1 +
 kernel/panic.c          | 1 +
 kernel/printk/printk.c  | 5 +++++
 3 files changed, 7 insertions(+)

diff --git a/include/linux/console.h b/include/linux/console.h
index ea731af..6edc2ea 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -151,6 +151,7 @@ extern void console_unlock(void);
 extern void console_conditional_schedule(void);
 extern void console_unblank(void);
 extern void console_flush_on_panic(void);
+extern void console_reset_on_panic(void);
 extern struct tty_driver *console_device(int *);
 extern void console_stop(struct console *);
 extern void console_start(struct console *);
diff --git a/kernel/panic.c b/kernel/panic.c
index d96469d..71d43f6 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -119,6 +119,7 @@ void panic(const char *fmt, ...)
 
 	console_verbose();
 	bust_spinlocks(1);
+	console_reset_on_panic();
 	va_start(args, fmt);
 	vsnprintf(buf, sizeof(buf), fmt, args);
 	va_end(args);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 097ca8b..34642f7 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2394,6 +2394,11 @@ void console_flush_on_panic(void)
 	console_unlock();
 }
 
+void console_reset_on_panic(void)
+{
+	zap_locks();
+}
+
 /*
  * Return the console tty driver structure and its associated index
  */
-- 
2.7.0

[PATCH 2/3] printk: introduce reset_console_drivers()

[Sergey Senozhatsky]

Console driver(-s) can be in any state when CPU stop IPI
arrives from panic() issued on another CPU, so
console_flush_on_panic()->console_unlock() can call
con->write() callback on a locked console driver.

Introduce reset_console_drivers() that attempts to reset()
every console in via a console driver specific ->reset()
call.

Invoke reset_console_drivers() from console_reset_on_panic().

WARNING
=======
console_reset_on_panic() needs to be fixed.

Not-Yet-Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h |  1 +
 kernel/printk/printk.c  | 10 ++++++++++
 2 files changed, 11 insertions(+)

diff --git a/include/linux/console.h b/include/linux/console.h
index 6edc2ea..f745ffe 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -125,6 +125,7 @@ struct console {
 	void	(*unblank)(void);
 	int	(*setup)(struct console *, char *);
 	int	(*match)(struct console *, char *name, int idx, char *options);
+	void	(*reset)(struct console *);
 	short	flags;
 	short	index;
 	int	cflag;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 34642f7..e245f9f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1462,6 +1462,15 @@ static void call_console_drivers(int level,
 	}
 }
 
+static void reset_console_drivers(void)
+{
+	struct console *con;
+
+	for_each_console(con)
+		if ((con->flags & CON_ENABLED) && con->reset)
+			con->reset(con);
+}
+
 /*
  * Zap console related locks when oopsing.
  * To leave time for slow consoles to print a full oops,
@@ -2397,6 +2406,7 @@ void console_flush_on_panic(void)
 void console_reset_on_panic(void)
 {
 	zap_locks();
+	reset_console_drivers();
 }
 
 /*
-- 
2.7.0

[PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump()

[Sergey Senozhatsky]

spin_dump() calls printk() which can attempt to reacquire the
'buggy' lock (one of printk's lock, or console device driver lock,
etc.) and thus spin_dump() will recursive into itself. Steal most
significant bit of spin_lock->owner_cpu to keep there a mark
that spin_dump() is in progress for that particular spin_lock.
spin_dump() will now set SPIN_DUMP_IN_PROGRESS bit at the
beginning of spin_dump() and clear it at the end, so it's
possible to detect recursive spin_dump() calls by checking if
lock's owner_cpu already has SPIN_DUMP_IN_PROGRESS bit already
set. panic() the system when spin_dump() recursion occurs.

Not-Yet-Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/locking/spinlock_debug.c | 22 +++++++++++++++++-----
 1 file changed, 17 insertions(+), 5 deletions(-)

diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..1a4a864 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -13,6 +13,9 @@
 #include <linux/delay.h>
 #include <linux/export.h>
 
+#define SPIN_DUMP_IN_PROGRESS	(1 << 31)
+#define DEFAULT_OWNER_CPU	(INT_MAX >> 1)
+
 void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 			  struct lock_class_key *key)
 {
@@ -26,7 +29,7 @@ void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 	lock->raw_lock = (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
 	lock->magic = SPINLOCK_MAGIC;
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = DEFAULT_OWNER_CPU;
 }
 
 EXPORT_SYMBOL(__raw_spin_lock_init);
@@ -44,7 +47,7 @@ void __rwlock_init(rwlock_t *lock, const char *name,
 	lock->raw_lock = (arch_rwlock_t) __ARCH_RW_LOCK_UNLOCKED;
 	lock->magic = RWLOCK_MAGIC;
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = DEFAULT_OWNER_CPU;
 }
 
 EXPORT_SYMBOL(__rwlock_init);
@@ -53,6 +56,13 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 {
 	struct task_struct *owner = NULL;
 
+	if (lock->owner_cpu & SPIN_DUMP_IN_PROGRESS)
+		panic("BUG: lock: %pS spin dump recursion on CPU#%d, %s/%d\n",
+				lock, raw_smp_processor_id(),
+				current->comm, task_pid_nr(current));
+
+	lock->owner_cpu |= SPIN_DUMP_IN_PROGRESS;
+
 	if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
 		owner = lock->owner;
 	printk(KERN_EMERG "BUG: spinlock %s on CPU#%d, %s/%d\n",
@@ -63,8 +73,10 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",
 		owner ? task_pid_nr(owner) : -1,
-		lock->owner_cpu);
+		lock->owner_cpu == DEFAULT_OWNER_CPU ? -1 : lock->owner_cpu);
 	dump_stack();
+
+	lock->owner_cpu &= ~SPIN_DUMP_IN_PROGRESS;
 }
 
 static void spin_bug(raw_spinlock_t *lock, const char *msg)
@@ -100,7 +112,7 @@ static inline void debug_spin_unlock(raw_spinlock_t *lock)
 	SPIN_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = DEFAULT_OWNER_CPU;
 }
 
 static void __spin_lock_debug(raw_spinlock_t *lock)
@@ -244,7 +256,7 @@ static inline void debug_write_unlock(rwlock_t *lock)
 	RWLOCK_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = DEFAULT_OWNER_CPU;
 }
 
 #if 0		/* This can cause lockups */
-- 
2.7.0

Re: [PATCH 1/3] printk: introduce console_reset_on_panic() function

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1194 bytes --]

Hi Sergey,

[auto build test ERROR on linus/master]
[also build test ERROR on v4.5-rc1 next-20160129]
[cannot apply to tip/core/locking]
[if your patch is applied to the wrong git tree, please drop us a note to help improving the system]

url:    https://github.com/0day-ci/linux/commits/Sergey-Senozhatsky/printk-introduce-console_reset_on_panic-function/20160131-203605
config: i386-tinyconfig (attached as .config)
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'console_reset_on_panic':
>> kernel/printk/printk.c:2417:2: error: implicit declaration of function 'zap_locks' [-Werror=implicit-function-declaration]
     zap_locks();
     ^
   cc1: some warnings being treated as errors

vim +/zap_locks +2417 kernel/printk/printk.c

  2411		console_may_schedule = 0;
  2412		console_unlock();
  2413	}
  2414	
  2415	void console_reset_on_panic(void)
  2416	{
> 2417		zap_locks();
  2418	}
  2419	
  2420	/*

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/octet-stream, Size: 6206 bytes --]

Re: [PATCH 2/3] printk: introduce reset_console_drivers()

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1414 bytes --]

Hi Sergey,

[auto build test ERROR on linus/master]
[also build test ERROR on v4.5-rc1 next-20160129]
[cannot apply to tip/core/locking]
[if your patch is applied to the wrong git tree, please drop us a note to help improving the system]

url:    https://github.com/0day-ci/linux/commits/Sergey-Senozhatsky/printk-introduce-console_reset_on_panic-function/20160131-203605
config: i386-tinyconfig (attached as .config)
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'console_reset_on_panic':
   kernel/printk/printk.c:2426:2: error: implicit declaration of function 'zap_locks' [-Werror=implicit-function-declaration]
     zap_locks();
     ^
>> kernel/printk/printk.c:2427:2: error: implicit declaration of function 'reset_console_drivers' [-Werror=implicit-function-declaration]
     reset_console_drivers();
     ^
   cc1: some warnings being treated as errors

vim +/reset_console_drivers +2427 kernel/printk/printk.c

  2420		console_may_schedule = 0;
  2421		console_unlock();
  2422	}
  2423	
  2424	void console_reset_on_panic(void)
  2425	{
> 2426		zap_locks();
> 2427		reset_console_drivers();
  2428	}
  2429	
  2430	/*

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/octet-stream, Size: 6206 bytes --]

Re: [PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump()

[Sergey Senozhatsky]

On (01/31/16 21:33), Sergey Senozhatsky wrote:
> spin_dump() calls printk() which can attempt to reacquire the
> 'buggy' lock (one of printk's lock, or console device driver lock,
> etc.) and thus spin_dump() will recurse into itself.

how about splitting ->owner_cpu 4 bytes as:

                            |                                   |
  1 byte spin bug recursion | 1 byte spin_dump recursion counter | 2 bytes owner cpu
                            |                                   |

?

so we have 2 bytes to store the lock owner's smp_processor_id().
(I just don't want to extend spin lock with another 4 bytes to
fix the recursion.)


spin_dump() will increment lock's spin_dump recursion counter and decrement it
upon the exit from spin_dump(). if lock's recursion counter is equal to
U8_MAX -- panic() the system, we have recursed spin_dump() into spin_dump()
enough... (U8_MAX recursive printk->spin_dump->printk calls look big enough).

for spin_bug() recursion we don't have to maintain any counter: set
SPIN_BUG_RECURSION bit at the beginning of spin_bug() and clear it at
the end. if the lock already has SPIN_BUG_RECURSION bit set -- panic()
the system.

compile tested only.
will test it tomorrow.

---
 kernel/locking/spinlock_debug.c | 32 +++++++++++++++++++++++++++-----
 1 file changed, 27 insertions(+), 5 deletions(-)

diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..54bcc3b 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -13,6 +13,9 @@
 #include <linux/delay.h>
 #include <linux/export.h>
 
+#define SPIN_DUMP_RECURSION	(1 << 16)
+#define SPIN_BUG_RECURSION	(1 << 31)
+
 void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 			  struct lock_class_key *key)
 {
@@ -26,7 +29,7 @@ void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 	lock->raw_lock = (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
 	lock->magic = SPINLOCK_MAGIC;
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
 }
 
 EXPORT_SYMBOL(__raw_spin_lock_init);
@@ -44,14 +47,26 @@ void __rwlock_init(rwlock_t *lock, const char *name,
 	lock->raw_lock = (arch_rwlock_t) __ARCH_RW_LOCK_UNLOCKED;
 	lock->magic = RWLOCK_MAGIC;
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
 }
 
 EXPORT_SYMBOL(__rwlock_init);
 
+static void spin_recursion_panic(raw_spinlock_t *lock, const char *msg)
+{
+	panic("BUG: lock: %pS %s recursion on CPU#%d, %s/%d\n",
+			lock, msg, raw_smp_processor_id(),
+			current->comm, task_pid_nr(current));
+}
+
 static void spin_dump(raw_spinlock_t *lock, const char *msg)
 {
 	struct task_struct *owner = NULL;
+	u8 recursion_counter = (u8)(lock->owner_cpu >> 16);
+
+	lock->owner_cpu += SPIN_DUMP_RECURSION;
+	if ((recursion_counter + 1) == U8_MAX)
+		spin_recursion_panic(lock, "spin_dump()");
 
 	if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
 		owner = lock->owner;
@@ -63,8 +78,10 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",
 		owner ? task_pid_nr(owner) : -1,
-		lock->owner_cpu);
+		lock->owner_cpu == USHRT_MAX ? -1 : lock->owner_cpu);
 	dump_stack();
+
+	lock->owner_cpu -= SPIN_DUMP_RECURSION;
 }
 
 static void spin_bug(raw_spinlock_t *lock, const char *msg)
@@ -72,7 +89,12 @@ static void spin_bug(raw_spinlock_t *lock, const char *msg)
 	if (!debug_locks_off())
 		return;
 
+	if (lock->owner_cpu & SPIN_BUG_RECURSION)
+		spin_recursion_panic(lock, "spin_bug()");
+
+	lock->owner_cpu |= SPIN_BUG_RECURSION;
 	spin_dump(lock, msg);
+	lock->owner_cpu &= ~SPIN_BUG_RECURSION;
 }
 
 #define SPIN_BUG_ON(cond, lock, msg) if (unlikely(cond)) spin_bug(lock, msg)
@@ -100,7 +122,7 @@ static inline void debug_spin_unlock(raw_spinlock_t *lock)
 	SPIN_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
 }
 
 static void __spin_lock_debug(raw_spinlock_t *lock)
@@ -244,7 +266,7 @@ static inline void debug_write_unlock(rwlock_t *lock)
 	RWLOCK_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
 }
 
 #if 0		/* This can cause lockups */
-- 
2.7.0.75.g3ee1e0f

Re: [PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump()

[Sergey Senozhatsky]

On (02/02/16 01:14), Sergey Senozhatsky wrote:
> how about splitting ->owner_cpu 4 bytes as:
> 
>                             |                                   |
>   1 byte spin bug recursion | 1 byte spin_dump recursion counter | 2 bytes owner cpu
>                             |                                   |

after some thinking... no, this will not do the trick. one byte is not
enough for recursion counter -- we can have 8K CPUs on the system and
8K-1 cpus can "suspect a lockup". so, a slightly different approach:

1) split ->owner_cpu 4 bytes in struct raw_spinlock
 unsigned short owner_cpu;
 unsigned short recursion;

I still can use only ->owner_cpu, but it's much easier when they are
apart. with a single 4 byte variable for recursion and cpu owner we
need to take extra care of higher 2 bytes every time we touch the
->owner_cpu

CPU1							CPU2
spin_dump
 ->owner_cpu[recursion_bits] += 1			spin_unlock
 							->owner_cpu = -1
						^^^ need to store cpu_id in
						lower 2 bytes, avoiding
						overwrite of 2 higher bytes, etc.
 ->owner_cpu[recursion_bits] -= 1

which is fragile and ugly.


2) ->recursion has most significant bit for spin_bug() bit, the
remaining bits are for recursion counter.

spin_bug() does
	set SPIN_BUG bit (most significant bit)
	spin_dump
	clear SPIN_BUG bit

spin_dump() does
	read SPIN_BUG bit
	inc ->recursion
	do_checks
	printk...
	dec ->recursion

and the do_checks is:

-- "if the SPIN_BUG bit is set AND recursion counter > NR_CPUS"
   then we have a spin_bug() recursion on at least one of the CPUs
   and we need to panic the system

printk
 spin_lock
  spin_bug
   spin_dump
    printk
     spin_lock
      spin_bug
       spin_dump
        ...


-- "if the SPIN_BUG bit is clear AND recursion counter >= SHRT_MAX/2"
   then we have spin_dump() recursion (16K calls.. can be bigger) and
   we need to panic the system. if recursion counter < SHRT_MAX/2 - keep
   going. "suspected soft lockup" potentially can be resolved (the lock
   owner unlocks the lock), so we need to have a big enough limit before
   we declare panic().

printk
 spin_lock
  spin_dump
   printk
    spin_lock
     spin_dump
      ...

I guess I'll I'll start a new thread with the next submission, to
refresh it.

RFC, any opinions are appreciated.
not yet tested code.

---
 include/linux/spinlock_types.h  |  4 +++-
 kernel/locking/spinlock_debug.c | 40 +++++++++++++++++++++++++++++++++++++---
 2 files changed, 40 insertions(+), 4 deletions(-)

diff --git a/include/linux/spinlock_types.h b/include/linux/spinlock_types.h
index 73548eb..c8f6b56 100644
--- a/include/linux/spinlock_types.h
+++ b/include/linux/spinlock_types.h
@@ -23,7 +23,9 @@ typedef struct raw_spinlock {
 	unsigned int break_lock;
 #endif
 #ifdef CONFIG_DEBUG_SPINLOCK
-	unsigned int magic, owner_cpu;
+	unsigned int magic;
+	unsigned short owner_cpu;
+	unsigned short recursion;
 	void *owner;
 #endif
 #ifdef CONFIG_DEBUG_LOCK_ALLOC
diff --git a/kernel/locking/spinlock_debug.c b/kernel/locking/spinlock_debug.c
index 0374a59..f838fe9 100644
--- a/kernel/locking/spinlock_debug.c
+++ b/kernel/locking/spinlock_debug.c
@@ -13,6 +13,8 @@
 #include <linux/delay.h>
 #include <linux/export.h>
 
+#define SPIN_BUG_RECURSION		(1 << 15)
+
 void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 			  struct lock_class_key *key)
 {
@@ -26,7 +28,8 @@ void __raw_spin_lock_init(raw_spinlock_t *lock, const char *name,
 	lock->raw_lock = (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
 	lock->magic = SPINLOCK_MAGIC;
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
+	lock->recursion = 0;
 }
 
 EXPORT_SYMBOL(__raw_spin_lock_init);
@@ -49,9 +52,31 @@ void __rwlock_init(rwlock_t *lock, const char *name,
 
 EXPORT_SYMBOL(__rwlock_init);
 
+static void spin_recursion_panic(raw_spinlock_t *lock, const char *msg)
+{
+	panic("lock: %pS %s recursion on CPU#%d, %s/%d\n",
+			lock, msg, raw_smp_processor_id(),
+			current->comm, task_pid_nr(current));
+}
+
 static void spin_dump(raw_spinlock_t *lock, const char *msg)
 {
 	struct task_struct *owner = NULL;
+	unsigned short dump_counter;
+	bool spin_bug;
+
+	spin_bug = lock->recursion & SPIN_BUG_RECURSION;
+	dump_counter = lock->recursion & SHRT_MAX;
+	smp_rmb();
+
+	smp_wmb();
+	lock->recursion += 1;
+	dump_counter++;
+
+	if (spin_bug && dump_counter > NR_CPUS) /* num_online_cpus() */
+		spin_recursion_panic(lock, "spin_bug()");
+	if (dump_counter >= (SHRT_MAX >> 1))
+		spin_recursion_panic(lock, "spin_dump()");
 
 	if (lock->owner && lock->owner != SPINLOCK_OWNER_INIT)
 		owner = lock->owner;
@@ -63,8 +88,11 @@ static void spin_dump(raw_spinlock_t *lock, const char *msg)
 		lock, lock->magic,
 		owner ? owner->comm : "<none>",
 		owner ? task_pid_nr(owner) : -1,
-		lock->owner_cpu);
+		lock->owner_cpu == USHRT_MAX ? -1 : lock->owner_cpu);
 	dump_stack();
+
+	smp_wmb();
+	lock->recursion -= 1;
 }
 
 static void spin_bug(raw_spinlock_t *lock, const char *msg)
@@ -72,7 +100,13 @@ static void spin_bug(raw_spinlock_t *lock, const char *msg)
 	if (!debug_locks_off())
 		return;
 
+	smp_wmb();
+	lock->recursion |= SPIN_BUG_RECURSION;
+
 	spin_dump(lock, msg);
+
+	smp_wmb();
+	lock->recursion &= ~SPIN_BUG_RECURSION;
 }
 
 #define SPIN_BUG_ON(cond, lock, msg) if (unlikely(cond)) spin_bug(lock, msg)
@@ -100,7 +134,7 @@ static inline void debug_spin_unlock(raw_spinlock_t *lock)
 	SPIN_BUG_ON(lock->owner_cpu != raw_smp_processor_id(),
 							lock, "wrong CPU");
 	lock->owner = SPINLOCK_OWNER_INIT;
-	lock->owner_cpu = -1;
+	lock->owner_cpu = USHRT_MAX;
 }
 
 static void __spin_lock_debug(raw_spinlock_t *lock)
-- 
2.7.0