What does inconsistent lock state mean?

[Kai Meyer]

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 at 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: 
[<ffffffffa04c4d2a>] 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:  [<ffffffff810afbca>] 
__lock_acquire+0x77a/0x1570
Dec  7 15:52:20 dev2 kernel:  [<ffffffff810b0a64>] lock_acquire+0xa4/0x120
Dec  7 15:52:20 dev2 kernel:  [<ffffffff81520c75>] 
_spin_lock_irqsave+0x55/0xa0
Dec  7 15:52:20 dev2 kernel:  [<ffffffffa006b19b>] blk_done+0x2b/0x110 
[virtio_blk]
Dec  7 15:52:20 dev2 kernel:  [<ffffffffa00401dc>] 
vring_interrupt+0x3c/0xd0 [virtio_ring]
Dec  7 15:52:20 dev2 kernel:  [<ffffffff810ec080>] 
handle_IRQ_event+0x50/0x160
Dec  7 15:52:20 dev2 kernel:  [<ffffffff810ee840>] 
handle_edge_irq+0xe0/0x170
Dec  7 15:52:20 dev2 kernel:  [<ffffffff8100e059>] handle_irq+0x49/0xa0
Dec  7 15:52:20 dev2 kernel:  [<ffffffff81526cdc>] do_IRQ+0x6c/0xf0
Dec  7 15:52:20 dev2 kernel:  [<ffffffff8100ba93>] ret_from_intr+0x0/0x16
Dec  7 15:52:20 dev2 kernel:  [<ffffffff810148e2>] default_idle+0x52/0xc0
Dec  7 15:52:20 dev2 kernel:  [<ffffffff81009e0b>] cpu_idle+0xbb/0x110
Dec  7 15:52:20 dev2 kernel:  [<ffffffff81516623>] 
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): 
[<ffffffff81179e81>] __kmalloc+0x241/0x330
Dec  7 15:52:20 dev2 kernel: hardirqs last disabled at (4698): 
[<ffffffff81179d60>] __kmalloc+0x120/0x330
Dec  7 15:52:20 dev2 kernel: softirqs last  enabled at (4696): 
[<ffffffff81076baa>] __do_softirq+0x14a/0x200
Dec  7 15:52:20 dev2 kernel: softirqs last disabled at (4681): 
[<ffffffff8100c30c>] 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: 
[<ffffffffa04c4b7c>] 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: [<ffffffff810ad947>] ? 
print_usage_bug+0x177/0x180
Dec  7 15:52:20 dev2 kernel: [<ffffffff810ae8ed>] ? mark_lock+0x35d/0x430
Dec  7 15:52:20 dev2 kernel: [<ffffffff810afa59>] ? 
__lock_acquire+0x609/0x1570
Dec  7 15:52:20 dev2 kernel: [<ffffffff810ab31d>] ? 
trace_hardirqs_off+0xd/0x10
Dec  7 15:52:20 dev2 kernel: [<ffffffff815208e7>] ? 
_spin_unlock_irqrestore+0x67/0x80
Dec  7 15:52:20 dev2 kernel: [<ffffffff8106ec43>] ? 
release_console_sem+0x203/0x250
Dec  7 15:52:20 dev2 kernel: [<ffffffff810b0a64>] ? lock_acquire+0xa4/0x120
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4d2a>] ? 
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffff81520af6>] ? _spin_lock+0x36/0x70
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4d2a>] ? 
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4d2a>] ? 
sblsnap_snap_now+0x25a/0x2a0 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4de4>] ? 
sblsnap_patch_blkdev+0x74/0x120 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4eaf>] ? 
sblsnap_get_snapshot+0x1f/0x60 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c4f59>] ? 
sblsnap_create_snapshot+0x69/0x120 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffffa04c53cb>] ? 
sblsnap_config_write+0x26b/0x2c0 [sblsnap]
Dec  7 15:52:20 dev2 kernel: [<ffffffff81200343>] ? 
proc_file_write+0x73/0xb0
Dec  7 15:52:20 dev2 kernel: [<ffffffff812002d0>] ? proc_file_write+0x0/0xb0
Dec  7 15:52:20 dev2 kernel: [<ffffffff811f97c5>] ? proc_reg_write+0x85/0xc0
Dec  7 15:52:20 dev2 kernel: [<ffffffff81193318>] ? vfs_write+0xb8/0x1a0
Dec  7 15:52:20 dev2 kernel: [<ffffffff810e68b2>] ? 
audit_syscall_entry+0x272/0x2a0
Dec  7 15:52:20 dev2 kernel: [<ffffffff81193d21>] ? sys_write+0x51/0x90
Dec  7 15:52:20 dev2 kernel: [<ffffffff8100b0b2>] ? 
system_call_fastpath+0x16/0x1b

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20111208/b711349a/attachment.html