[PATCH] watchdog: print all locks on a softlock

[PATCH] watchdog: print all locks on a softlock

[Eric Paris]

If the CPU hits a softlockup this patch will also have it print the
information about all locks being held on the system.  This might help
determine if a lock is being held too long leading to this problem.

Signed-off-by: Eric Paris <eparis@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Don Zickus <dzickus@redhat.com>
Cc: Michal Hocko <mhocko@suse.cz>
Cc: Ben Zhang <benzh@chromium.org>
---
 kernel/watchdog.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index 516203e..a027240 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -322,6 +322,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
 			current->comm, task_pid_nr(current));
 		print_modules();
 		print_irqtrace_events(current);
+		debug_show_all_locks();
 		if (regs)
 			show_regs(regs);
 		else
-- 
1.9.0

Re: [PATCH] watchdog: print all locks on a softlock

[Don Zickus]

On Thu, May 01, 2014 at 02:55:35PM -0400, Eric Paris wrote:
> If the CPU hits a softlockup this patch will also have it print the
> information about all locks being held on the system.  This might help
> determine if a lock is being held too long leading to this problem.

I am not sure this helps you.  A softlockup is the result of pre-emption
disabled, ie the scheduler not being called after 60 seconds.  Holding a
lock does not disable pre-emption usually.  So I don't think this is going
to add anything.

Are you trying to debug a hung task?  The the hung_task thread checks to
see if a task hasn't scheduled in 2 minutes or so.  That could be the
result of long lock (but that output already dumps the lockdep stuff).

Cheers,
Don

> 
> Signed-off-by: Eric Paris <eparis@redhat.com>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Don Zickus <dzickus@redhat.com>
> Cc: Michal Hocko <mhocko@suse.cz>
> Cc: Ben Zhang <benzh@chromium.org>
> ---
>  kernel/watchdog.c | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/kernel/watchdog.c b/kernel/watchdog.c
> index 516203e..a027240 100644
> --- a/kernel/watchdog.c
> +++ b/kernel/watchdog.c
> @@ -322,6 +322,7 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
>  			current->comm, task_pid_nr(current));
>  		print_modules();
>  		print_irqtrace_events(current);
> +		debug_show_all_locks();
>  		if (regs)
>  			show_regs(regs);
>  		else
> -- 
> 1.9.0
> 

Re: [PATCH] watchdog: print all locks on a softlock

[Frederic Weisbecker]

On Thu, May 01, 2014 at 03:17:20PM -0400, Don Zickus wrote:
> On Thu, May 01, 2014 at 02:55:35PM -0400, Eric Paris wrote:
> > If the CPU hits a softlockup this patch will also have it print the
> > information about all locks being held on the system.  This might help
> > determine if a lock is being held too long leading to this problem.
> 
> I am not sure this helps you.  A softlockup is the result of pre-emption
> disabled, ie the scheduler not being called after 60 seconds.  Holding a
> lock does not disable pre-emption usually.  So I don't think this is going
> to add anything.
> 
> Are you trying to debug a hung task?  The the hung_task thread checks to
> see if a task hasn't scheduled in 2 minutes or so.  That could be the
> result of long lock (but that output already dumps the lockdep stuff).

There may be some deadlocks that lockdep doesn't detect yet. 2 example:

1) spinlock <-> IPI dependency


        CPU 0                                            CPU 1
        --------------------------------------------------------
        spin_lock_irq(A)
        smp_send_function_single_async(CPU 1, func)
                                                         //IPI
                                                         func {
                                                            spin_lock(1)
                                                         }

But this should be resolved with a virtual lock on the IPI functions.
I should try that.

2) rwlock <-> IPI

        CPU 0                                            CPU 1
        --------------------------------------------------------
        read_lock(A)
                                                         write_lock_irq(A)
        smp_send_function_single(CPU 1, func)
                                                         //IPI never happens

This one is much trickier.

Anyway those are the only scenario I know of but there may be more. When possible
we want to extend lockdep to detect new scenarios of deadlock but we don't have the
guarantee that it can detect everything.

So, could be useful...

Re: [PATCH] watchdog: print all locks on a softlock

[Frederic Weisbecker]

