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: [<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