inconsistent lock state on call to kmem_cache_zalloc()

inconsistent lock state on call to kmem_cache_zalloc()

[Arvid Brodin]

On a call to kmem_cache_zalloc(), I get this:

=================================
[ INFO: inconsistent lock state ]
2.6.37 #116
---------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
khubd/133 [HC0[0]:SC0[0]:HE1:SE1] takes:
 (&(&priv->lock)->rlock){?.-...}, at: [<9017a508>] isp1760_urb_enqueue+0x24c/0x3e4
{IN-HARDIRQ-W} state was registered at:
  [<90043476>] lock_acquire+0x3a/0x48
  [<90236210>] _raw_spin_lock_irqsave+0x28/0x50
  [<9017a7ac>] isp1760_irq+0x44/0x3b4
  [<9016ffec>] usb_hcd_irq+0x68/0x70
...

And I cannot understand why. (I'm also unsure about the syntax - what does
"IN-HARDIRQ-W" and "HARDIRQ-ON-W" mean?)

Background:

I have an interrupt routine isp1760_irq() that calls
	spin_lock(&priv->lock)
	...
	spin_unlock(&priv->lock)

I also take this lock in isp1760_urb_enqueue() mentioned in the printout. I
believe this function gets called by the USB core when an urb should be
transferred. isp1760_urb_enqueue() uses

	spin_lock_irqsave(&priv->lock, spinflags);
	...
	spin_unlock_irqrestore(&priv->lock, spinflags);

isp1760_urb_enqueue() also calls kmem_cache_zalloc(); this is what apparently
triggers the printout above (the lock have already been successfully taken).

The call to kmem_cache_zalloc() never returns; the printk() text on the line
after is never displayed and the system locks up. The printk() om the line
before displays.

I also get an additional BUG:

BUG: spinlock lockup on CPU#0, khubd/133, 93dcc138
Call trace:
 [<9001d370>] dump_stack+0x18/0x20
 [<9012e7aa>] do_raw_spin_lock+0x9a/0xc8
 [<9023622a>] _raw_spin_lock_irqsave+0x42/0x50
 [<9017a7ac>] isp1760_irq+0x44/0x3b4
 [<9016ffec>] usb_hcd_irq+0x68/0x70
 [<9004b2fc>] handle_IRQ_event+0x16/0x92
 [<9004cbec>] handle_level_irq+0xb0/0xc8
 [<9001ad28>] demux_eic_irq+0x38/0x50
 [<9001ac36>] do_IRQ+0x36/0x5c
 [<90019428>] irq_level0+0x18/0x60
 [<9006aa96>] kmem_cache_alloc+0x4a/0x90
 [<9017a59c>] isp1760_urb_enqueue+0x2e0/0x3e4
 [<90170e54>] usb_hcd_submit_urb+0x6d4/0x758
 [<90171186>] usb_submit_urb+0x1ce/0x1e0
 [<901718aa>] usb_start_wait_urb+0x32/0x80
 [<90171bc4>] usb_control_msg+0xc0/0xd8
 [<9016d6ac>] hub_port_init+0x218/0x528
 [<9016e672>] hub_thread+0x5aa/0xa38
 [<900358c6>] kthread+0x58/0x62
 [<90027c4a>] do_exit+0x0/0x43e

which seems very weird to me, since it looks like isp1760_irq() gets called
even though I thought I had disabled interrupts with spin_lock_irqsave() in
isp1760_urb_enqueue().

Obviously I have not understood the locking in the kernel. What have I done
wrong here?

Thanks,
Arvid Brodin
Enea Services Stockholm AB

inconsistent lock state on call to kmem_cache_zalloc()

[Daniel Baluta]

Hello,

> The call to kmem_cache_zalloc() never returns; the printk() text on the line
> after is never displayed and the system locks up. The printk() om the line
> before displays.

What flags are you passing to kmem_cache_zalloc?

thanks,
Daniel.

inconsistent lock state on call to kmem_cache_zalloc()

[Arvid Brodin]

Hi,

Daniel Baluta wrote:
> Hello,
> 
>> The call to kmem_cache_zalloc() never returns; the printk() text on the line
>> after is never displayed and the system locks up. The printk() om the line
>> before displays.
> 
> What flags are you passing to kmem_cache_zalloc?

I'm using the flags passed to the urb_enqueue() function; a printk reveals
the value is 16, which would be GFP_NOIO if I read include/linux/gfp.h correctly.

> thanks,
> Daniel.

Thanks,
Arvid Brodin
Enea Services Stockholm AB

inconsistent lock state on call to kmem_cache_zalloc()

[Daniel Baluta]

On Thu, Mar 17, 2011 at 10:59 PM, Arvid Brodin <arvid.brodin@enea.com> wrote:
> Hi,
>
> Daniel Baluta wrote:
>> Hello,
>>
>>> The call to kmem_cache_zalloc() never returns; the printk() text on the line
>>> after is never displayed and the system locks up. The printk() om the line
>>> before displays.
>>
>> What flags are you passing to kmem_cache_zalloc?
>
> I'm using the flags passed to the urb_enqueue() function; a printk reveals
> the value is 16, which would be GFP_NOIO if I read include/linux/gfp.h correctly.

Hmm, I guess this is not quite OK. You hold a spinlock, and you can sleep
while allocating memory.

Daniel.

inconsistent lock state on call to kmem_cache_zalloc()

[Arvid Brodin]

Daniel Baluta wrote:
> On Thu, Mar 17, 2011 at 10:59 PM, Arvid Brodin <arvid.brodin@enea.com> wrote:
>> Hi,
>>
>> Daniel Baluta wrote:
>>> Hello,
>>>
>>>> The call to kmem_cache_zalloc() never returns; the printk() text on the line
>>>> after is never displayed and the system locks up. The printk() om the line
>>>> before displays.
>>> What flags are you passing to kmem_cache_zalloc?
>> I'm using the flags passed to the urb_enqueue() function; a printk reveals
>> the value is 16, which would be GFP_NOIO if I read include/linux/gfp.h correctly.
> 
> Hmm, I guess this is not quite OK. You hold a spinlock, and you can sleep
> while allocating memory.

I can see why this is not a good idea, and indeed using GFP_ATOMIC gets rid of the

=================================
[ INFO: inconsistent lock state ]
2.6.37 #116
---------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
...

message. Many thanks!

To the list in general:

Still, I would have expected some kind of "You're sleeping while holding a
spinlock / with interrupts disabled!" message (I have DEBUG_SPINLOCK_SLEEP
enabled), not a message from the lock debug code. Well... perhaps one of the
'W's in the message stands for "wait"? Also, the call stack in my original
mail shows the interrupt routine being called despite having disabled
interrupts - are they automatically enabled by functions that sleep?

> 
> Daniel.

-- 
Arvid Brodin
Enea Services Stockholm AB