Skip to contentSkip to conversation

lockdep: Show description of lockdep problems

GIT PULL In review Steven Rostedt 4 participants 26 messages Apr 21, 2011 – Apr 22, 2011

lore
Share & tools
lore

Steven Rostedt

author
#0 lore raw

Ingo,

Please pull the latest tip/lockdep/devel tree, which can be found at:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/lockdep/devel

Steven Rostedt (7):
lockdep: Print a nice description of an irq locking issue
lockdep: Print a nice description of normal deadlocks
lockdep: Print a nice description of simple deadlock
lockdep: Printk nice description for irq inversion bug
lockdep: Replace bad path error message with something sane
lockdep: Print a nice description of simple irq inversion
lockdep: Remove cmpxchg to update nr_chain_hlocks

----

 kernel/lockdep.c |  206 +++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 files changed, 195 insertions(+), 11 deletions(-)
author
#1 lore raw

PATCH 1/7 lockdep: Print a nice description of an irq locking issue

From: Steven Rostedt <[email protected]>

Locking order inversion due to interrupts is a subtle problem. When a locking inversion due to interrupts is discovered by lockdep, it currently reports something like this:

[ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ]

And then writes the locks that are involved as well as back traces. But several developers are confused by what a HARDIRQ->safe to unsafe issue is all about, and sometimes even blow it off as a bug in lockdep. As it is not obvious when lockdep describes this about a lock that is never taken in interrupt context.

After explaining the problems that lockdep is reporting, I decided to add a description of the problem in visual form. Now the following is shown:

---
other info that might help us debug this:

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockA);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

---
other info that might help us debug this:

Chain exists of:
  &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockC);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   70 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 70 insertions(+), 0 deletions(-)
kernel/lockdep.c +70 -0
index 0d2058d..bb77c030 100644
@@ -490,6 +490,18 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
 	usage[i] = '\0';
 }
 
+static int __print_lock_name(struct lock_class *class)
+{
+	char str[KSYM_NAME_LEN];
+	const char *name;
+
+	name = class->name;
+	if (!name)
+		name = __get_key_name(class->key, str);
+
+	return printk("%s", name);
+}
+
 static void print_lock_name(struct lock_class *class)
 {
 	char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];

@@ -1325,6 +1337,62 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 	return;
 }
 
+static void
+print_irq_lock_scenario(struct lock_list *safe_entry,
+			struct lock_list *unsafe_entry,
+			struct held_lock *prev,
+			struct held_lock *next)
+{
+	struct lock_class *safe_class = safe_entry->class;
+	struct lock_class *unsafe_class = unsafe_entry->class;
+	struct lock_class *middle_class = hlock_class(prev);
+
+	if (middle_class == safe_class)
+		middle_class = hlock_class(next);
+
+	/*
+	 * A direct locking problem where unsafe_class lock is taken
+	 * directly by safe_class lock, then all we need to show
+	 * is the deadlock scenario, as it is obvious that the
+	 * unsafe lock is taken under the safe lock.
+	 *
+	 * But if there is a chain instead, where the safe lock takes
+	 * an intermediate lock (middle_class) where this lock is
+	 * not the same as the safe lock, then the lock chain is
+	 * used to describe the problem. Otherwise we would need
+	 * to show a different CPU case for each link in the chain
+	 * from the safe_class lock to the unsafe_class lock.
+	 */
+	if (middle_class != unsafe_class) {
+		printk("Chain exists of:\n  ");
+		__print_lock_name(safe_class);
+		printk(" --> ");
+		__print_lock_name(middle_class);
+		printk(" --> ");
+		__print_lock_name(unsafe_class);
+		printk("\n\n");
+	}
+
+	printk(" Possible interrupt unsafe locking scenario:\n\n");
+	printk("       CPU0                    CPU1\n");
+	printk("       ----                    ----\n");
+	printk("  lock(");
+	__print_lock_name(unsafe_class);
+	printk(");\n");
+	printk("                               local_irq_disable();\n");
+	printk("                               lock(");
+	__print_lock_name(safe_class);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(middle_class);
+	printk(");\n");
+	printk("  <Interrupt>\n");
+	printk("    lock(");
+	__print_lock_name(safe_class);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 static int
 print_bad_irq_dependency(struct task_struct *curr,
 			 struct lock_list *prev_root,

@@ -1376,6 +1444,8 @@ print_bad_irq_dependency(struct task_struct *curr,
 	print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
 	printk("\nother info that might help us debug this:\n\n");
+	print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nthe dependencies between %s-irq-safe lock", irqclass);
Signature · 1 line
1.7.2.3
#2 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 23 lines · Steven Rostedt

 ---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

 ---
other info that might help us debug this:

Chain exists of:

 &rq->lock --> lockA --> lockC

 Possible interrupt unsafe locking scenario:

      CPU0                    CPU1
      ----                    ---- lock(lockC);
                              local_irq_disable(); lock(&rq->lock); lock(lockA); <Interrupt>
   lock(&rq->lock);

Quoted 1 line

 *** DEADLOCK ***

But this is not a real deadlock, right? Or maybe you can teach me :)

I just assume your scenario should show a more real one, But for a possible irq-dependence deadlock, it seems not easy to find out.

Thanks,
Yong

Quoted 112 lines
Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/lockdep.c |   70 ++++++++++++++++++++++++++++++++++++++++++++++++++++++

 1 files changed, 70 insertions(+), 0 deletions(-)
kernel/lockdep.c +68 -0
index 0d2058d..bb77c030 100644
@@ -490,6 +490,18 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
        usage[i] = '\0';
  }
 
+static int __print_lock_name(struct lock_class *class)
+{
+       char str[KSYM_NAME_LEN];
+       const char *name;
+
+       name = class->name;
+       if (!name)
+               name = __get_key_name(class->key, str);
+
+       return printk("%s", name);
+}
+
  static void print_lock_name(struct lock_class *class)
  {
        char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];

@@ -1325,6 +1337,62 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
        return;
  }
 
