irda rmmod lockdep trace.

irda rmmod lockdep trace.

[Dave Jones]

modprobe irda ; rmmod irda in 2.6.21rc3 gets me the spew below..

	Dave

NET: Registered protocol family 23
NET: Unregistered protocol family 23

=============================================
[ INFO: possible recursive locking detected ]
2.6.20-1.2966.fc7 #1
---------------------------------------------
rmmod/16712 is trying to acquire lock:
 (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]

but task is already holding lock:
 (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]

other info that might help us debug this:
1 lock held by rmmod/16712:
 #0:  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]

stack backtrace:

Call Trace:
 [<ffffffff802a303b>] __lock_acquire+0x151/0xbc4
 [<ffffffff884c1517>] :irda:__irias_delete_attrib+0x0/0x31
 [<ffffffff802a3ea4>] lock_acquire+0x4c/0x65
 [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
 [<ffffffff80264011>] _spin_lock_irqsave+0x2c/0x3c
 [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
 [<ffffffff884c1918>] :irda:__irias_delete_object+0x0/0x39
 [<ffffffff884c193d>] :irda:__irias_delete_object+0x25/0x39
 [<ffffffff884bf48d>] :irda:hashbin_delete+0x40/0x94
 [<ffffffff884c5e3a>] :irda:iriap_cleanup+0x36/0x38
 [<ffffffff884c5fd6>] :irda:irda_cleanup+0x29/0x3a
 [<ffffffff802aa1e1>] sys_delete_module+0x199/0x1ca
 [<ffffffff8026ce36>] syscall_trace_enter+0x9a/0x9f
 [<ffffffff8025c2b5>] tracesys+0xdc/0xe1


-- 
http://www.codemonkey.org.uk

Re: irda rmmod lockdep trace.

[Samuel Ortiz]

Hi Dave,

On Thu, Mar 08, 2007 at 05:54:36PM -0500, Dave Jones wrote:
> modprobe irda ; rmmod irda in 2.6.21rc3 gets me the spew below..
Well it seems that we call __irias_delete_object() from hashbin_delete(). Then
__irias_delete_object() calls itself hashbin_delete() again. We're trying to
get the lock recursively.
I'll try to fix that soon, thanks for the report.

Cheers,
Samuel.


> 	Dave
> 
> NET: Registered protocol family 23
> NET: Unregistered protocol family 23
> 
> =============================================
> [ INFO: possible recursive locking detected ]
> 2.6.20-1.2966.fc7 #1
> ---------------------------------------------
> rmmod/16712 is trying to acquire lock:
>  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> 
> but task is already holding lock:
>  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> 
> other info that might help us debug this:
> 1 lock held by rmmod/16712:
>  #0:  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> 
> stack backtrace:
> 
> Call Trace:
>  [<ffffffff802a303b>] __lock_acquire+0x151/0xbc4
>  [<ffffffff884c1517>] :irda:__irias_delete_attrib+0x0/0x31
>  [<ffffffff802a3ea4>] lock_acquire+0x4c/0x65
>  [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
>  [<ffffffff80264011>] _spin_lock_irqsave+0x2c/0x3c
>  [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
>  [<ffffffff884c1918>] :irda:__irias_delete_object+0x0/0x39
>  [<ffffffff884c193d>] :irda:__irias_delete_object+0x25/0x39
>  [<ffffffff884bf48d>] :irda:hashbin_delete+0x40/0x94
>  [<ffffffff884c5e3a>] :irda:iriap_cleanup+0x36/0x38
>  [<ffffffff884c5fd6>] :irda:irda_cleanup+0x29/0x3a
>  [<ffffffff802aa1e1>] sys_delete_module+0x199/0x1ca
>  [<ffffffff8026ce36>] syscall_trace_enter+0x9a/0x9f
>  [<ffffffff8025c2b5>] tracesys+0xdc/0xe1
> 
> 
> -- 
> http://www.codemonkey.org.uk

Re: irda rmmod lockdep trace.

[Samuel Ortiz]

Hi Dave,

On Sat, Mar 10, 2007 at 07:43:26PM +0200, Samuel Ortiz wrote:
> Hi Dave,
> 
> On Thu, Mar 08, 2007 at 05:54:36PM -0500, Dave Jones wrote:
> > modprobe irda ; rmmod irda in 2.6.21rc3 gets me the spew below..
> Well it seems that we call __irias_delete_object() from hashbin_delete(). Then
> __irias_delete_object() calls itself hashbin_delete() again. We're trying to
> get the lock recursively.
Looking at the code more carefully, this seems to be a false positive:
iriap_cleanup and and __irias_delete_object are taking 2 different locks from
2 different hashbin instances. The locks belong to the same lock class but
they are hierarchically different. We need to tell the validator about it and
the following patch does that. Comments are welcomed as I'm planning to push
it to netdev soon:

 include/net/irda/irqueue.h |    4 +++-
 net/irda/irias_object.c    |    3 ++-
 net/irda/irqueue.c         |   13 +++++++++----
 3 files changed, 14 insertions(+), 6 deletions(-)

diff --git a/include/net/irda/irqueue.h b/include/net/irda/irqueue.h
index 335b0ac..ce9fa7c 100644
--- a/include/net/irda/irqueue.h
+++ b/include/net/irda/irqueue.h
@@ -77,7 +77,8 @@ typedef struct hashbin_t {
 } hashbin_t;
 
 hashbin_t *hashbin_new(int type);
-int      hashbin_delete(hashbin_t* hashbin, FREE_FUNC func);
+int      hashbin_delete_nested(hashbin_t* hashbin, FREE_FUNC func,
+			       u8 nested_depth);
 int      hashbin_clear(hashbin_t* hashbin, FREE_FUNC free_func);
 void     hashbin_insert(hashbin_t* hashbin, irda_queue_t* entry, long hashv, 
 			const char* name);
@@ -92,5 +93,6 @@ irda_queue_t *hashbin_get_first(hashbin_t *hashbin);
 irda_queue_t *hashbin_get_next(hashbin_t *hashbin);
 
 #define HASHBIN_GET_SIZE(hashbin) hashbin->hb_size
+#define hashbin_delete(hashbin, func) hashbin_delete_nested(hashbin, func, 0)
 
 #endif
diff --git a/net/irda/iriap.c b/net/irda/iriap.c
diff --git a/net/irda/irias_object.c b/net/irda/irias_object.c
index 4adaae2..4238d23 100644
--- a/net/irda/irias_object.c
+++ b/net/irda/irias_object.c
@@ -142,7 +142,8 @@ void __irias_delete_object(struct ias_object *obj)
 
 	kfree(obj->name);
 
-	hashbin_delete(obj->attribs, (FREE_FUNC) __irias_delete_attrib);
+	hashbin_delete_nested(obj->attribs, (FREE_FUNC) __irias_delete_attrib,
+			      SINGLE_DEPTH_NESTING);
 
 	obj->magic = ~IAS_OBJECT_MAGIC;
 
diff --git a/net/irda/irqueue.c b/net/irda/irqueue.c
index 9266233..c669a86 100644
--- a/net/irda/irqueue.c
+++ b/net/irda/irqueue.c
@@ -378,13 +378,14 @@ EXPORT_SYMBOL(hashbin_new);
 
 
 /*
- * Function hashbin_delete (hashbin, free_func)
+ * Function hashbin_delete_nested (hashbin, free_func, nested_lock)
  *
  *    Destroy hashbin, the free_func can be a user supplied special routine
  *    for deallocating this structure if it's complex. If not the user can
  *    just supply kfree, which should take care of the job.
  */
-int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
+int hashbin_delete_nested( hashbin_t* hashbin, FREE_FUNC free_func,
+			   u8 nested_depth)
 {
 	irda_queue_t* queue;
 	unsigned long flags = 0;
@@ -395,7 +396,11 @@ int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
 
 	/* Synchronize */
 	if ( hashbin->hb_type & HB_LOCK ) {
-		spin_lock_irqsave(&hashbin->hb_spinlock, flags);
+		if (nested_depth > 0)
+			spin_lock_irqsave_nested(&hashbin->hb_spinlock, flags,
+						 nested_depth);
+		else
+			spin_lock_irqsave(&hashbin->hb_spinlock, flags);
 	}
 
 	/*
@@ -428,7 +433,7 @@ int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
 
 	return 0;
 }
-EXPORT_SYMBOL(hashbin_delete);
+EXPORT_SYMBOL(hashbin_delete_nested);
 
 /********************* HASHBIN LIST OPERATIONS *********************/
 



> I'll try to fix that soon, thanks for the report.
> 
> Cheers,
> Samuel.
> 
> 
> > 	Dave
> > 
> > NET: Registered protocol family 23
> > NET: Unregistered protocol family 23
> > 
> > =============================================
> > [ INFO: possible recursive locking detected ]
> > 2.6.20-1.2966.fc7 #1
> > ---------------------------------------------
> > rmmod/16712 is trying to acquire lock:
> >  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> > 
> > but task is already holding lock:
> >  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> > 
> > other info that might help us debug this:
> > 1 lock held by rmmod/16712:
> >  #0:  (&hashbin->hb_spinlock){....}, at: [<ffffffff884bf476>] hashbin_delete+0x29/0x94 [irda]
> > 
> > stack backtrace:
> > 
> > Call Trace:
> >  [<ffffffff802a303b>] __lock_acquire+0x151/0xbc4
> >  [<ffffffff884c1517>] :irda:__irias_delete_attrib+0x0/0x31
> >  [<ffffffff802a3ea4>] lock_acquire+0x4c/0x65
> >  [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
> >  [<ffffffff80264011>] _spin_lock_irqsave+0x2c/0x3c
> >  [<ffffffff884bf476>] :irda:hashbin_delete+0x29/0x94
> >  [<ffffffff884c1918>] :irda:__irias_delete_object+0x0/0x39
> >  [<ffffffff884c193d>] :irda:__irias_delete_object+0x25/0x39
> >  [<ffffffff884bf48d>] :irda:hashbin_delete+0x40/0x94
> >  [<ffffffff884c5e3a>] :irda:iriap_cleanup+0x36/0x38
> >  [<ffffffff884c5fd6>] :irda:irda_cleanup+0x29/0x3a
> >  [<ffffffff802aa1e1>] sys_delete_module+0x199/0x1ca
> >  [<ffffffff8026ce36>] syscall_trace_enter+0x9a/0x9f
> >  [<ffffffff8025c2b5>] tracesys+0xdc/0xe1
> > 
> > 
> > -- 
> > http://www.codemonkey.org.uk

Re: irda rmmod lockdep trace.

[David Miller]

From: Samuel Ortiz <samuel@sortiz.org>
Date: Mon, 12 Mar 2007 02:38:43 +0200

> On Sat, Mar 10, 2007 at 07:43:26PM +0200, Samuel Ortiz wrote:
> > Hi Dave,
> > 
> > On Thu, Mar 08, 2007 at 05:54:36PM -0500, Dave Jones wrote:
> > > modprobe irda ; rmmod irda in 2.6.21rc3 gets me the spew below..
> > Well it seems that we call __irias_delete_object() from hashbin_delete(). Then
> > __irias_delete_object() calls itself hashbin_delete() again. We're trying to
> > get the lock recursively.
> Looking at the code more carefully, this seems to be a false positive:
> iriap_cleanup and and __irias_delete_object are taking 2 different locks from
> 2 different hashbin instances. The locks belong to the same lock class but
> they are hierarchically different. We need to tell the validator about it and
> the following patch does that. Comments are welcomed as I'm planning to push
> it to netdev soon:

I would strongly caution against adding any run-time overhead just to
cure a false lockdep warning.  Even adding a new function argument
is too much IMHO.

Make the cost show up for lockdep only, perhaps by putting each
hashbin lock into a seperate locking class?

Re: irda rmmod lockdep trace.

[Samuel Ortiz]

On 3/12/2007, "David Miller" <davem@davemloft.net> wrote:

>From: Samuel Ortiz <samuel@sortiz.org>
>Date: Mon, 12 Mar 2007 02:38:43 +0200
>
>> On Sat, Mar 10, 2007 at 07:43:26PM +0200, Samuel Ortiz wrote:
>> > Hi Dave,
>> >
>> > On Thu, Mar 08, 2007 at 05:54:36PM -0500, Dave Jones wrote:
>> > > modprobe irda ; rmmod irda in 2.6.21rc3 gets me the spew below..
>> > Well it seems that we call __irias_delete_object() from hashbin_delete(). Then
>> > __irias_delete_object() calls itself hashbin_delete() again. We're trying to
>> > get the lock recursively.
>> Looking at the code more carefully, this seems to be a false positive:
>> iriap_cleanup and and __irias_delete_object are taking 2 different locks from
>> 2 different hashbin instances. The locks belong to the same lock class but
>> they are hierarchically different. We need to tell the validator about it and
>> the following patch does that. Comments are welcomed as I'm planning to push
>> it to netdev soon:
>
>I would strongly caution against adding any run-time overhead just to
>cure a false lockdep warning.  Even adding a new function argument
>is too much IMHO.
>
>Make the cost show up for lockdep only, perhaps by putting each
>hashbin lock into a seperate locking class?
I considered that solution as well, and thought that it would then
prevent the hasbin locks from being ever validated by lockdep.
OTOH, the hashbin code is not likely to change anytime soon and is
currently validated.
Also, you will eventually push this code upstream, so I'd rather go for
that fix ;-)

Thanks for the comment.

Cheers,
Samuel.

Re: irda rmmod lockdep trace.

[Samuel Ortiz]

On Mon, Mar 12, 2007 at 04:49:21PM -0700, David Miller wrote:
> I would strongly caution against adding any run-time overhead just to
> cure a false lockdep warning.  Even adding a new function argument
> is too much IMHO.
> 
> Make the cost show up for lockdep only, perhaps by putting each
> hashbin lock into a seperate locking class?
Does that look better to you:

diff --git a/include/net/irda/irqueue.h b/include/net/irda/irqueue.h
index 335b0ac..67cb434 100644
--- a/include/net/irda/irqueue.h
+++ b/include/net/irda/irqueue.h
@@ -71,6 +71,7 @@ typedef struct hashbin_t {
 	int        hb_size;
 	spinlock_t hb_spinlock;		/* HB_LOCK - Can be used by the user */
 
+	struct lock_class_key hb_lock_key;
 	irda_queue_t* hb_queue[HASHBIN_SIZE] IRDA_ALIGN;
 
 	irda_queue_t* hb_current;
diff --git a/net/irda/irqueue.c b/net/irda/irqueue.c
index 9266233..c72ecee 100644
--- a/net/irda/irqueue.c
+++ b/net/irda/irqueue.c
@@ -370,6 +370,8 @@ hashbin_t *hashbin_new(int type)
 	/* Make sure all spinlock's are unlocked */
 	if ( hashbin->hb_type & HB_LOCK ) {
 		spin_lock_init(&hashbin->hb_spinlock);
+		lockdep_set_class(&hashbin->hb_spinlock,
+				  &hashbin->hb_lock_key);
 	}
 
 	return hashbin;


 

Re: irda rmmod lockdep trace.

[David Miller]

From: Samuel Ortiz <samuel@sortiz.org>
Date: Wed, 14 Mar 2007 02:50:03 +0200

> On Mon, Mar 12, 2007 at 04:49:21PM -0700, David Miller wrote:
> > I would strongly caution against adding any run-time overhead just to
> > cure a false lockdep warning.  Even adding a new function argument
> > is too much IMHO.
> > 
> > Make the cost show up for lockdep only, perhaps by putting each
> > hashbin lock into a seperate locking class?
> Does that look better to you:

Yes, it does.:)

Re: irda rmmod lockdep trace.

[Samuel Ortiz]

On Tue, Mar 13, 2007 at 07:22:37PM -0700, David Miller wrote:
> From: Samuel Ortiz <samuel@sortiz.org>
> Date: Wed, 14 Mar 2007 02:50:03 +0200
> 
> > On Mon, Mar 12, 2007 at 04:49:21PM -0700, David Miller wrote:
> > > I would strongly caution against adding any run-time overhead just to
> > > cure a false lockdep warning.  Even adding a new function argument
> > > is too much IMHO.
> > > 
> > > Make the cost show up for lockdep only, perhaps by putting each
> > > hashbin lock into a seperate locking class?
> > Does that look better to you:
> 
> Yes, it does.:)
Unfortunately, it doesn't work, as the lock key is not on the stack. We get
hit by the lockdep code checking if our lock key is static:

      if (!static_obj(key)) {
                printk("BUG: key %p not in .data!\n", key);
                DEBUG_LOCKS_WARN_ON(1);
                return;
        }

So, instead, I propose the following, which does work, and adds runtime
overhead only when LOCKDEP is enabled:

---
 net/irda/irqueue.c |    9 ++++++++-
 1 files changed, 8 insertions(+), 1 deletions(-)

diff --git a/net/irda/irqueue.c b/net/irda/irqueue.c
index 9266233..d058b46 100644
--- a/net/irda/irqueue.c
+++ b/net/irda/irqueue.c
@@ -384,6 +384,9 @@ EXPORT_SYMBOL(hashbin_new);
  *    for deallocating this structure if it's complex. If not the user can
  *    just supply kfree, which should take care of the job.
  */
+#ifdef CONFIG_LOCKDEP
+static int hashbin_lock_depth = 0;
+#endif
 int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
 {
 	irda_queue_t* queue;
@@ -395,7 +398,8 @@ int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
 
 	/* Synchronize */
 	if ( hashbin->hb_type & HB_LOCK ) {
-		spin_lock_irqsave(&hashbin->hb_spinlock, flags);
+		spin_lock_irqsave_nested(&hashbin->hb_spinlock, flags,
+					 hashbin_lock_depth++);
 	}
 
 	/*
@@ -419,6 +423,9 @@ int hashbin_delete( hashbin_t* hashbin, FREE_FUNC free_func)
 	/* Release lock */
 	if ( hashbin->hb_type & HB_LOCK) {
 		spin_unlock_irqrestore(&hashbin->hb_spinlock, flags);
+#ifdef CONFIG_LOCKDEP
+		hashbin_lock_depth--;
+#endif
 	}
 
 	/*