inconsistent lock state on call to kmem_cache_zalloc()

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

Hello,

What flags are you passing to kmem_cache_zalloc?

thanks,
Daniel.

Hi,

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,
Arvid Brodin
Enea Services Stockholm AB

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

Daniel.

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?

Arvid Brodin
Enea Services Stockholm AB