+static void
+print_irq_lock_scenario(struct lock_list *safe_entry,
+                       struct lock_list *unsafe_entry,
+                       struct held_lock *prev,
+                       struct held_lock *next)
+{
+       struct lock_class *safe_class = safe_entry->class;
+       struct lock_class *unsafe_class = unsafe_entry->class;
+       struct lock_class *middle_class = hlock_class(prev);
+
+       if (middle_class == safe_class)
+               middle_class = hlock_class(next);
+
+       /*
+        * A direct locking problem where unsafe_class lock is taken
+        * directly by safe_class lock, then all we need to show
+        * is the deadlock scenario, as it is obvious that the
+        * unsafe lock is taken under the safe lock.
+        *
+        * But if there is a chain instead, where the safe lock takes
+        * an intermediate lock (middle_class) where this lock is
+        * not the same as the safe lock, then the lock chain is
+        * used to describe the problem. Otherwise we would need
+        * to show a different CPU case for each link in the chain
+        * from the safe_class lock to the unsafe_class lock.
+        */
+       if (middle_class != unsafe_class) {
+               printk("Chain exists of:\n  ");
+               __print_lock_name(safe_class);
+               printk(" --> ");
+               __print_lock_name(middle_class);
+               printk(" --> ");
+               __print_lock_name(unsafe_class);
+               printk("\n\n");
+       }
+
+       printk(" Possible interrupt unsafe locking scenario:\n\n");
+       printk("       CPU0                    CPU1\n");
+       printk("       ----                    ----\n");
+       printk("  lock(");
+       __print_lock_name(unsafe_class);
+       printk(");\n");
+       printk("                               local_irq_disable();\n");
+       printk("                               lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("                               lock(");
+       __print_lock_name(middle_class);
+       printk(");\n");
+       printk("  <Interrupt>\n");
+       printk("    lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("\n *** DEADLOCK ***\n\n");
+}
+

 static int
 print_bad_irq_dependency(struct task_struct *curr, struct lock_list *prev_root,

kernel/lockdep.c +2 -1
@@ -1376,6 +1444,8 @@ print_bad_irq_dependency(struct task_struct *curr,
        print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
        printk("\nother info that might help us debug this:\n\n");
+       print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+
        lockdep_print_held_locks(curr);
 
        printk("\nthe dependencies between %s-irq-safe lock", irqclass);
--

1.7.2.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Signature · 1 line
Only stand for myself
#3 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

In reply to Steven Rostedt
Quoted 23 lines · Steven Rostedt

 ---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

 ---
other info that might help us debug this:

Chain exists of:

 &rq->lock --> lockA --> lockC

 Possible interrupt unsafe locking scenario:

      CPU0                    CPU1
      ----                    ---- lock(lockC);
                              local_irq_disable(); lock(&rq->lock); lock(lockA); <Interrupt>
   lock(&rq->lock);

Quoted 1 line

 *** DEADLOCK ***

Or we could show this:

Chain exists of:

&rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

CPU0 CPU1 CPU2
---- ---- ----

 lock(lockC);
                              local_irq_disable();
                              lock(&rq->lock);            lock(lockA);
                              lock(lockA);                   lock(lockC);

<Interrupt>
lock(&rq->lock);

*** DEADLOCK ***

Thanks,
Yong

Quoted 112 lines
Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/lockdep.c |   70 ++++++++++++++++++++++++++++++++++++++++++++++++++++++

 1 files changed, 70 insertions(+), 0 deletions(-)
kernel/lockdep.c +68 -0
index 0d2058d..bb77c030 100644
@@ -490,6 +490,18 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
        usage[i] = '\0';
  }
 
+static int __print_lock_name(struct lock_class *class)
+{
+       char str[KSYM_NAME_LEN];
+       const char *name;
+
+       name = class->name;
+       if (!name)
+               name = __get_key_name(class->key, str);
+
+       return printk("%s", name);
+}
+
  static void print_lock_name(struct lock_class *class)
  {
        char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];

@@ -1325,6 +1337,62 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
        return;
  }
 
+static void
+print_irq_lock_scenario(struct lock_list *safe_entry,
+                       struct lock_list *unsafe_entry,
+                       struct held_lock *prev,
+                       struct held_lock *next)
+{
+       struct lock_class *safe_class = safe_entry->class;
+       struct lock_class *unsafe_class = unsafe_entry->class;
+       struct lock_class *middle_class = hlock_class(prev);
+
+       if (middle_class == safe_class)
+               middle_class = hlock_class(next);
+
+       /*
+        * A direct locking problem where unsafe_class lock is taken
+        * directly by safe_class lock, then all we need to show
+        * is the deadlock scenario, as it is obvious that the
+        * unsafe lock is taken under the safe lock.
+        *
+        * But if there is a chain instead, where the safe lock takes
+        * an intermediate lock (middle_class) where this lock is
+        * not the same as the safe lock, then the lock chain is
+        * used to describe the problem. Otherwise we would need
+        * to show a different CPU case for each link in the chain
+        * from the safe_class lock to the unsafe_class lock.
+        */
+       if (middle_class != unsafe_class) {
+               printk("Chain exists of:\n  ");
+               __print_lock_name(safe_class);
+               printk(" --> ");
+               __print_lock_name(middle_class);
+               printk(" --> ");
+               __print_lock_name(unsafe_class);
+               printk("\n\n");
+       }
+
+       printk(" Possible interrupt unsafe locking scenario:\n\n");
+       printk("       CPU0                    CPU1\n");
+       printk("       ----                    ----\n");
+       printk("  lock(");
+       __print_lock_name(unsafe_class);
+       printk(");\n");
+       printk("                               local_irq_disable();\n");
+       printk("                               lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("                               lock(");
+       __print_lock_name(middle_class);
+       printk(");\n");
+       printk("  <Interrupt>\n");
+       printk("    lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("\n *** DEADLOCK ***\n\n");
+}
+

 static int
 print_bad_irq_dependency(struct task_struct *curr, struct lock_list *prev_root,

kernel/lockdep.c +2 -1
@@ -1376,6 +1444,8 @@ print_bad_irq_dependency(struct task_struct *curr,
        print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
        printk("\nother info that might help us debug this:\n\n");
+       print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+
        lockdep_print_held_locks(curr);
 
        printk("\nthe dependencies between %s-irq-safe lock", irqclass);
--

1.7.2.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Signature · 1 line
Only stand for myself
#4 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 28 lines · Yong Zhang
Quoted 23 lines · Steven Rostedt

 ---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

 ---
other info that might help us debug this:

Chain exists of:

 &rq->lock --> lockA --> lockC

 Possible interrupt unsafe locking scenario:

      CPU0                    CPU1
      ----                    ---- lock(lockC);
                              local_irq_disable(); lock(&rq->lock); lock(lockA); <Interrupt>
   lock(&rq->lock);

Quoted 1 line

 *** DEADLOCK ***

Or we could show this:

Chain exists of:
Quoted 8 lines

&rq->lock --> lockA --> lockC

 Possible interrupt unsafe locking scenario:

     CPU0                    CPU1                           CPU2 ----                    ----                                     ---- lock(lockC);
                             local_irq_disable();

Forget
local_irq_disable(); here :)

Quoted 128 lines

                             lock(&rq->lock);            lock(lockA); lock(lockA);                   lock(lockC); <Interrupt>
  lock(&rq->lock);

 *** DEADLOCK ***

Thanks,
Yong

Quoted 106 lines
Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/lockdep.c |   70 ++++++++++++++++++++++++++++++++++++++++++++++++++++++

 1 files changed, 70 insertions(+), 0 deletions(-)
kernel/lockdep.c +68 -0
index 0d2058d..bb77c030 100644
@@ -490,6 +490,18 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
        usage[i] = '\0';
  }
 
+static int __print_lock_name(struct lock_class *class)
+{
+       char str[KSYM_NAME_LEN];
+       const char *name;
+
+       name = class->name;
+       if (!name)
+               name = __get_key_name(class->key, str);
+
+       return printk("%s", name);
+}
+
  static void print_lock_name(struct lock_class *class)
  {
        char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];

@@ -1325,6 +1337,62 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
        return;
  }
 
+static void
+print_irq_lock_scenario(struct lock_list *safe_entry,
+                       struct lock_list *unsafe_entry,
+                       struct held_lock *prev,
+                       struct held_lock *next)
+{
+       struct lock_class *safe_class = safe_entry->class;
+       struct lock_class *unsafe_class = unsafe_entry->class;
+       struct lock_class *middle_class = hlock_class(prev);
+
+       if (middle_class == safe_class)
+               middle_class = hlock_class(next);
+
+       /*
+        * A direct locking problem where unsafe_class lock is taken
+        * directly by safe_class lock, then all we need to show
+        * is the deadlock scenario, as it is obvious that the
+        * unsafe lock is taken under the safe lock.
+        *
+        * But if there is a chain instead, where the safe lock takes
+        * an intermediate lock (middle_class) where this lock is
+        * not the same as the safe lock, then the lock chain is
+        * used to describe the problem. Otherwise we would need
+        * to show a different CPU case for each link in the chain
+        * from the safe_class lock to the unsafe_class lock.
+        */
+       if (middle_class != unsafe_class) {
+               printk("Chain exists of:\n  ");
+               __print_lock_name(safe_class);
+               printk(" --> ");
+               __print_lock_name(middle_class);
+               printk(" --> ");
+               __print_lock_name(unsafe_class);
+               printk("\n\n");
+       }
+
+       printk(" Possible interrupt unsafe locking scenario:\n\n");
+       printk("       CPU0                    CPU1\n");
+       printk("       ----                    ----\n");
+       printk("  lock(");
+       __print_lock_name(unsafe_class);
+       printk(");\n");
+       printk("                               local_irq_disable();\n");
+       printk("                               lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("                               lock(");
+       __print_lock_name(middle_class);
+       printk(");\n");
+       printk("  <Interrupt>\n");
+       printk("    lock(");
+       __print_lock_name(safe_class);
+       printk(");\n");
+       printk("\n *** DEADLOCK ***\n\n");
+}
+

 static int
 print_bad_irq_dependency(struct task_struct *curr, struct lock_list *prev_root,

kernel/lockdep.c +2 -1
@@ -1376,6 +1444,8 @@ print_bad_irq_dependency(struct task_struct *curr,
        print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
        printk("\nother info that might help us debug this:\n\n");
+       print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+
        lockdep_print_held_locks(curr);
 
        printk("\nthe dependencies between %s-irq-safe lock", irqclass);
--

1.7.2.3

Quoted 6 lines

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

--
Only stand for myself

Signature · 1 line
Only stand for myself
author
#5 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

In reply to Yong Zhang
Quoted 34 lines · Yong Zhang
Quoted 20 lines · Steven Rostedt

---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

---
other info that might help us debug this:

Chain exists of:
 &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

      CPU0                    CPU1
      ----                    ----
 lock(lockC);
                              local_irq_disable();
                              lock(&rq->lock);
                              lock(lockA);
Quoted 4 lines

<Interrupt>
lock(&rq->lock);

*** DEADLOCK ***

Or we could show this:

Chain exists of:

&rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

CPU0 CPU1 CPU2
---- ---- ----

Quoted 8 lines
 lock(lockC);
                              local_irq_disable();
                              lock(&rq->lock);            lock(lockA);
                              lock(lockA);                   lock(lockC);

<Interrupt>
lock(&rq->lock);

*** DEADLOCK ***

We could but I prefer not to ;) We have some chains that are 8 locks deep. I really don't want to scatter that entirely across the screen. Hence my "Chain exists.." statement, following an example that any kernel developer can (with a little thinking) see is a possible deadlock.

In fact, this code doesn't even look at the full chain, it only examines 3 locks in the chain, and lets the developer figure out the rest. I could show the entire chain too.

Thanks,

-- Steve

#6 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 42 lines · Steven Rostedt
Quoted 41 lines · Yong Zhang
Quoted 20 lines · Steven Rostedt

---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

---
other info that might help us debug this:

Chain exists of:
 &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

      CPU0                    CPU1
      ----                    ----
 lock(lockC);
                              local_irq_disable();
                              lock(&rq->lock);
                              lock(lockA);
Quoted 4 lines

<Interrupt>
lock(&rq->lock);

*** DEADLOCK ***

Or we could show this:

Chain exists of:

&rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

CPU0 CPU1 CPU2
---- ---- ----

 lock(lockC);
                              local_irq_disable();
                              lock(&rq->lock);            lock(lockA);
                              lock(lockA);                   lock(lockC);

<Interrupt>
lock(&rq->lock);

Quoted 8 lines
Quoted 1 line

*** DEADLOCK ***

We could but I prefer not to ;) We have some chains that are 8 locks deep. I really don't want to scatter that entirely across the screen. Hence my "Chain exists.." statement, following an example that any kernel developer can (with a little thinking) see is a possible deadlock.

Yup :)

Quoted 3 lines

In fact, this code doesn't even look at the full chain, it only examines 3 locks in the chain, and lets the developer figure out the rest.

OK, fair enough.

Quoted 2 lines

I
could show the entire chain too.

Sure :)

Thanks,
Yong

author
#7 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 6 lines · Yong Zhang
Quoted 2 lines · Steven Rostedt

I
could show the entire chain too.

Sure :)

I talked a little about this with Peter Zijlstra on IRC, and we agreed that we'll keep this as is until we notice that kernel developers are still confused with the output.

The more advanced I make this output, the more likely I'll make a mistake and show something that is not what actually happens. I wrote a module to trigger each of these cases and the problems that lockdep can detect grows exponentially as we make the output more specific.

I probably should modify the lockdep selftests to add an option to show the output as well as it triggers errors. This would allow me to make sure the output still works.

But for now, I have other things to work on ;)

-- Steve

#8 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 11 lines · Steven Rostedt
Quoted 6 lines · Yong Zhang
Quoted 2 lines · Steven Rostedt

I
could show the entire chain too.

Sure :)

I talked a little about this with Peter Zijlstra on IRC, and we agreed that we'll keep this as is until we notice that kernel developers are still confused with the output.

OK :)

Quoted 9 lines

The more advanced I make this output, the more likely I'll make a mistake and show something that is not what actually happens. I wrote a module to trigger each of these cases and the problems that lockdep can detect grows exponentially as we make the output more specific.

I probably should modify the lockdep selftests to add an option to show the output as well as it triggers errors. This would allow me to make sure the output still works.

This does make sense to keep things consistent if we have it.

Quoted 2 lines

But for now, I have other things to work on ;)