2014-05-01 22:09 GMT+02:00 Frederic Weisbecker <fweisbec@gmail.com>:
> On Thu, May 01, 2014 at 03:17:20PM -0400, Don Zickus wrote:
>> On Thu, May 01, 2014 at 02:55:35PM -0400, Eric Paris wrote:
>> > If the CPU hits a softlockup this patch will also have it print the
>> > information about all locks being held on the system.  This might help
>> > determine if a lock is being held too long leading to this problem.
>>
>> I am not sure this helps you.  A softlockup is the result of pre-emption
>> disabled, ie the scheduler not being called after 60 seconds.  Holding a
>> lock does not disable pre-emption usually.  So I don't think this is going
>> to add anything.
>>
>> Are you trying to debug a hung task?  The the hung_task thread checks to
>> see if a task hasn't scheduled in 2 minutes or so.  That could be the
>> result of long lock (but that output already dumps the lockdep stuff).
>
> There may be some deadlocks that lockdep doesn't detect yet. 2 example:
>
> 1) spinlock <-> IPI dependency
>
>
>         CPU 0                                            CPU 1
>         --------------------------------------------------------
>         spin_lock_irq(A)
>         smp_send_function_single_async(CPU 1, func)
>                                                          //IPI
>                                                          func {
>                                                             spin_lock(1)
>                                                          }
>
> But this should be resolved with a virtual lock on the IPI functions.
> I should try that.

So actually this one above shouldn't be a problem because the _async
version doesn't wait for the IPI to complete. But the below still
looks possible.

>
> 2) rwlock <-> IPI
>
>         CPU 0                                            CPU 1
>         --------------------------------------------------------
>         read_lock(A)
>                                                          write_lock_irq(A)
>         smp_send_function_single(CPU 1, func)
>                                                          //IPI never happens
>
> This one is much trickier.
>
> Anyway those are the only scenario I know of but there may be more. When possible
> we want to extend lockdep to detect new scenarios of deadlock but we don't have the
> guarantee that it can detect everything.
>
> So, could be useful...

Re: [PATCH] watchdog: print all locks on a softlock

[Don Zickus]

On Thu, May 01, 2014 at 10:09:01PM +0200, Frederic Weisbecker wrote:
> On Thu, May 01, 2014 at 03:17:20PM -0400, Don Zickus wrote:
> > On Thu, May 01, 2014 at 02:55:35PM -0400, Eric Paris wrote:
> > > If the CPU hits a softlockup this patch will also have it print the
> > > information about all locks being held on the system.  This might help
> > > determine if a lock is being held too long leading to this problem.
> > 
> > I am not sure this helps you.  A softlockup is the result of pre-emption
> > disabled, ie the scheduler not being called after 60 seconds.  Holding a
> > lock does not disable pre-emption usually.  So I don't think this is going
> > to add anything.
> > 
> > Are you trying to debug a hung task?  The the hung_task thread checks to
> > see if a task hasn't scheduled in 2 minutes or so.  That could be the
> > result of long lock (but that output already dumps the lockdep stuff).
> 
> There may be some deadlocks that lockdep doesn't detect yet. 2 example:
> 
> 1) spinlock <-> IPI dependency
> 
> 
>         CPU 0                                            CPU 1
>         --------------------------------------------------------
>         spin_lock_irq(A)
>         smp_send_function_single_async(CPU 1, func)
>                                                          //IPI
>                                                          func {
>                                                             spin_lock(1)
>                                                          }
> 
> But this should be resolved with a virtual lock on the IPI functions.
> I should try that.
> 
> 2) rwlock <-> IPI
> 
>         CPU 0                                            CPU 1
>         --------------------------------------------------------
>         read_lock(A)
>                                                          write_lock_irq(A)
>         smp_send_function_single(CPU 1, func)
>                                                          //IPI never happens

The hardlockup detector would go off here.  And dumping all the cpus in
the system (something we don't do today), would show this scenario.  I see
this scenario a lot during page flushes on RHEL (a lot being once every
other month or so).

Cheers,
Don

> 
> This one is much trickier.
> 
> Anyway those are the only scenario I know of but there may be more. When possible
> we want to extend lockdep to detect new scenarios of deadlock but we don't have the
> guarantee that it can detect everything.
> 
> So, could be useful...