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

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

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(_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(>lock, flags)
__up
  wake_up_process
try_to_wake_up
  raw_spin_lock_irqsave(>pi_lock)
__spin_lock_debug
  spin_dump // once it happened
printk
  console_trylock
raw_spin_lock_irqsave(>lock, flags)

<=== DEADLOCK

cpu1

printk
  console_trylock
raw_spin_lock_irqsave(>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 
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 
---
 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 == _sem.lock) ||
+   (lock == _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

[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 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(>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 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(_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(>lock, flags)
__up
  wake_up_process
try_to_wake_up
  raw_spin_lock_irqsave(>pi_lock)
__spin_lock_debug
  spin_dump // once it happened
printk
  console_trylock
raw_spin_lock_irqsave(>lock, flags)

<=== DEADLOCK

cpu1

printk
  console_trylock
raw_spin_lock_irqsave(>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 
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 
---
 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 == _sem.lock) ||
+   (lock == _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

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

[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(>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 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(>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:16), Sergey Senozhatsky wrote:
> 
>  http://marc.info/?l=linux-kernel=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

[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=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=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(_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=145404023915268

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

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

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

[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(>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 s
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

[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

[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

[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

[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(>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 17:13), Byungchul Park wrote:
[..]
> > > > int down_trylock(struct semaphore *sem)
> > > > {
> > > > unsigned long flags;
> > > > int count;
> > > > 
> > > > raw_spin_lock_irqsave(>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(>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

[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(>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(>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(>lock, flags);
>   count = sem->count - 1;
>   if (likely(count >= 0))
>   sem->count = count;
>   raw_spin_unlock_irqrestore(>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(>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(>lock);
>   timeout = schedule_timeout(timeout);
>   raw_spin_lock_irq(>lock);
>   if (waiter.up)
>   return 0;
>   }
>   ...
>   }
>   raw_spin_unlock_irqrestore(>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.

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=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=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(_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=145404023915268

-ss

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

[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

[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(>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:16), Sergey Senozhatsky wrote:
> 
>  http://marc.info/?l=linux-kernel=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

[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(>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 s
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 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(>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(>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(>lock, flags);
>   count = sem->count - 1;
>   if (likely(count >= 0))
>   sem->count = count;
>   raw_spin_unlock_irqrestore(>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(>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(>lock);
>   timeout = schedule_timeout(timeout);
>   raw_spin_lock_irq(>lock);
>   if (waiter.up)
>   return 0;
>   }
>   ...
>   }
>   raw_spin_unlock_irqrestore(>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.

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

[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(>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(_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(>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 s
> 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 

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

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

[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(>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(>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(>lock, flags);
count = sem->count - 1;
if (likely(count >= 0))
sem->count = count;
raw_spin_unlock_irqrestore(>lock, flags);


or down()/down_common()


raw_spin_lock_irqsave(>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(>lock);
timeout = schedule_timeout(timeout);
raw_spin_lock_irq(>lock);
if (waiter.up)
return 0;
}
...
}
raw_spin_unlock_irqrestore(>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]

> From: Sergey Senozhatsky [mailto:sergey.senozhatsky.w...@gmail.com]
> Sent: Thursday, January 28, 2016 11:38 AM
> To: Byungchul Park
> Cc: a...@linux-foundation.org; mi...@kernel.org; linux-
> ker...@vger.kernel.org; akinobu.m...@gmail.com; j...@suse.cz;
> torva...@linux-foundation.org; pe...@hurleysoftware.com;
> sergey.senozhatsky.w...@gmail.com; sergey.senozhat...@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(>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(>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 
> > > ---
> > >  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 pe...@hurleysoftware.com
> +cc sergey.senozhatsky.w...@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(>lock, flags);   <<  um...
count = sem->count - 1;
if (likely(count >= 0))
sem->count = count;
raw_spin_unlock_irqrestore(>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 
> > ---
> >  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]

+cc pe...@hurleysoftware.com
+cc sergey.senozhatsky.w...@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 
> 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 
> ---
>  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 
> 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 
> ---
>  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
> 

[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 
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 
---
 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.p...@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.p...@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

[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(>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(>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(>lock, flags);
count = sem->count - 1;
if (likely(count >= 0))
sem->count = count;
raw_spin_unlock_irqrestore(>lock, flags);


or down()/down_common()


raw_spin_lock_irqsave(>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(>lock);
timeout = schedule_timeout(timeout);
raw_spin_lock_irq(>lock);
if (waiter.up)
return 0;
}
...
}
raw_spin_unlock_irqrestore(>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

[Sergey Senozhatsky]

Hello,

On (01/28/16 10:42), Byungchul Park wrote:
> +cc pe...@hurleysoftware.com
> +cc sergey.senozhatsky.w...@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(>lock, flags);   <<  um...
count = sem->count - 1;
if (likely(count >= 0))
sem->count = count;
raw_spin_unlock_irqrestore(>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 
> > ---
> >  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]

+cc pe...@hurleysoftware.com
+cc sergey.senozhatsky.w...@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.p...@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.p...@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]

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

> From: Sergey Senozhatsky [mailto:sergey.senozhatsky.w...@gmail.com]
> Sent: Thursday, January 28, 2016 11:38 AM
> To: Byungchul Park
> Cc: a...@linux-foundation.org; mi...@kernel.org; linux-
> ker...@vger.kernel.org; akinobu.m...@gmail.com; j...@suse.cz;
> torva...@linux-foundation.org; pe...@hurleysoftware.com;
> sergey.senozhatsky.w...@gmail.com; sergey.senozhat...@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(>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(>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.p...@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
> >

[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.p...@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.p...@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