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: [<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 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.
On Thu, Dec 8, 2011 at 4:49 AM, Kai Meyer <kai@gnukai.com> 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: [<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
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
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
On Thu, Dec 8, 2011 at 11:50 PM, Kai Meyer <kai@gnukai.com> 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: [<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
The line print_usage_bug_scenario(this); seems to be missing in your kernel's print_usage_bug() function in kernel/lockdep.c If it was there (it is there in newer kernels), it would have showed pictorially what is the problem, and then most likely you wouldn't have to look at anything else to figure out what's the problem! That's the reason I asked for full output, but alas your lockdep seems to be old. Though, what exactly is the problem is not immediately apparent to me, I would certainly suggest using spin_lock_irqsave() and spin_unlock_irqrestore() functions, instead of just using the spin_lock() and spin_unlock() versions, whenever you are dealing with locks that have the possibility of being acquired by interrupt contexts (i.e., while servicing interrupts). Regards, Srivatsa S. Bhat
participants (2)
-
Kai Meyer -
Srivatsa Bhat