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
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
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.
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
participants (2)
-
Arvid Brodin -
Daniel Baluta