Re: What does inconsistent lock state mean?
On Thu, Dec 8, 2011 at 11:50 PM, Kai Meyer wrote:
> **
> On 12/08/2011 07:47 AM, Srivatsa Bhat wrote:
>
> 2 things:
> 1. Documentation/lockdep-design.txt explains the "cryptic lock state
> symbols".
> 2. Please post the lockdep splat _exactly_ as it appears, and _in full_
> (and without line-wrapping, if possible). Usually lockdep is
> intelligent
> enough to tell you the possible scenario that would lock up your
> system.
> That gives a very good clue, in case you find it difficult to make out
> what
> is wrong from the cryptic symbols.
>
> Regards,
> Srivatsa S. Bhat
>
>
>
>
> ___
> Kernelnewbies mailing list
> Kernelnewbies@kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>
>
> Oh, sorry. I suppose I only included things that made any sense to me. If
> I were to hazard a guess after reading through the design doc, it sounds
> like there's a problem with the context in which locks are being acquired?
> That seems odd to me, since I don't get the inconsistent lock state until
> I'm trying to spin_unlock &sblsnap_snapshot_table[i].sblsnap_lock (which
> is why I assume it's listed as one that's currently held.
>
>
> Dec 7 15:52:20 dev2 kernel: =
> Dec 7 15:52:20 dev2 kernel: [ INFO: inconsistent lock state ]
> Dec 7 15:52:20 dev2 kernel: 2.6.32-220.el6.x86_64.debug #1
> Dec 7 15:52:20 dev2 kernel: -
> Dec 7 15:52:20 dev2 kernel: inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W}
> usage.
> Dec 7 15:52:20 dev2 kernel: tee/1966 [HC0[0]:SC0[0]:HE1:SE1] takes:
> Dec 7 15:52:20 dev2 kernel: (&vblk->lock){?.-...}, at:
> [] sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: {IN-HARDIRQ-W} state was registered at:
> Dec 7 15:52:20 dev2 kernel: []
> __lock_acquire+0x77a/0x1570
> Dec 7 15:52:20 dev2 kernel: [] lock_acquire+0xa4/0x120
> Dec 7 15:52:20 dev2 kernel: []
> _spin_lock_irqsave+0x55/0xa0
> Dec 7 15:52:20 dev2 kernel: [] blk_done+0x2b/0x110
> [virtio_blk]
> Dec 7 15:52:20 dev2 kernel: []
> vring_interrupt+0x3c/0xd0 [virtio_ring]
> Dec 7 15:52:20 dev2 kernel: []
> handle_IRQ_event+0x50/0x160
> Dec 7 15:52:20 dev2 kernel: []
> handle_edge_irq+0xe0/0x170
> Dec 7 15:52:20 dev2 kernel: [] handle_irq+0x49/0xa0
> Dec 7 15:52:20 dev2 kernel: [] do_IRQ+0x6c/0xf0
> Dec 7 15:52:20 dev2 kernel: [] ret_from_intr+0x0/0x16
> Dec 7 15:52:20 dev2 kernel: [] default_idle+0x52/0xc0
> Dec 7 15:52:20 dev2 kernel: [] cpu_idle+0xbb/0x110
> Dec 7 15:52:20 dev2 kernel: []
> start_secondary+0x211/0x254
> Dec 7 15:52:20 dev2 kernel: irq event stamp: 4699
> Dec 7 15:52:20 dev2 kernel: hardirqs last enabled at (4699):
> [] __kmalloc+0x241/0x330
> Dec 7 15:52:20 dev2 kernel: hardirqs last disabled at (4698):
> [] __kmalloc+0x120/0x330
> Dec 7 15:52:20 dev2 kernel: softirqs last enabled at (4696):
> [] __do_softirq+0x14a/0x200
> Dec 7 15:52:20 dev2 kernel: softirqs last disabled at (4681):
> [] call_softirq+0x1c/0x30
> Dec 7 15:52:20 dev2 kernel:
> Dec 7 15:52:20 dev2 kernel: other info that might help us debug this:
> Dec 7 15:52:20 dev2 kernel: 1 lock held by tee/1966:
> Dec 7 15:52:20 dev2 kernel: #0:
> (&sblsnap_snapshot_table[i].sblsnap_lock){+.+.+.}, at: []
> sblsnap_snap_now+0xac/0x2a0 [sblsnap]
> Dec 7 15:52:20 dev2 kernel:
> Dec 7 15:52:20 dev2 kernel: stack backtrace:
> Dec 7 15:52:20 dev2 kernel: Pid: 1966, comm: tee Not tainted
> 2.6.32-220.el6.x86_64.debug #1
> Dec 7 15:52:20 dev2 kernel: Call Trace:
> Dec 7 15:52:20 dev2 kernel: [] ?
> print_usage_bug+0x177/0x180
> Dec 7 15:52:20 dev2 kernel: [] ? mark_lock+0x35d/0x430
> Dec 7 15:52:20 dev2 kernel: [] ?
> __lock_acquire+0x609/0x1570
> Dec 7 15:52:20 dev2 kernel: [] ?
> trace_hardirqs_off+0xd/0x10
> Dec 7 15:52:20 dev2 kernel: [] ?
> _spin_unlock_irqrestore+0x67/0x80
> Dec 7 15:52:20 dev2 kernel: [] ?
> release_console_sem+0x203/0x250
> Dec 7 15:52:20 dev2 kernel: [] ? lock_acquire+0xa4/0x120
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ? _spin_lock+0x36/0x70
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_patch_blkdev+0x74/0x120 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_get_snapshot+0x1f/0x60 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_create_snapshot+0x69/0x120 [sblsnap]
> Dec 7 15:52:20 dev2 kernel: [] ?
> sblsnap_config_w
Re: What does inconsistent lock state mean?
On 12/08/2011 07:47 AM, Srivatsa Bhat wrote:
2 things:
1. Documentation/lockdep-design.txt explains the "cryptic lock state
symbols".
2. Please post the lockdep splat _exactly_ as it appears, and _in full_
(and without line-wrapping, if possible). Usually lockdep is
intelligent
enough to tell you the possible scenario that would lock up your
system.
That gives a very good clue, in case you find it difficult to make
out what
is wrong from the cryptic symbols.
Regards,
Srivatsa S. Bhat
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Oh, sorry. I suppose I only included things that made any sense to me.
If I were to hazard a guess after reading through the design doc, it
sounds like there's a problem with the context in which locks are being
acquired? That seems odd to me, since I don't get the inconsistent lock
state until I'm trying to spin_unlock
&sblsnap_snapshot_table[i].sblsnap_lock (which is why I assume it's
listed as one that's currently held.
Dec 7 15:52:20 dev2 kernel: =
Dec 7 15:52:20 dev2 kernel: [ INFO: inconsistent lock state ]
Dec 7 15:52:20 dev2 kernel: 2.6.32-220.el6.x86_64.debug #1
Dec 7 15:52:20 dev2 kernel: -
Dec 7 15:52:20 dev2 kernel: inconsistent {IN-HARDIRQ-W} ->
{HARDIRQ-ON-W} usage.
Dec 7 15:52:20 dev2 kernel: tee/1966 [HC0[0]:SC0[0]:HE1:SE1] takes:
Dec 7 15:52:20 dev2 kernel: (&vblk->lock){?.-...}, at:
[] sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec 7 15:52:20 dev2 kernel: {IN-HARDIRQ-W} state was registered at:
Dec 7 15:52:20 dev2 kernel: []
__lock_acquire+0x77a/0x1570
Dec 7 15:52:20 dev2 kernel: [] lock_acquire+0xa4/0x120
Dec 7 15:52:20 dev2 kernel: []
_spin_lock_irqsave+0x55/0xa0
Dec 7 15:52:20 dev2 kernel: [] blk_done+0x2b/0x110
[virtio_blk]
Dec 7 15:52:20 dev2 kernel: []
vring_interrupt+0x3c/0xd0 [virtio_ring]
Dec 7 15:52:20 dev2 kernel: []
handle_IRQ_event+0x50/0x160
Dec 7 15:52:20 dev2 kernel: []
handle_edge_irq+0xe0/0x170
Dec 7 15:52:20 dev2 kernel: [] handle_irq+0x49/0xa0
Dec 7 15:52:20 dev2 kernel: [] do_IRQ+0x6c/0xf0
Dec 7 15:52:20 dev2 kernel: [] ret_from_intr+0x0/0x16
Dec 7 15:52:20 dev2 kernel: [] default_idle+0x52/0xc0
Dec 7 15:52:20 dev2 kernel: [] cpu_idle+0xbb/0x110
Dec 7 15:52:20 dev2 kernel: []
start_secondary+0x211/0x254
Dec 7 15:52:20 dev2 kernel: irq event stamp: 4699
Dec 7 15:52:20 dev2 kernel: hardirqs last enabled at (4699):
[] __kmalloc+0x241/0x330
Dec 7 15:52:20 dev2 kernel: hardirqs last disabled at (4698):
[] __kmalloc+0x120/0x330
Dec 7 15:52:20 dev2 kernel: softirqs last enabled at (4696):
[] __do_softirq+0x14a/0x200
Dec 7 15:52:20 dev2 kernel: softirqs last disabled at (4681):
[] call_softirq+0x1c/0x30
Dec 7 15:52:20 dev2 kernel:
Dec 7 15:52:20 dev2 kernel: other info that might help us debug this:
Dec 7 15:52:20 dev2 kernel: 1 lock held by tee/1966:
Dec 7 15:52:20 dev2 kernel: #0:
(&sblsnap_snapshot_table[i].sblsnap_lock){+.+.+.}, at:
[] sblsnap_snap_now+0xac/0x2a0 [sblsnap]
Dec 7 15:52:20 dev2 kernel:
Dec 7 15:52:20 dev2 kernel: stack backtrace:
Dec 7 15:52:20 dev2 kernel: Pid: 1966, comm: tee Not tainted
2.6.32-220.el6.x86_64.debug #1
Dec 7 15:52:20 dev2 kernel: Call Trace:
Dec 7 15:52:20 dev2 kernel: [] ?
print_usage_bug+0x177/0x180
Dec 7 15:52:20 dev2 kernel: [] ? mark_lock+0x35d/0x430
Dec 7 15:52:20 dev2 kernel: [] ?
__lock_acquire+0x609/0x1570
Dec 7 15:52:20 dev2 kernel: [] ?
trace_hardirqs_off+0xd/0x10
Dec 7 15:52:20 dev2 kernel: [] ?
_spin_unlock_irqrestore+0x67/0x80
Dec 7 15:52:20 dev2 kernel: [] ?
release_console_sem+0x203/0x250
Dec 7 15:52:20 dev2 kernel: [] ? lock_acquire+0xa4/0x120
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ? _spin_lock+0x36/0x70
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_patch_blkdev+0x74/0x120 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_get_snapshot+0x1f/0x60 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_create_snapshot+0x69/0x120 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
sblsnap_config_write+0x26b/0x2c0 [sblsnap]
Dec 7 15:52:20 dev2 kernel: [] ?
proc_file_write+0x73/0xb0
Dec 7 15:52:20 dev2 kernel: [] ? proc_file_write+0x0/0xb0
Dec 7 15:52:20 dev2 kernel: [] ? proc_reg_write+0x85/0xc0
Dec 7 15:52:20 dev2 kernel: [] ? vfs_write+0xb8/0x1a0
Dec 7 15:52:20 dev2 kernel: [] ?
audit_syscall_entry+0x272/0x2a0
Dec 7 15:52:20 dev2 kernel: [] ? sys_write+0x51/0x90
Dec 7 15:52:20 dev2 kernel: [] ?
system_call_fastpath+0x16/0x1b
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbie
Re: What does inconsistent lock state mean?
On Thu, Dec 8, 2011 at 4:49 AM, Kai Meyer wrote:
> I'm getting this when I try to spin_unlock a recently acquired lock with
> spin_lock. IRQs are still somewhat of a mystery to me, and cryptic lock
> state symbols (IN-HARDIRQ-W, HARDIRQ-ON-W) are unintelligible to me.
>
> Dec 7 15:52:20 dev2 kernel: =
> Dec 7 15:52:20 dev2 kernel: [ INFO: inconsistent lock state ]
> Dec 7 15:52:20 dev2 kernel: 2.6.32-220.el6.x86_64.debug #1
> Dec 7 15:52:20 dev2 kernel: -
> Dec 7 15:52:20 dev2 kernel: inconsistent {IN-HARDIRQ-W} ->
> {HARDIRQ-ON-W} usage.
>
> Looking at lockdep.c isn't giving me any help either. It's obfuscated
> beyond my ability to grok by simply reading the code.
>
> It seems like this portion should help me, but it doesn't
> Dec 7 15:52:20 dev2 kernel: {IN-HARDIRQ-W} state was registered at:
> Dec 7 15:52:20 dev2 kernel: []
> __lock_acquire+0x77a/0x1570
> Dec 7 15:52:20 dev2 kernel: [] lock_acquire+0xa4/0x120
> Dec 7 15:52:20 dev2 kernel: []
> _spin_lock_irqsave+0x55/0xa0
> Dec 7 15:52:20 dev2 kernel: [] blk_done+0x2b/0x110
> [virtio_blk]
> Dec 7 15:52:20 dev2 kernel: []
> vring_interrupt+0x3c/0xd0 [virtio_ring]
> Dec 7 15:52:20 dev2 kernel: []
> handle_IRQ_event+0x50/0x160
> Dec 7 15:52:20 dev2 kernel: []
> handle_edge_irq+0xe0/0x170
> Dec 7 15:52:20 dev2 kernel: [] handle_irq+0x49/0xa0
> Dec 7 15:52:20 dev2 kernel: [] do_IRQ+0x6c/0xf0
> Dec 7 15:52:20 dev2 kernel: [] ret_from_intr+0x0/0x16
> Dec 7 15:52:20 dev2 kernel: [] default_idle+0x52/0xc0
> Dec 7 15:52:20 dev2 kernel: [] cpu_idle+0xbb/0x110
> Dec 7 15:52:20 dev2 kernel: []
> start_secondary+0x211/0x254
>
> Then later it tells me that I'm holding 1 lock, which is the one that I
> mentioned at the beginning that was just recently locked.
>
>
2 things:
1. Documentation/lockdep-design.txt explains the "cryptic lock state
symbols".
2. Please post the lockdep splat _exactly_ as it appears, and _in full_
(and without line-wrapping, if possible). Usually lockdep is intelligent
enough to tell you the possible scenario that would lock up your system.
That gives a very good clue, in case you find it difficult to make out
what
is wrong from the cryptic symbols.
Regards,
Srivatsa S. Bhat
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
What does inconsistent lock state mean?
I'm getting this when I try to spin_unlock a recently acquired lock with
spin_lock. IRQs are still somewhat of a mystery to me, and cryptic lock
state symbols (IN-HARDIRQ-W, HARDIRQ-ON-W) are unintelligible to me.
Dec 7 15:52:20 dev2 kernel: =
Dec 7 15:52:20 dev2 kernel: [ INFO: inconsistent lock state ]
Dec 7 15:52:20 dev2 kernel: 2.6.32-220.el6.x86_64.debug #1
Dec 7 15:52:20 dev2 kernel: -
Dec 7 15:52:20 dev2 kernel: inconsistent {IN-HARDIRQ-W} ->
{HARDIRQ-ON-W} usage.
Looking at lockdep.c isn't giving me any help either. It's obfuscated
beyond my ability to grok by simply reading the code.
It seems like this portion should help me, but it doesn't
Dec 7 15:52:20 dev2 kernel: {IN-HARDIRQ-W} state was registered at:
Dec 7 15:52:20 dev2 kernel: []
__lock_acquire+0x77a/0x1570
Dec 7 15:52:20 dev2 kernel: [] lock_acquire+0xa4/0x120
Dec 7 15:52:20 dev2 kernel: []
_spin_lock_irqsave+0x55/0xa0
Dec 7 15:52:20 dev2 kernel: [] blk_done+0x2b/0x110
[virtio_blk]
Dec 7 15:52:20 dev2 kernel: []
vring_interrupt+0x3c/0xd0 [virtio_ring]
Dec 7 15:52:20 dev2 kernel: []
handle_IRQ_event+0x50/0x160
Dec 7 15:52:20 dev2 kernel: []
handle_edge_irq+0xe0/0x170
Dec 7 15:52:20 dev2 kernel: [] handle_irq+0x49/0xa0
Dec 7 15:52:20 dev2 kernel: [] do_IRQ+0x6c/0xf0
Dec 7 15:52:20 dev2 kernel: [] ret_from_intr+0x0/0x16
Dec 7 15:52:20 dev2 kernel: [] default_idle+0x52/0xc0
Dec 7 15:52:20 dev2 kernel: [] cpu_idle+0xbb/0x110
Dec 7 15:52:20 dev2 kernel: []
start_secondary+0x211/0x254
Then later it tells me that I'm holding 1 lock, which is the one that I
mentioned at the beginning that was just recently locked.
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: inconsistent lock state on call to kmem_cache_zalloc()
Daniel Baluta wrote:
> On Thu, Mar 17, 2011 at 10:59 PM, Arvid Brodin 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
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: inconsistent lock state on call to kmem_cache_zalloc()
On Thu, Mar 17, 2011 at 10:59 PM, Arvid Brodin 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. ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: inconsistent lock state on call to kmem_cache_zalloc()
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 ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: inconsistent lock state on call to kmem_cache_zalloc()
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. ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
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
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
"inconsistent lock state"
Hello,
I'm using spinlocks (spin_lock_irqsave() / spin_unlock_irqrestore()) to
protect shared resources between softirq, hardirq and non-irq kernel
contexts. When I configure PROVE_LOCKING I get
=
[ INFO: inconsistent lock state ]
2.6.27.54 #148
-
inconsistent {softirq-on-W} -> {in-softirq-W} usage.
khubd/85 [HC0[0]:SC1[1]:HE0:SE0] takes:
(&priv->lock){-+..}, at: [<90152430>] schedule_ptds+0x54/0x564
{softirq-on-W} state was registered at:
[<9003856e>] trace_hardirqs_on_caller+0x92/0xc4
[<900385a8>] trace_hardirqs_on+0x8/0xc
[<90058fc2>] __slab_alloc+0xee/0x3e4
[<90059f9c>] kmem_cache_alloc+0x30/0x70
etc...
I don't understand why. Assuming that "{softirq-on-W} -> {in-softirq-W}"
means that the problem is that the lock was taken in "softirq on" (irqs
enabled) state, and at some later time in softirq context, then what is
the problem? spin_lock_irqsave() disables irqs, right? So after the lock
is taken in non-irq context, softirq cannot interrupt?
There are code paths like this:
{
spin_lock_irqsave(...);
...
spin_unlock()
...
spin_lock()
...
spin_unlock_irqrestore(...);
}
in both non-irq and softirq contexts. Could this be a problem? If I
understand correctly, spin_lock() and spin_unlock() does not touch irq
settings, so the usage above should be fine, right?
Thanks,
Arvid Brodin
Enea Services Stockholm AB
___
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