If you want, you can show more details on your ideas, maybe I could get some time to finish it :)

Thanks,
Yong

Signature · 1 line
Only stand for myself
author
#9 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 5 lines · Yong Zhang
Quoted 3 lines

I probably should modify the lockdep selftests to add an option to show the output as well as it triggers errors. This would allow me to make sure the output still works.

This does make sense to keep things consistent if we have it.

Actually, Peter informed me that we already do this. Just need to boot with debug_locks_verbose=1.

Quoted 6 lines
Quoted 3 lines

But for now, I have other things to work on ;)

If you want, you can show more details on your ideas, maybe I could get some time to finish it :)

Well, I got pretty much what I wanted out for now. I'll probably go and look later. But by all means, if you find other ways to make lockdep more readable. Please, don't let me stop you ;)

-- Steve

#10 lore raw

Re: [PATCH 1/7] lockdep: Print a nice description of an irq locking issue

Quoted 10 lines · Steven Rostedt
Quoted 5 lines · Yong Zhang
Quoted 3 lines

I probably should modify the lockdep selftests to add an option to show the output as well as it triggers errors. This would allow me to make sure the output still works.

This does make sense to keep things consistent if we have it.

Actually, Peter informed me that we already do this. Just need to boot with debug_locks_verbose=1.

Yeah, that's been in lockdep since v1, that's how i prettified the original lockdep output.

