[RFC][PATCH] lockdep: Print a nice description of an irq locking issue

March 29th, 2011 - 01:20 pm ET by Steven Rostedt | Report spam
After having to explain lockdep interrupt locking inversions a few
times, I decided to have lockdep spit out the scenario that it is
complaining about.



The following patch is in:

git://git.kernel.org/pub/scm/linux/...-trace.git

branch: tip/lockdep/devel


Steven Rostedt (1):
lockdep: Print a nice description of an irq locking issue

-
kernel/lockdep.c | 66 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
1 files changed, 66 insertions(+), 0 deletions(-)

commit 3429984fca737d0028c57d8d5c6a6b94ac3e90de
Author: Steven Rostedt <srostedt@redhat.com>
Date: Tue Mar 29 12:55:14 2011 -0400

lockdep: Print a nice description of an irq locking issue

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



Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 0d2058d..cc5fb5b 100644
a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -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,58 @@ print_shortest_lock_dependencies(struct lock_list *leaf,
return;
}

+static void
+print_irq_lock_scenario(struct lock_list *backwards_entry,
+ struct lock_list *forwards_entry,
+ struct held_lock *next)
+{
+ struct lock_class *safe_class = backwards_entry->class;
+ struct lock_class *unsafe_class = forwards_entry->class;
+ struct lock_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: ");
+ __print_lock_name(safe_class);
+ printk(" --> ");
+ __print_lock_name(middle_class);
+ printk(" --> ");
+ __print_lock_name(unsafe_class);
+ printk("");
+ }
+
+ printk(" Possible interrupt unsafe locking scenario:");
+ printk(" CPU0 CPU1");
+ printk(" - -");
+ printk(" lock(");
+ __print_lock_name(unsafe_class);
+ printk(");");
+ printk(" local_irq_disable();");
+ printk(" lock(");
+ __print_lock_name(safe_class);
+ printk(");");
+ printk(" lock(");
+ __print_lock_name(middle_class);
+ printk(");");
+ printk(" <Interrupt>");
+ printk(" lock(");
+ __print_lock_name(safe_class);
+ printk(")");
+ printk(" *** DEADLOCK ***");
+}
+
static int
print_bad_irq_dependency(struct task_struct *curr,
struct lock_list *prev_root,
@@ -1376,6 +1440,8 @@ print_bad_irq_dependency(struct task_struct *curr,
print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);

printk("other info that might help us debug this:");
+ print_irq_lock_scenario(backwards_entry, forwards_entry, next);
+
lockdep_print_held_locks(curr);

printk("the dependencies between %s-irq-safe lock", irqclass);


To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
email Follow the discussionReplies 5 repliesReplies Make a reply

Replies

#1 Steven Rostedt
March 29th, 2011 - 01:30 pm ET | Report spam
On Tue, 2011-03-29 at 13:14 -0400, Steven Rostedt wrote:


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




Note, the above output is real. To produce this output, I wrote a module
that created a "lockA", "lockB" and "lockC" and had the following:

spin_lock_irq(&lockA);
spin_lock(&lockB);
spin_unlock(&lockB);
spin_unlock_irq(&lockA);

spin_lock_irq(&lockB);
spin_lock(&lockC);
spin_unlock(&lockC);
spin_unlock_irq(&lockB);

spin_lock(&lockC);
spin_unlock(&lockC);
ret = register_trace_sched_switch(probe_switch, NULL);

static void
probe_switch(void *ignore, struct task_struct *p, struct task_struct *n)
{
unsigned long flags;

spin_lock_irqsave(&lockA, flags);
spin_unlock_irqrestore(&lockA, flags);
}


probe_switch is called via the trace_sched_switch() trace point that is
called with the rq lock held, producing the call chain that will trigger
lockdep to produce a dump.





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

Similar topics