Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1318907 > unrolled thread

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

Back to article view | Back to linux.kernel

Contents

  [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-27 13:10 +0100
    Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the  debug code Peter Hurley <peter@hurleysoftware.com> - 2016-01-27 23:50 +0100
      Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-28 08:20 +0100
        Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 09:20 +0100
    Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-28 03:00 +0100
      Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-28 03:40 +0100
        RE: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the debug code "byungchul.park" <byungchul.park@lge.com> - 2016-01-28 06:00 +0100
          Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-28 07:10 +0100
            Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-28 09:30 +0100
              Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-28 11:50 +0100
                Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-28 12:00 +0100
                  Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-01-28 16:50 +0100
                    Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the  debug code Peter Hurley <peter@hurleysoftware.com> - 2016-01-29 00:10 +0100
                      Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 01:00 +0100
                        Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 02:00 +0100
                          Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 04:10 +0100
                            Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 05:10 +0100
                              Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 13:20 +0100
                      Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 01:30 +0100
                        Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the  debug code Peter Hurley <peter@hurleysoftware.com> - 2016-01-29 05:40 +0100
                          Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 06:30 +0100
                            Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in the  debug code Peter Hurley <peter@hurleysoftware.com> - 2016-01-29 06:50 +0100
                              Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 07:20 +0100
                                Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 07:40 +0100
                                  Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-31 13:30 +0100
                                    [PATCH 2/3] printk: introduce reset_console_drivers() Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-31 13:40 +0100
                                      Re: [PATCH 2/3] printk: introduce reset_console_drivers() kbuild test robot <lkp@intel.com> - 2016-01-31 13:50 +0100
                                    [PATCH 1/3] printk: introduce console_reset_on_panic() function Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-31 13:40 +0100
                                      [PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump() Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-31 13:40 +0100
                                        Re: [PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump() Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-02-01 17:20 +0100
                                          Re: [PATCH 3/3] spinlock_debug: panic on recursive lock spin_dump() Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-02-02 09:00 +0100
                                      Re: [PATCH 1/3] printk: introduce console_reset_on_panic() function kbuild test robot <lkp@intel.com> - 2016-01-31 13:50 +0100
                        Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 08:00 +0100
                          Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-01-29 08:20 +0100
                            Re: [PATCH v4] lib/spinlock_debug.c: prevent a recursive cycle in  the debug code Byungchul Park <byungchul.park@lge.com> - 2016-01-29 09:20 +0100

Page 1 of 2  [1] 2  Next page →

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

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

[toc] | [next] | [standalone]

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

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
> 

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

+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

[toc] | [prev] | [next] | [standalone]

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

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
> 

[toc] | [prev] | [next] | [standalone]

#1320295

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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
> 

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

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

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

[toc] | [prev] | [next] | [standalone]

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web