Thanks,

Ingo

#11 lore raw

[tip:core/locking] lockdep: Print a nicer description for irq lock inversions

In reply to Steven Rostedt
Commit-ID:  3003eba313dd0e0502dd71548c36fe7c19801ce5
Gitweb:     http://git.kernel.org/tip/3003eba313dd0e0502dd71548c36fe7c19801ce5
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:54 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:57 +0200

lockdep: Print a nicer description for irq lock inversions

Locking order inversion due to interrupts is a subtle problem.

When an irq lockiinversion discovered by lockdep it currently reports something like:

[ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ]

... and then prints out the locks that are involved, as back traces.

Judging by lkml feedback developers were routinely confused by what a HARDIRQ->safe to unsafe issue is all about, and sometimes even blew it off as a bug in lockdep.

It is not obvious when lockdep prints this message about a lock that is never taken in interrupt context.

After explaining the problems that lockdep is reporting, I decided to add a description of the problem in visual form. Now the following is shown:

---
other info that might help us debug this:

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockA);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

---

The above is the case when the unsafe lock is taken while holding a lock taken in irq context. But when a lock is taken that also grabs a unsafe lock, the call chain is shown:

---
other info that might help us debug this:

Chain exists of:
  &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockC);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   70 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 70 insertions(+), 0 deletions(-)
kernel/lockdep.c +70 -0
index 53a6895..7b2ffee 100644
@@ -490,6 +490,18 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS])
 	usage[i] = '\0';
 }
 
+static int __print_lock_name(struct lock_class *class)
+{
+	char str[KSYM_NAME_LEN];
+	const char *name;
+
+	name = class->name;
+	if (!name)
+		name = __get_key_name(class->key, str);
+
+	return printk("%s", name);
+}
+
 static void print_lock_name(struct lock_class *class)
 {
 	char str[KSYM_NAME_LEN], usage[LOCK_USAGE_CHARS];

@@ -1325,6 +1337,62 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 	return;
 }
 
+static void
+print_irq_lock_scenario(struct lock_list *safe_entry,
+			struct lock_list *unsafe_entry,
+			struct held_lock *prev,
+			struct held_lock *next)
+{
+	struct lock_class *safe_class = safe_entry->class;
+	struct lock_class *unsafe_class = unsafe_entry->class;
+	struct lock_class *middle_class = hlock_class(prev);
+
+	if (middle_class == safe_class)
+		middle_class = hlock_class(next);
+
+	/*
+	 * A direct locking problem where unsafe_class lock is taken
+	 * directly by safe_class lock, then all we need to show
+	 * is the deadlock scenario, as it is obvious that the
+	 * unsafe lock is taken under the safe lock.
+	 *
+	 * But if there is a chain instead, where the safe lock takes
+	 * an intermediate lock (middle_class) where this lock is
+	 * not the same as the safe lock, then the lock chain is
+	 * used to describe the problem. Otherwise we would need
+	 * to show a different CPU case for each link in the chain
+	 * from the safe_class lock to the unsafe_class lock.
+	 */
+	if (middle_class != unsafe_class) {
+		printk("Chain exists of:\n  ");
+		__print_lock_name(safe_class);
+		printk(" --> ");
+		__print_lock_name(middle_class);
+		printk(" --> ");
+		__print_lock_name(unsafe_class);
+		printk("\n\n");
+	}
+
+	printk(" Possible interrupt unsafe locking scenario:\n\n");
+	printk("       CPU0                    CPU1\n");
+	printk("       ----                    ----\n");
+	printk("  lock(");
+	__print_lock_name(unsafe_class);
+	printk(");\n");
+	printk("                               local_irq_disable();\n");
+	printk("                               lock(");
+	__print_lock_name(safe_class);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(middle_class);
+	printk(");\n");
+	printk("  <Interrupt>\n");
+	printk("    lock(");
+	__print_lock_name(safe_class);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 static int
 print_bad_irq_dependency(struct task_struct *curr,
 			 struct lock_list *prev_root,

@@ -1376,6 +1444,8 @@ print_bad_irq_dependency(struct task_struct *curr,
 	print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
 	printk("\nother info that might help us debug this:\n\n");
+	print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nthe dependencies between %s-irq-safe lock", irqclass);
author
#12 lore raw

PATCH 2/7 lockdep: Print a nice description of normal deadlocks

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The lockdep output can be pretty cryptic, having a nice output can save a lot of head scratching. When a normal deadlock scenario is detected by lockdep (lock A -> lock B and there exists a place where lock B -> lock A) we get the following output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0                    CPU1
       ----                    ----
  lock(lockB);
                               lock(lockA);
                               lock(lockB);

lock(lockA);

*** DEADLOCK ***

On cases where there's a deeper chair, it shows the partial chain that can cause the issue:

Chain exists of:
  lockC --> lockA --> lockB

 Possible unsafe locking scenario:
       CPU0                    CPU1
       ----                    ----
  lock(lockB);
                               lock(lockA);
                               lock(lockB);

lock(lockC);

*** DEADLOCK ***

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   55 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 55 insertions(+), 0 deletions(-)
kernel/lockdep.c +55 -0
index bb77c030..1039008 100644
@@ -1065,6 +1065,56 @@ print_circular_bug_entry(struct lock_list *target, int depth)
 	return 0;
 }
 
+static void
+print_circular_lock_scenario(struct held_lock *src,
+			     struct held_lock *tgt,
+			     struct lock_list *prt)
+{
+	struct lock_class *source = hlock_class(src);
+	struct lock_class *target = hlock_class(tgt);
+	struct lock_class *parent = prt->class;
+
+	/*
+	 * A direct locking problem where unsafe_class lock is taken
+	 * directly by safe_class lock, then all we need to show
+	 * is the deadlock scenario, as it is obvious that the
+	 * unsafe lock is taken under the safe lock.
+	 *
+	 * But if there is a chain instead, where the safe lock takes
+	 * an intermediate lock (middle_class) where this lock is
+	 * not the same as the safe lock, then the lock chain is
+	 * used to describe the problem. Otherwise we would need
+	 * to show a different CPU case for each link in the chain
+	 * from the safe_class lock to the unsafe_class lock.
+	 */
+	if (parent != source) {
+		printk("Chain exists of:\n  ");
+		__print_lock_name(source);
+		printk(" --> ");
+		__print_lock_name(parent);
+		printk(" --> ");
+		__print_lock_name(target);
+		printk("\n\n");
+	}
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0                    CPU1\n");
+	printk("       ----                    ----\n");
+	printk("  lock(");
+	__print_lock_name(target);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(parent);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(target);
+	printk(");\n");
+	printk("  lock(");
+	__print_lock_name(source);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 /*
  * When a circular dependency is detected, print the
  * header first:

@@ -1108,6 +1158,7 @@ static noinline int print_circular_bug(struct lock_list *this,
 {
 	struct task_struct *curr = current;
 	struct lock_list *parent;
+	struct lock_list *first_parent;
 	int depth;
 
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)

@@ -1121,6 +1172,7 @@ static noinline int print_circular_bug(struct lock_list *this,
 	print_circular_bug_header(target, depth, check_src, check_tgt);
 
 	parent = get_lock_parent(target);
+	first_parent = parent;
 
 	while (parent) {
 		print_circular_bug_entry(parent, --depth);

@@ -1128,6 +1180,9 @@ static noinline int print_circular_bug(struct lock_list *this,
 	}
 
 	printk("\nother info that might help us debug this:\n\n");
+	print_circular_lock_scenario(check_src, check_tgt,
+				     first_parent);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
Signature · 1 line
1.7.2.3
#13 lore raw

[tip:core/locking] lockdep: Print a nicer description for normal deadlocks

Commit-ID:  f4185812aa046ecb97e8817e10148cacdd7a6baa
Gitweb:     http://git.kernel.org/tip/f4185812aa046ecb97e8817e10148cacdd7a6baa
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:55 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:57 +0200

lockdep: Print a nicer description for normal deadlocks

The lockdep output can be pretty cryptic, having nicer output can save a lot of head scratching. When a normal deadlock scenario is detected by lockdep (lock A -> lock B and there exists a place where lock B -> lock A) we now get the following new output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0                    CPU1
       ----                    ----
  lock(lockB);
                               lock(lockA);
                               lock(lockB);

lock(lockA);

*** DEADLOCK ***

On cases where there's a deeper chair, it shows the partial chain that can cause the issue:

Chain exists of:
  lockC --> lockA --> lockB

 Possible unsafe locking scenario:
       CPU0                    CPU1
       ----                    ----
  lock(lockB);
                               lock(lockA);
                               lock(lockB);

lock(lockC);

*** DEADLOCK ***

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   55 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 55 insertions(+), 0 deletions(-)
kernel/lockdep.c +55 -0
index 7b2ffee..73cebd7 100644
@@ -1065,6 +1065,56 @@ print_circular_bug_entry(struct lock_list *target, int depth)
 	return 0;
 }
 
+static void
+print_circular_lock_scenario(struct held_lock *src,
+			     struct held_lock *tgt,
+			     struct lock_list *prt)
+{
+	struct lock_class *source = hlock_class(src);
+	struct lock_class *target = hlock_class(tgt);
+	struct lock_class *parent = prt->class;
+
+	/*
+	 * A direct locking problem where unsafe_class lock is taken
+	 * directly by safe_class lock, then all we need to show
+	 * is the deadlock scenario, as it is obvious that the
+	 * unsafe lock is taken under the safe lock.
+	 *
+	 * But if there is a chain instead, where the safe lock takes
+	 * an intermediate lock (middle_class) where this lock is
+	 * not the same as the safe lock, then the lock chain is
+	 * used to describe the problem. Otherwise we would need
+	 * to show a different CPU case for each link in the chain
+	 * from the safe_class lock to the unsafe_class lock.
+	 */
+	if (parent != source) {
+		printk("Chain exists of:\n  ");
+		__print_lock_name(source);
+		printk(" --> ");
+		__print_lock_name(parent);
+		printk(" --> ");
+		__print_lock_name(target);
+		printk("\n\n");
+	}
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0                    CPU1\n");
+	printk("       ----                    ----\n");
+	printk("  lock(");
+	__print_lock_name(target);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(parent);
+	printk(");\n");
+	printk("                               lock(");
+	__print_lock_name(target);
+	printk(");\n");
+	printk("  lock(");
+	__print_lock_name(source);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 /*
  * When a circular dependency is detected, print the
  * header first:

@@ -1108,6 +1158,7 @@ static noinline int print_circular_bug(struct lock_list *this,
 {
 	struct task_struct *curr = current;
 	struct lock_list *parent;
+	struct lock_list *first_parent;
 	int depth;
 
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)

@@ -1121,6 +1172,7 @@ static noinline int print_circular_bug(struct lock_list *this,
 	print_circular_bug_header(target, depth, check_src, check_tgt);
 
 	parent = get_lock_parent(target);
+	first_parent = parent;
 
 	while (parent) {
 		print_circular_bug_entry(parent, --depth);

@@ -1128,6 +1180,9 @@ static noinline int print_circular_bug(struct lock_list *this,
 	}
 
 	printk("\nother info that might help us debug this:\n\n");
+	print_circular_lock_scenario(check_src, check_tgt,
+				     first_parent);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
author
#14 lore raw

PATCH 3/7 lockdep: Print a nice description of simple deadlock

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The lockdep output can be pretty cryptic, having a nice output can save a lot of head scratching. When a simple deadlock scenario is detected by lockdep (lock A -> lock A) we get the following output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0
       ----

lock(&(lock)->rlock);
lock(&(lock)->rlock);

*** DEADLOCK ***

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   21 +++++++++++++++++++++
 1 files changed, 21 insertions(+), 0 deletions(-)
kernel/lockdep.c +21 -0
index 1039008..a0f253b 100644
@@ -1664,6 +1664,26 @@ static inline void inc_chains(void)
 
 #endif
 
+static void
+print_deadlock_scenario(struct held_lock *nxt,
+			     struct held_lock *prv)
+{
+	struct lock_class *next = hlock_class(nxt);
+	struct lock_class *prev = hlock_class(prv);
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0\n");
+	printk("       ----\n");
+	printk("  lock(");
+	__print_lock_name(prev);
+	printk(");\n");
+	printk("  lock(");
+	__print_lock_name(next);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+	printk(" May be due to missing lock nesting notation\n\n");
+}
+
 static int
 print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
 		   struct held_lock *next)

@@ -1682,6 +1702,7 @@ print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
 	print_lock(prev);
 
 	printk("\nother info that might help us debug this:\n");
+	print_deadlock_scenario(next, prev);
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
Signature · 1 line
1.7.2.3
#15 lore raw

[tip:core/locking] lockdep: Print a nicer description for simple deadlocks

Commit-ID:  48702ecf308e53f176c1f6fdc193d622ded54ac0
Gitweb:     http://git.kernel.org/tip/48702ecf308e53f176c1f6fdc193d622ded54ac0
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:56 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:58 +0200

lockdep: Print a nicer description for simple deadlocks

Lockdep output can be pretty cryptic, having nicer output can save a lot of head scratching. When a simple deadlock scenario is detected by lockdep (lock A -> lock A) we now get the following new output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0
       ----

lock(&(lock)->rlock);
lock(&(lock)->rlock);

*** DEADLOCK ***

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   21 +++++++++++++++++++++
 1 files changed, 21 insertions(+), 0 deletions(-)
kernel/lockdep.c +21 -0
index 73cebd7..c4cc5d1 100644
@@ -1664,6 +1664,26 @@ static inline void inc_chains(void)
 
 #endif
 
+static void
+print_deadlock_scenario(struct held_lock *nxt,
+			     struct held_lock *prv)
+{
+	struct lock_class *next = hlock_class(nxt);
+	struct lock_class *prev = hlock_class(prv);
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0\n");
+	printk("       ----\n");
+	printk("  lock(");
+	__print_lock_name(prev);
+	printk(");\n");
+	printk("  lock(");
+	__print_lock_name(next);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+	printk(" May be due to missing lock nesting notation\n\n");
+}
+
 static int
 print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
 		   struct held_lock *next)

@@ -1682,6 +1702,7 @@ print_deadlock_bug(struct task_struct *curr, struct held_lock *prev,
 	print_lock(prev);
 
 	printk("\nother info that might help us debug this:\n");
+	print_deadlock_scenario(next, prev);
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
author
#16 lore raw

PATCH 4/7 lockdep: Printk nice description for irq inversion bug

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The irq inversion and irq dependency bug are only subtly different. The diffenerence lies where the interrupt occurred.

For irq dependency:

	irq_disable
	lock(A)
	lock(B)
	unlock(B)
	unlock(A)
	irq_enable

	lock(B)
	unlock(B)

<interrupt>

	  lock(A)

The interrupt comes in after it has been established that lock A can be held when taking an irq unsafe lock. Lockdep detects the problem when taking lock A in interrupt context.

<interrupt>

	  lock(A)

	irq_disable
	lock(A)
	lock(B)
	unlock(B)
	unlock(A)
	irq_enable

	lock(B)
	unlock(B)

With the irq_inversion the irq happens before it is established and lockdep detects the problem with the taking of lock B.

Since the problem with the locking for both of these issues are in actuality the same, they both should report the same scenario.

other info that might help us debug this:

Chain exists of:
  &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockC);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   34 +++++++++++++++++++++++++++++-----
 1 files changed, 29 insertions(+), 5 deletions(-)
kernel/lockdep.c +29 -5
index a0f253b..8646b8c 100644
@@ -1395,15 +1395,15 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 static void
 print_irq_lock_scenario(struct lock_list *safe_entry,
 			struct lock_list *unsafe_entry,
-			struct held_lock *prev,
-			struct held_lock *next)
+			struct lock_class *prev_class,
+			struct lock_class *next_class)
 {
 	struct lock_class *safe_class = safe_entry->class;
 	struct lock_class *unsafe_class = unsafe_entry->class;
-	struct lock_class *middle_class = hlock_class(prev);
+	struct lock_class *middle_class = prev_class;
 
 	if (middle_class == safe_class)
-		middle_class = hlock_class(next);
+		middle_class = next_class;
 
 	/*
 	 * A direct locking problem where unsafe_class lock is taken

@@ -1499,7 +1499,8 @@ print_bad_irq_dependency(struct task_struct *curr,
 	print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
 	printk("\nother info that might help us debug this:\n\n");
-	print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+	print_irq_lock_scenario(backwards_entry, forwards_entry,
+				hlock_class(prev), hlock_class(next));
 
 	lockdep_print_held_locks(curr);
 

@@ -2219,6 +2220,10 @@ print_irq_inversion_bug(struct task_struct *curr,
 			struct held_lock *this, int forwards,
 			const char *irqclass)
 {
+	struct lock_list *entry = other;
+	struct lock_list *middle = NULL;
+	int depth;
+
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 

@@ -2237,6 +2242,25 @@ print_irq_inversion_bug(struct task_struct *curr,
 	printk("\n\nand interrupts could create inverse lock ordering between them.\n\n");
 
 	printk("\nother info that might help us debug this:\n");
+
+	/* Find a middle lock (if one exists) */
+	depth = get_lock_depth(other);
+	do {
+		if (depth == 0 && (entry != root)) {
+			printk("lockdep:%s bad path found in chain graph\n", __func__);
+			break;
+		}
+		middle = entry;
+		entry = get_lock_parent(entry);
+		depth--;
+	} while (entry && entry != root && (depth >= 0));
+	if (forwards)
+		print_irq_lock_scenario(root, other,
+			middle ? middle->class : root->class, other->class);
+	else
+		print_irq_lock_scenario(other, root,
+			middle ? middle->class : other->class, root->class);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nthe shortest dependencies between 2nd lock and 1st lock:\n");
Signature · 1 line
1.7.2.3
#17 lore raw

[tip:core/locking] lockdep: Print a nicer description for irq inversion bugs

Commit-ID:  dad3d7435e1d8c254d6877dc06852dc00c5da812
Gitweb:     http://git.kernel.org/tip/dad3d7435e1d8c254d6877dc06852dc00c5da812
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:57 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:58 +0200

lockdep: Print a nicer description for irq inversion bugs

Irq inversion and irq dependency bugs are only subtly different. The diffenerence lies where the interrupt occurred.

For irq dependency:

	irq_disable
	lock(A)
	lock(B)
	unlock(B)
	unlock(A)
	irq_enable

	lock(B)
	unlock(B)

<interrupt>

	  lock(A)

The interrupt comes in after it has been established that lock A can be held when taking an irq unsafe lock. Lockdep detects the problem when taking lock A in interrupt context.

With the irq_inversion the irq happens before it is established and lockdep detects the problem with the taking of lock B:

<interrupt>

	  lock(A)

	irq_disable
	lock(A)
	lock(B)
	unlock(B)
	unlock(A)
	irq_enable

	lock(B)
	unlock(B)

Since the problem with the locking logic for both of these issues is in actuality the same, they both should report the same scenario. This patch implements that and prints this:

other info that might help us debug this:

Chain exists of:
  &rq->lock --> lockA --> lockC

Possible interrupt unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(lockC);
                               local_irq_disable();
                               lock(&rq->lock);
                               lock(lockA);
  <Interrupt>
    lock(&rq->lock);

*** DEADLOCK ***

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   34 +++++++++++++++++++++++++++++-----
 1 files changed, 29 insertions(+), 5 deletions(-)
kernel/lockdep.c +29 -5
index c4cc5d1..0b497dd 100644
@@ -1395,15 +1395,15 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 static void
 print_irq_lock_scenario(struct lock_list *safe_entry,
 			struct lock_list *unsafe_entry,
-			struct held_lock *prev,
-			struct held_lock *next)
+			struct lock_class *prev_class,
+			struct lock_class *next_class)
 {
 	struct lock_class *safe_class = safe_entry->class;
 	struct lock_class *unsafe_class = unsafe_entry->class;
-	struct lock_class *middle_class = hlock_class(prev);
+	struct lock_class *middle_class = prev_class;
 
 	if (middle_class == safe_class)
-		middle_class = hlock_class(next);
+		middle_class = next_class;
 
 	/*
 	 * A direct locking problem where unsafe_class lock is taken

@@ -1499,7 +1499,8 @@ print_bad_irq_dependency(struct task_struct *curr,
 	print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
 	printk("\nother info that might help us debug this:\n\n");
-	print_irq_lock_scenario(backwards_entry, forwards_entry, prev, next);
+	print_irq_lock_scenario(backwards_entry, forwards_entry,
+				hlock_class(prev), hlock_class(next));
 
 	lockdep_print_held_locks(curr);
 

@@ -2219,6 +2220,10 @@ print_irq_inversion_bug(struct task_struct *curr,
 			struct held_lock *this, int forwards,
 			const char *irqclass)
 {
+	struct lock_list *entry = other;
+	struct lock_list *middle = NULL;
+	int depth;
+
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 

@@ -2237,6 +2242,25 @@ print_irq_inversion_bug(struct task_struct *curr,
 	printk("\n\nand interrupts could create inverse lock ordering between them.\n\n");
 
 	printk("\nother info that might help us debug this:\n");
+
+	/* Find a middle lock (if one exists) */
+	depth = get_lock_depth(other);
+	do {
+		if (depth == 0 && (entry != root)) {
+			printk("lockdep:%s bad path found in chain graph\n", __func__);
+			break;
+		}
+		middle = entry;
+		entry = get_lock_parent(entry);
+		depth--;
+	} while (entry && entry != root && (depth >= 0));
+	if (forwards)
+		print_irq_lock_scenario(root, other,
+			middle ? middle->class : root->class, other->class);
+	else
+		print_irq_lock_scenario(other, root,
+			middle ? middle->class : other->class, root->class);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nthe shortest dependencies between 2nd lock and 1st lock:\n");
author
#18 lore raw

PATCH 5/7 lockdep: Replace bad path error message with something sane

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The message of "Bad BFS generated tree" is a bit confusing. Replace it with a more sane error message.

Thanks to Peter Zijlstra for helping me come up with a better message.

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
kernel/lockdep.c +1 -1
index 8646b8c..b531c66 100644
@@ -1381,7 +1381,7 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 		printk("\n");
 
 		if (depth == 0 && (entry != root)) {
-			printk("lockdep:%s bad BFS generated tree\n", __func__);
+			printk("lockdep:%s bad path found in chain graph\n", __func__);
 			break;
 		}
Signature · 1 line
1.7.2.3
#19 lore raw

[tip:core/locking] lockdep: Replace "Bad BFS generated tree" message with something less cryptic

Commit-ID:  6be8c3935b914dfbc24b27c91c2b6d583645e61a
Gitweb:     http://git.kernel.org/tip/6be8c3935b914dfbc24b27c91c2b6d583645e61a
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:58 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:59 +0200

lockdep: Replace "Bad BFS generated tree" message with something less cryptic

The message of "Bad BFS generated tree" is a bit confusing. Replace it with a more sane error message.

Thanks to Peter Zijlstra for helping me come up with a better message.

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
kernel/lockdep.c +1 -1
index 0b497dd..270cfa4 100644
@@ -1381,7 +1381,7 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
 		printk("\n");
 
 		if (depth == 0 && (entry != root)) {
-			printk("lockdep:%s bad BFS generated tree\n", __func__);
+			printk("lockdep:%s bad path found in chain graph\n", __func__);
 			break;
 		}
author
#20 lore raw

PATCH 6/7 lockdep: Print a nice description of simple irq inversion

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The lockdep output can be pretty cryptic, having a nice output can save a lot of head scratching. When a simple irq inversion scenario is detected by lockdep (lock A taken in interrupt context but also in thread context without disabling interrupts) we get the following output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0
       ----
  lock(lockA);
  <Interrupt>
    lock(lockA);

*** DEADLOCK ***

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   20 ++++++++++++++++++++
 1 files changed, 20 insertions(+), 0 deletions(-)
kernel/lockdep.c +20 -0
index b531c66..3b1ac92 100644
@@ -2158,6 +2158,24 @@ static void check_chain_key(struct task_struct *curr)
 #endif
 }
 
+static void
+print_usage_bug_scenario(struct held_lock *lock)
+{
+	struct lock_class *class = hlock_class(lock);
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0\n");
+	printk("       ----\n");
+	printk("  lock(");
+	__print_lock_name(class);
+	printk(");\n");
+	printk("  <Interrupt>\n");
+	printk("    lock(");
+	__print_lock_name(class);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 static int
 print_usage_bug(struct task_struct *curr, struct held_lock *this,
 		enum lock_usage_bit prev_bit, enum lock_usage_bit new_bit)

@@ -2186,6 +2204,8 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this,
 
 	print_irqtrace_events(curr);
 	printk("\nother info that might help us debug this:\n");
+	print_usage_bug_scenario(this);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
Signature · 1 line
1.7.2.3
#21 lore raw

[tip:core/locking] lockdep: Print a nicer description for simple irq lock inversions

Commit-ID:  282b5c2f6f663c008444321fd8fcdd374596046b
Gitweb:     http://git.kernel.org/tip/282b5c2f6f663c008444321fd8fcdd374596046b
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:41:59 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:59 +0200

lockdep: Print a nicer description for simple irq lock inversions

Lockdep output can be pretty cryptic, having nicer output can save a lot of head scratching. When a simple irq inversion scenario is detected by lockdep (lock A taken in interrupt context but also in thread context without disabling interrupts) we now get the following (hopefully more informative) output:

other info that might help us debug this:

 Possible unsafe locking scenario:
       CPU0
       ----
  lock(lockA);
  <Interrupt>
    lock(lockA);

*** DEADLOCK ***

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   20 ++++++++++++++++++++
 1 files changed, 20 insertions(+), 0 deletions(-)
kernel/lockdep.c +20 -0
index 270cfa4..27c609f 100644
@@ -2158,6 +2158,24 @@ static void check_chain_key(struct task_struct *curr)
 #endif
 }
 
+static void
+print_usage_bug_scenario(struct held_lock *lock)
+{
+	struct lock_class *class = hlock_class(lock);
+
+	printk(" Possible unsafe locking scenario:\n\n");
+	printk("       CPU0\n");
+	printk("       ----\n");
+	printk("  lock(");
+	__print_lock_name(class);
+	printk(");\n");
+	printk("  <Interrupt>\n");
+	printk("    lock(");
+	__print_lock_name(class);
+	printk(");\n");
+	printk("\n *** DEADLOCK ***\n\n");
+}
+
 static int
 print_usage_bug(struct task_struct *curr, struct held_lock *this,
 		enum lock_usage_bit prev_bit, enum lock_usage_bit new_bit)

@@ -2186,6 +2204,8 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this,
 
 	print_irqtrace_events(curr);
 	printk("\nother info that might help us debug this:\n");
+	print_usage_bug_scenario(this);
+
 	lockdep_print_held_locks(curr);
 
 	printk("\nstack backtrace:\n");
author
#22 lore raw

PATCH 7/7 lockdep: Remove cmpxchg to update nr_chain_hlocks

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

For some reason nr_chain_hlocks is updated with cmpxchg, but this is performed inside of the lockdep global "grab_lock()", which also makes simple modification of this variable atomic.

Remove the cmpxchg logic for updating nr_chain_hlocks and simplify the code.

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/lockdep.c |   14 ++++----------
 1 files changed, 4 insertions(+), 10 deletions(-)
kernel/lockdep.c +4 -10
index 3b1ac92..60bce52 100644
@@ -1973,7 +1973,7 @@ static inline int lookup_chain_cache(struct task_struct *curr,
 	struct list_head *hash_head = chainhashentry(chain_key);
 	struct lock_chain *chain;
 	struct held_lock *hlock_curr, *hlock_next;
-	int i, j, n, cn;
+	int i, j;
 
 	if (DEBUG_LOCKS_WARN_ON(!irqs_disabled()))
 		return 0;

@@ -2033,15 +2033,9 @@ cache_hit:
 	}
 	i++;
 	chain->depth = curr->lockdep_depth + 1 - i;
-	cn = nr_chain_hlocks;
-	while (cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS) {
-		n = cmpxchg(&nr_chain_hlocks, cn, cn + chain->depth);
-		if (n == cn)
-			break;
-		cn = n;
-	}
-	if (likely(cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
-		chain->base = cn;
+	if (likely(nr_chain_hlocks + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
+		chain->base = nr_chain_hlocks;
+		nr_chain_hlocks += chain->depth;
 		for (j = 0; j < chain->depth - 1; j++, i++) {
 			int lock_id = curr->held_locks[i].class_idx - 1;
 			chain_hlocks[chain->base + j] = lock_id;
Signature · 1 line
1.7.2.3
#23 lore raw

Re: [PATCH 7/7] lockdep: Remove cmpxchg to update nr_chain_hlocks

Quoted 20 lines · Steven Rostedt

From: Steven Rostedt <[email protected]>

For some reason nr_chain_hlocks is updated with cmpxchg, but this is performed inside of the lockdep global "grab_lock()", which also makes simple modification of this variable atomic.

Remove the cmpxchg logic for updating nr_chain_hlocks and simplify the code.

Acked-by Peter Zijlstra <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/lockdep.c |   14 ++++----------

 1 files changed, 4 insertions(+), 10 deletions(-)
kernel/lockdep.c +0 -0
index 3b1ac92..60bce52 100644

kernel/lockdep.c static inline int lookup_chain_cache(struct task_struct *curr, · line 1975

Quoted 3 lines
kernel/lockdep.c +0 -0
@@ -1973,7 +1973,7 @@ static inline int lookup_chain_cache(struct task_struct *curr,
        struct list_head *hash_head = chainhashentry(chain_key);
        struct lock_chain *chain;
        struct held_lock *hlock_curr, *hlock_next;

Maybe we can also remove hlock_next in this function for some cleanup, because it's just an alias of hlock.

Thanks,
Yong

Quoted 34 lines
kernel/lockdep.c +4 -11
-       int i, j, n, cn;
+       int i, j;
 
        if (DEBUG_LOCKS_WARN_ON(!irqs_disabled()))
                return 0;

@@ -2033,15 +2033,9 @@ cache_hit:
        }
        i++;
        chain->depth = curr->lockdep_depth + 1 - i;
-       cn = nr_chain_hlocks;
-       while (cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS) {
-               n = cmpxchg(&nr_chain_hlocks, cn, cn + chain->depth);
-               if (n == cn)
-                       break;
-               cn = n;
-       }
-       if (likely(cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
-               chain->base = cn;
+       if (likely(nr_chain_hlocks + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
+               chain->base = nr_chain_hlocks;
+               nr_chain_hlocks += chain->depth;
                for (j = 0; j < chain->depth - 1; j++, i++) {
                        int lock_id = curr->held_locks[i].class_idx - 1;
                        chain_hlocks[chain->base + j] = lock_id;
--

1.7.2.3

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Signature · 1 line
Only stand for myself
#24 lore raw

[tip:core/locking] lockdep: Remove cmpxchg to update nr_chain_hlocks

In reply to Steven Rostedt
Commit-ID:  e0944ee63f7249802be74454cef81c97630ae1cd
Gitweb:     http://git.kernel.org/tip/e0944ee63f7249802be74454cef81c97630ae1cd
Author:     Steven Rostedt <[email protected]>
AuthorDate: Wed, 20 Apr 2011 21:42:00 -0400
Committer:  Ingo Molnar <[email protected]>
CommitDate: Fri, 22 Apr 2011 11:06:59 +0200

lockdep: Remove cmpxchg to update nr_chain_hlocks

For some reason nr_chain_hlocks is updated with cmpxchg, but this is performed inside of the lockdep global "grab_lock()", which also makes simple modification of this variable atomic.

Remove the cmpxchg logic for updating nr_chain_hlocks and simplify the code.

Signed-off-by Steven Rostedt <[email protected]>
Acked-by Peter Zijlstra <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Linus Torvalds <[email protected]>
Cc Andrew Morton <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Ingo Molnar <[email protected]>
---
 kernel/lockdep.c |   14 ++++----------
 1 files changed, 4 insertions(+), 10 deletions(-)
kernel/lockdep.c +4 -10
index 27c609f..63437d0 100644
@@ -1973,7 +1973,7 @@ static inline int lookup_chain_cache(struct task_struct *curr,
 	struct list_head *hash_head = chainhashentry(chain_key);
 	struct lock_chain *chain;
 	struct held_lock *hlock_curr, *hlock_next;
-	int i, j, n, cn;
+	int i, j;
 
 	if (DEBUG_LOCKS_WARN_ON(!irqs_disabled()))
 		return 0;

@@ -2033,15 +2033,9 @@ cache_hit:
 	}
 	i++;
 	chain->depth = curr->lockdep_depth + 1 - i;
-	cn = nr_chain_hlocks;
-	while (cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS) {
-		n = cmpxchg(&nr_chain_hlocks, cn, cn + chain->depth);
-		if (n == cn)
-			break;
-		cn = n;
-	}
-	if (likely(cn + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
-		chain->base = cn;
+	if (likely(nr_chain_hlocks + chain->depth <= MAX_LOCKDEP_CHAIN_HLOCKS)) {
+		chain->base = nr_chain_hlocks;
+		nr_chain_hlocks += chain->depth;
 		for (j = 0; j < chain->depth - 1; j++, i++) {
 			int lock_id = curr->held_locks[i].class_idx - 1;
 			chain_hlocks[chain->base + j] = lock_id;
#25 lore raw
In reply to Steven Rostedt
Quoted 9 lines · Steven Rostedt

Steven Rostedt (7):
     lockdep: Print a nice description of an irq locking issue
     lockdep: Print a nice description of normal deadlocks
     lockdep: Print a nice description of simple deadlock
     lockdep: Printk nice description for irq inversion bug
     lockdep: Replace bad path error message with something sane
     lockdep: Print a nice description of simple irq inversion
     lockdep: Remove cmpxchg to update nr_chain_hlocks

Quoted 3 lines

----
 kernel/lockdep.c |  206 +++++++++++++++++++++++++++++++++++++++++++++++++++---

 1 files changed, 195 insertions(+), 11 deletions(-)

This looks very nice :)

Thanks,
Yong

Signature · 1 line
Only stand for myself