LinuxLists.cc - 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Mark Lord wrote:
> =================================
> [ INFO: inconsistent lock state ]
> 2.6.19-rc3-git7-ml #3
> ---------------------------------
> inconsistent {in-softirq-W} -> {softirq-on-W} usage.
> startproc/4046 [HC0[0]:SC0[0]:HE1:SE1] takes:
> (&q->__queue_lock){-+..}, at: [<c0219091>] cfq_set_request+0x351/0x3b0
> {in-softirq-W} state was registered at:
> [<c01376b1>] mark_lock+0x81/0x5f0
> [<c0138a90>] __lock_acquire+0x660/0xc10
> [<c013939d>] lock_acquire+0x5d/0x80
> [<c0361c59>] _spin_lock+0x29/0x40
> [<c029fa24>] scsi_device_unbusy+0x64/0x90
> [<c029a5bc>] scsi_finish_command+0x1c/0xa0
> [<c02115c2>] blk_done_softirq+0x62/0x70
> [<c0122a27>] __do_softirq+0x87/0x100
> [<c0122af5>] do_softirq+0x55/0x60
> [<c0122f3c>] ksoftirqd+0x7c/0xd0
> [<c0130f76>] kthread+0xf6/0x100
> [<c0103c6f>] kernel_thread_helper+0x7/0x18
> [<ffffffff>] 0xffffffff
> irq event stamp: 3331
> hardirqs last enabled at (3331): [<c016326d>] kmem_cache_alloc+0x6d/0xa0
> hardirqs last disabled at (3330): [<c016321f>] kmem_cache_alloc+0x1f/0xa0
> softirqs last enabled at (3012): [<c0122af5>] do_softirq+0x55/0x60
> softirqs last disabled at (2971): [<c0122af5>] do_softirq+0x55/0x60

Not sure what exactly is complained about here. The queue_lock must
always be grabbed with an irq disabling option, such as _irq or _irqsave
if potentially in interrupt context. I'm guessing it's the
scsi_device_unbusy() locking sequence that confuses it:

spin_lock_irqsave(shost->host_lock, flags);
...
spin_unlock(shost->host_lock);
spin_lock(sdev->request_queue->queue_lock);
...
spin_unlock_irqrestore(sdev->request_queue->queue_lock, flags);

which has always been considered safe, while not very pretty.

Ingo?

--
Jens Axboe

2006-10-30 14:57:26

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

> which has always been considered safe, while not very pretty.

actually it's different I think (based on a brief inspection of the
code, I could well be wrong):
get_request_wait() causes a get_request() call with a GFP_NOIO gfp_mask
which perculates upto cfq_set_request() as argument.
cfq_set_request() then calls the inline cfq_get_queue() (which isn't in
the backtrace due to inlining) which does
} else if (gfp_mask & __GFP_WAIT) {
/*
* Inform the allocator of the fact that we will
* just repeat this allocation if it fails, to allow
* the allocator to do whatever it needs to attempt to
* free memory.
*/
spin_unlock_irq(cfqd->queue->queue_lock);

which enables interrupts right smack in the middle of holding a whole
bunch of locks.....

so to me it looks like lockdep at least has the appearance of moaning
about a reasonably fishy situation...

--
if you want to mail me at work (you don't), use arjan (at) linux.intel.com
Test the interaction between Linux and your BIOS via http://www.linuxfirmwarekit.org

2006-10-30 15:43:09

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Arjan van de Ven wrote:
>
> > which has always been considered safe, while not very pretty.
>
>
> actually it's different I think (based on a brief inspection of the
> code, I could well be wrong):
> get_request_wait() causes a get_request() call with a GFP_NOIO gfp_mask
> which perculates upto cfq_set_request() as argument.
> cfq_set_request() then calls the inline cfq_get_queue() (which isn't in
> the backtrace due to inlining) which does
> } else if (gfp_mask & __GFP_WAIT) {
> /*
> * Inform the allocator of the fact that we will
> * just repeat this allocation if it fails, to allow
> * the allocator to do whatever it needs to attempt to
> * free memory.
> */
> spin_unlock_irq(cfqd->queue->queue_lock);
>
> which enables interrupts right smack in the middle of holding a whole
> bunch of locks.....

Where do you get 'a bunch' from? If you call get_request() with a
gfp_mask that includes __GFP_WAIT with a spinlock held, it's a bug. Just
as if you had called kmalloc() or similar with __GFP_WAIT set and
holding a lock. cfq even includes a warning check:

might_sleep_if(gfp_mask & __GFP_WAIT);

So there's no bug there, cfq even grabbed the lock on its own before
calling cfq_get_queue().

> so to me it looks like lockdep at least has the appearance of moaning
> about a reasonably fishy situation...

To me it looks more about lockdep complaining because it doesn't grok
the full picture. The question is how to shut it up.

--
Jens Axboe

2006-10-30 16:16:48

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

>
> > so to me it looks like lockdep at least has the appearance of moaning
> > about a reasonably fishy situation...
>
> To me it looks more about lockdep complaining because it doesn't grok
> the full picture. The question is how to shut it up.

ok that is quite possible. But I do think you read the original output
incorrectly so let me at least phrase it in english:

__queue_lock is used in softirq context like this:
[<c0361c59>] _spin_lock+0x29/0x40
[<c029fa24>] scsi_device_unbusy+0x64/0x90
[<c029a5bc>] scsi_finish_command+0x1c/0xa0
[<c02115c2>] blk_done_softirq+0x62/0x70
[<c0122a27>] __do_softirq+0x87/0x100
[<c0122af5>] do_softirq+0x55/0x60
[<c0122f3c>] ksoftirqd+0x7c/0xd0
[<c0130f76>] kthread+0xf6/0x100

which means that it always has to be taken _irq / _irqsave and one never
can enable interrupts while holding this lock. This backtrace is from
the first time the lock was taken in irq context.

Now a new situation has arisen that violates this constraint, and it
looks like this:

[<c0219091>] cfq_set_request+0x351/0x3b0
[<c020c7fc>] elv_set_request+0x1c/0x40
[<c020fcff>] get_request+0x23f/0x270
[<c0210537>] get_request_wait+0x27/0x120
[<c02107ca>] __make_request+0x5a/0x350
[<c020f40f>] generic_make_request+0x16f/0x220
[<c02117e4>] submit_bio+0x64/0x110

now cfq_set_request() uses several inlines which muddies the situation,
but lockdep claims one of them is not done correctly. (eg either it
takes the lock incorrectly or something does spin_unlock_irq while the
lock is held)

I get the impression you assumed lockdep was complaining about
scsi_device_unbusy; but it's not; that function is only referenced since
it's the first place since boot where the lock was taken in softirq
context... not because the violation is occuring there.

--
if you want to mail me at work (you don't), use arjan (at) linux.intel.com
Test the interaction between Linux and your BIOS via http://www.linuxfirmwarekit.org

2006-10-30 16:24:44

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Arjan van de Ven wrote:
>
> >
> > > so to me it looks like lockdep at least has the appearance of moaning
> > > about a reasonably fishy situation...
> >
> > To me it looks more about lockdep complaining because it doesn't grok
> > the full picture. The question is how to shut it up.
>
> ok that is quite possible. But I do think you read the original output
> incorrectly so let me at least phrase it in english:
>
>
> __queue_lock is used in softirq context like this:
> [<c0361c59>] _spin_lock+0x29/0x40
> [<c029fa24>] scsi_device_unbusy+0x64/0x90
> [<c029a5bc>] scsi_finish_command+0x1c/0xa0
> [<c02115c2>] blk_done_softirq+0x62/0x70
> [<c0122a27>] __do_softirq+0x87/0x100
> [<c0122af5>] do_softirq+0x55/0x60
> [<c0122f3c>] ksoftirqd+0x7c/0xd0
> [<c0130f76>] kthread+0xf6/0x100
>
> which means that it always has to be taken _irq / _irqsave and one never
> can enable interrupts while holding this lock. This backtrace is from
> the first time the lock was taken in irq context.
>
> Now a new situation has arisen that violates this constraint, and it
> looks like this:
>
>
> [<c0219091>] cfq_set_request+0x351/0x3b0
> [<c020c7fc>] elv_set_request+0x1c/0x40
> [<c020fcff>] get_request+0x23f/0x270
> [<c0210537>] get_request_wait+0x27/0x120
> [<c02107ca>] __make_request+0x5a/0x350
> [<c020f40f>] generic_make_request+0x16f/0x220
> [<c02117e4>] submit_bio+0x64/0x110
>
> now cfq_set_request() uses several inlines which muddies the situation,
> but lockdep claims one of them is not done correctly. (eg either it
> takes the lock incorrectly or something does spin_unlock_irq while the
> lock is held)

It's not really inlined trickery, the trace is exactly as printed. A few
things may be allocated from that path, so we pass gfp_mask around. I'll
double check it tonight, but I don't currently see what could be wrong.
Would lockdep complain about:

spin_lock_irqsave(lock, flags);
...
spin_unlock_irq(lock);
...
spin_lock_irq(lock);
...
spin_unlock_irqrestore(lock, flags);

? cfq will do that, but only if it knew that interrupts were currently
enabled when we originally made the _irqsave call (when __GFP_WAIT is
set).

> I get the impression you assumed lockdep was complaining about
> scsi_device_unbusy; but it's not; that function is only referenced since
> it's the first place since boot where the lock was taken in softirq
> context... not because the violation is occuring there.

Yeah, I read it in the reverse order. To be honest, the lockdep output
is not immediately parseable to me, I guess I need to read the
documentation.

--
Jens Axboe

2006-10-30 16:32:04

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

> >
> >
> > [<c0219091>] cfq_set_request+0x351/0x3b0
> > [<c020c7fc>] elv_set_request+0x1c/0x40
> > [<c020fcff>] get_request+0x23f/0x270
> > [<c0210537>] get_request_wait+0x27/0x120
> > [<c02107ca>] __make_request+0x5a/0x350
> > [<c020f40f>] generic_make_request+0x16f/0x220
> > [<c02117e4>] submit_bio+0x64/0x110
> >
> > now cfq_set_request() uses several inlines which muddies the situation,
> > but lockdep claims one of them is not done correctly. (eg either it
> > takes the lock incorrectly or something does spin_unlock_irq while the
> > lock is held)
>
> It's not really inlined trickery, the trace is exactly as printed.

what I meant is that cfq_set_request() calls a few inlines that also
take locks so it might be one of those instead

> A few
> things may be allocated from that path, so we pass gfp_mask around. I'll
> double check it tonight, but I don't currently see what could be wrong.
> Would lockdep complain about:
>
> spin_lock_irqsave(lock, flags);
> ...
> spin_unlock_irq(lock);
> ...
> spin_lock_irq(lock);
> ...
> spin_unlock_irqrestore(lock, flags);

this is fine for lockdep IF and only IF there is no "out lock" held
around this that requires irqs to be off. So if you do

spin_lock_irqsave(lock1, flags);
...
spin_lock_irqsave(lock2, flags);
spin_unlock_irq(lock2)
...

then lockdep WILL complain, and rightfully so, about a violation since
lock1 gets violated here ;)

--
if you want to mail me at work (you don't), use arjan (at) linux.intel.com
Test the interaction between Linux and your BIOS via http://www.linuxfirmwarekit.org

2006-10-30 17:50:48

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Arjan van de Ven wrote:
>
> > >
> > >
> > > [<c0219091>] cfq_set_request+0x351/0x3b0
> > > [<c020c7fc>] elv_set_request+0x1c/0x40
> > > [<c020fcff>] get_request+0x23f/0x270
> > > [<c0210537>] get_request_wait+0x27/0x120
> > > [<c02107ca>] __make_request+0x5a/0x350
> > > [<c020f40f>] generic_make_request+0x16f/0x220
> > > [<c02117e4>] submit_bio+0x64/0x110
> > >
> > > now cfq_set_request() uses several inlines which muddies the situation,
> > > but lockdep claims one of them is not done correctly. (eg either it
> > > takes the lock incorrectly or something does spin_unlock_irq while the
> > > lock is held)
> >
> > It's not really inlined trickery, the trace is exactly as printed.
>
> what I meant is that cfq_set_request() calls a few inlines that also
> take locks so it might be one of those instead

I looked over them, and cfq_cic_link() should use _irqsave() instead of
_irq() if called without __GFP_WAIT set. That doesn't happen in the
normal io path though, so I'm not sure that is it.

So if the bug is using spin_lock_irq() with interrupts already disabled,
iirc that would trigger a different warning...

> > A few
> > things may be allocated from that path, so we pass gfp_mask around. I'll
> > double check it tonight, but I don't currently see what could be wrong.
> > Would lockdep complain about:
> >
> > spin_lock_irqsave(lock, flags);
> > ...
> > spin_unlock_irq(lock);
> > ...
> > spin_lock_irq(lock);
> > ...
> > spin_unlock_irqrestore(lock, flags);
>
> this is fine for lockdep IF and only IF there is no "out lock" held
> around this that requires irqs to be off. So if you do
>
> spin_lock_irqsave(lock1, flags);
> ...
> spin_lock_irqsave(lock2, flags);
> spin_unlock_irq(lock2)
> ...
>
> then lockdep WILL complain, and rightfully so, about a violation since
> lock1 gets violated here ;)

Naturally, that is a bug fair and simple, nothing to do with lockdep.

diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
index 4bae64e..da9bddf 100644
--- a/block/cfq-iosched.c
+++ b/block/cfq-iosched.c
@@ -1355,6 +1355,7 @@ cfq_cic_link(struct cfq_data *cfqd, stru
struct rb_node **p;
struct rb_node *parent;
struct cfq_io_context *__cic;
+ unsigned long flags;
void *k;

cic->ioc = ioc;
@@ -1384,9 +1385,9 @@ restart:
rb_link_node(&cic->rb_node, parent, p);
rb_insert_color(&cic->rb_node, &ioc->cic_root);

- spin_lock_irq(cfqd->queue->queue_lock);
+ spin_lock_irqsave(cfqd->queue->queue_lock, flags);
list_add(&cic->queue_list, &cfqd->cic_list);
- spin_unlock_irq(cfqd->queue->queue_lock);
+ spin_unlock_irqrestore(cfqd->queue->queue_lock, flags);
}

/*

--
Jens Axboe

2006-10-30 17:54:40

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

Jens Axboe wrote:
> I looked over them, and cfq_cic_link() should use _irqsave() instead of
> _irq() if called without __GFP_WAIT set. That doesn't happen in the
> normal io path though, so I'm not sure that is it.
>
> So if the bug is using spin_lock_irq() with interrupts already disabled,
> iirc that would trigger a different warning...
..

This seems 100% reproduceable here, so if there's any specific instrumentation
that might be useful, just let me know. Meanwhile I'll try Jen's patch (below).

-ml

>
> diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
> index 4bae64e..da9bddf 100644
> --- a/block/cfq-iosched.c
> +++ b/block/cfq-iosched.c
> @@ -1355,6 +1355,7 @@ cfq_cic_link(struct cfq_data *cfqd, stru
> struct rb_node **p;
> struct rb_node *parent;
> struct cfq_io_context *__cic;
> + unsigned long flags;
> void *k;
>
> cic->ioc = ioc;
> @@ -1384,9 +1385,9 @@ restart:
> rb_link_node(&cic->rb_node, parent, p);
> rb_insert_color(&cic->rb_node, &ioc->cic_root);
>
> - spin_lock_irq(cfqd->queue->queue_lock);
> + spin_lock_irqsave(cfqd->queue->queue_lock, flags);
> list_add(&cic->queue_list, &cfqd->cic_list);
> - spin_unlock_irq(cfqd->queue->queue_lock);
> + spin_unlock_irqrestore(cfqd->queue->queue_lock, flags);
> }

2006-10-30 17:54:30

by Ingo Molnar

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

* Jens Axboe <[email protected]> wrote:

> > > things may be allocated from that path, so we pass gfp_mask around. I'll
> > > double check it tonight, but I don't currently see what could be wrong.
> > > Would lockdep complain about:
> > >
> > > spin_lock_irqsave(lock, flags);
> > > ...
> > > spin_unlock_irq(lock);
> > > ...
> > > spin_lock_irq(lock);
> > > ...
> > > spin_unlock_irqrestore(lock, flags);
> >
> > this is fine for lockdep IF and only IF there is no "out lock" held
> > around this that requires irqs to be off. So if you do
> >
> > spin_lock_irqsave(lock1, flags);
> > ...
> > spin_lock_irqsave(lock2, flags);
> > spin_unlock_irq(lock2)
> > ...
> >
> > then lockdep WILL complain, and rightfully so, about a violation since
> > lock1 gets violated here ;)
>
> Naturally, that is a bug fair and simple, nothing to do with lockdep.

well, finding such locking bugs is the main purpose of lockdep, so there
is at least some connection i'd say ;-)

Ingo

2006-10-30 17:56:39

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

> > what I meant is that cfq_set_request() calls a few inlines that also
> > take locks so it might be one of those instead
>
> I looked over them, and cfq_cic_link() should use _irqsave() instead of
> _irq() if called without __GFP_WAIT set. That doesn't happen in the
> normal io path though, so I'm not sure that is it.
>
> So if the bug is using spin_lock_irq() with interrupts already disabled,
> iirc that would trigger a different warning...

it's not spin_lock_irq() that'll warn, but the unlock... :)

> Naturally, that is a bug fair and simple, nothing to do with lockdep.
>
>
> diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
> index 4bae64e..da9bddf 100644
> --- a/block/cfq-iosched.c
> +++ b/block/cfq-iosched.c
> @@ -1355,6 +1355,7 @@ cfq_cic_link(struct cfq_data *cfqd, stru
> structirely reason rb_node **p;
> struct rb_node *parent;
> struct cfq_io_context *__cic;
> + unsigned long flags;
> void *k;
>
> cic->ioc = ioc;
> @@ -1384,9 +1385,9 @@ restart:
> rb_link_node(&cic->rb_node, parent, p);
> rb_insert_color(&cic->rb_node, &ioc->cic_root);
>
> - spin_lock_irq(cfqd->queue->queue_lock);
> + spin_lock_irqsave(cfqd->queue->queue_lock, flags);
> list_add(&cic->queue_list, &cfqd->cic_list);
> - spin_unlock_irq(cfqd->queue->queue_lock);
> + spin_unlock_irqrestore(cfqd->queue->queue_lock, flags);
> }

this looks entirely reasonable and correct

Acked-By: Arjan van de Ven <[email protected]>

--
if you want to mail me at work (you don't), use arjan (at) linux.intel.com
Test the interaction between Linux and your BIOS via http://www.linuxfirmwarekit.org

2006-10-30 17:58:43

by Ingo Molnar

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

* Arjan van de Ven <[email protected]> wrote:

> > struct rb_node *parent;
> > struct cfq_io_context *__cic;
> > + unsigned long flags;
> > void *k;
> >
> > cic->ioc = ioc;
> > @@ -1384,9 +1385,9 @@ restart:
> > rb_link_node(&cic->rb_node, parent, p);
> > rb_insert_color(&cic->rb_node, &ioc->cic_root);
> >
> > - spin_lock_irq(cfqd->queue->queue_lock);
> > + spin_lock_irqsave(cfqd->queue->queue_lock, flags);
> > list_add(&cic->queue_list, &cfqd->cic_list);
> > - spin_unlock_irq(cfqd->queue->queue_lock);
> > + spin_unlock_irqrestore(cfqd->queue->queue_lock, flags);
> > }
>
> this looks entirely reasonable and correct
>
> Acked-By: Arjan van de Ven <[email protected]>

yep.

Acked-by: Ingo Molnar <[email protected]>

Ingo

2006-10-30 18:02:19

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Ingo Molnar wrote:
>
> * Jens Axboe <[email protected]> wrote:
>
> > > > things may be allocated from that path, so we pass gfp_mask around. I'll
> > > > double check it tonight, but I don't currently see what could be wrong.
> > > > Would lockdep complain about:
> > > >
> > > > spin_lock_irqsave(lock, flags);
> > > > ...
> > > > spin_unlock_irq(lock);
> > > > ...
> > > > spin_lock_irq(lock);
> > > > ...
> > > > spin_unlock_irqrestore(lock, flags);
> > >
> > > this is fine for lockdep IF and only IF there is no "out lock" held
> > > around this that requires irqs to be off. So if you do
> > >
> > > spin_lock_irqsave(lock1, flags);
> > > ...
> > > spin_lock_irqsave(lock2, flags);
> > > spin_unlock_irq(lock2)
> > > ...
> > >
> > > then lockdep WILL complain, and rightfully so, about a violation since
> > > lock1 gets violated here ;)
> >
> > Naturally, that is a bug fair and simple, nothing to do with lockdep.
>
> well, finding such locking bugs is the main purpose of lockdep, so there
> is at least some connection i'd say ;-)

Right, I'm totally with you on that one, I wasn't trying to state
otherwise :-)

But we've also had a class of lockdep complaints that simply need some
sort of annotation so that lockdep understands there's nothing wrong
with it.

--
Jens Axboe

2006-10-30 18:11:52

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

Mark Lord wrote:
> Jens Axboe wrote:
..
>> diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
>> index 4bae64e..da9bddf 100644
>> --- a/block/cfq-iosched.c
>> +++ b/block/cfq-iosched.c
..

It's still there. I also see it with the SLES10 kernel 2.6.16.21-0.8.

[ INFO: inconsistent lock state ]
2.6.19-rc3-git7-ml #3
---------------------------------
inconsistent {in-softirq-W} -> {softirq-on-W} usage.
startproc/4046 [HC0[0]:SC0[0]:HE1:SE1] takes:
(&q->__queue_lock){-+..}, at: [<c0219091>] cfq_set_request+0x351/0x3b0
{in-softirq-W} state was registered at:
[<c01376b1>] mark_lock+0x81/0x5f0
[<c0138a90>] __lock_acquire+0x660/0xc10
[<c013939d>] lock_acquire+0x5d/0x80
[<c0361c59>] _spin_lock+0x29/0x40
[<c029fa24>] scsi_device_unbusy+0x64/0x90
[<c029a5bc>] scsi_finish_command+0x1c/0xa0
[<c02115c2>] blk_done_softirq+0x62/0x70
[<c0122a27>] __do_softirq+0x87/0x100
[<c0122af5>] do_softirq+0x55/0x60
[<c0122f3c>] ksoftirqd+0x7c/0xd0
[<c0130f76>] kthread+0xf6/0x100
[<c0103c6f>] kernel_thread_helper+0x7/0x18
[<ffffffff>] 0xffffffff
irq event stamp: 3331
hardirqs last enabled at (3331): [<c016326d>] kmem_cache_alloc+0x6d/0xa0
hardirqs last disabled at (3330): [<c016321f>] kmem_cache_alloc+0x1f/0xa0
softirqs last enabled at (3012): [<c0122af5>] do_softirq+0x55/0x60
softirqs last disabled at (2971): [<c0122af5>] do_softirq+0x55/0x60

other info that might help us debug this:
no locks held by startproc/4046.

stack backtrace:
[<c0104042>] dump_trace+0x192/0x1c0
[<c0104088>] show_trace_log_lvl+0x18/0x30
[<c010483f>] show_trace+0xf/0x20
[<c01049a5>] dump_stack+0x15/0x20
[<c0137291>] print_usage_bug+0x251/0x270
[<c0137ae7>] mark_lock+0x4b7/0x5f0
[<c0138aae>] __lock_acquire+0x67e/0xc10
[<c013939d>] lock_acquire+0x5d/0x80
[<c0361c59>] _spin_lock+0x29/0x40
[<c0219091>] cfq_set_request+0x351/0x3b0
[<c020c7fc>] elv_set_request+0x1c/0x40
[<c020fcff>] get_request+0x23f/0x270
[<c0210537>] get_request_wait+0x27/0x120
[<c02107ca>] __make_request+0x5a/0x350
[<c020f40f>] generic_make_request+0x16f/0x220
[<c02117e4>] submit_bio+0x64/0x110
[<c018e969>] mpage_bio_submit+0x19/0x20
[<c018fe85>] mpage_readpages+0x105/0x140
[<c014d67f>] __do_page_cache_readahead+0x17f/0x260
[<c014d7d2>] blockable_page_cache_readahead+0x72/0xd0
[<c014da25>] page_cache_readahead+0x135/0x1e0
[<c01474ce>] do_generic_mapping_read+0x55e/0x5a0
[<c01496b1>] generic_file_aio_read+0x101/0x270
[<c01669b5>] do_sync_read+0xd5/0x120
[<c01672d1>] vfs_read+0xa1/0x160
[<c0167851>] sys_read+0x41/0x70
[<c0102f71>] sysenter_past_esp+0x56/0x8d
[<b7efd410>] 0xb7efd410
=======================

2006-10-30 18:15:09

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Mark Lord wrote:
> Mark Lord wrote:
> >Jens Axboe wrote:
> ..
> >>diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
> >>index 4bae64e..da9bddf 100644
> >>--- a/block/cfq-iosched.c
> >>+++ b/block/cfq-iosched.c
> ..
>

I thought so. But at least we got an obscure bug fixed in the process
:-)

> [ INFO: inconsistent lock state ]
> 2.6.19-rc3-git7-ml #3
> ---------------------------------
> inconsistent {in-softirq-W} -> {softirq-on-W} usage.
> startproc/4046 [HC0[0]:SC0[0]:HE1:SE1] takes:
> (&q->__queue_lock){-+..}, at: [<c0219091>] cfq_set_request+0x351/0x3b0
> {in-softirq-W} state was registered at:
> [<c01376b1>] mark_lock+0x81/0x5f0
> [<c0138a90>] __lock_acquire+0x660/0xc10
> [<c013939d>] lock_acquire+0x5d/0x80
> [<c0361c59>] _spin_lock+0x29/0x40
> [<c029fa24>] scsi_device_unbusy+0x64/0x90
> [<c029a5bc>] scsi_finish_command+0x1c/0xa0
> [<c02115c2>] blk_done_softirq+0x62/0x70
> [<c0122a27>] __do_softirq+0x87/0x100
> [<c0122af5>] do_softirq+0x55/0x60
> [<c0122f3c>] ksoftirqd+0x7c/0xd0
> [<c0130f76>] kthread+0xf6/0x100
> [<c0103c6f>] kernel_thread_helper+0x7/0x18
> [<ffffffff>] 0xffffffff
> irq event stamp: 3331
> hardirqs last enabled at (3331): [<c016326d>] kmem_cache_alloc+0x6d/0xa0
> hardirqs last disabled at (3330): [<c016321f>] kmem_cache_alloc+0x1f/0xa0
> softirqs last enabled at (3012): [<c0122af5>] do_softirq+0x55/0x60
> softirqs last disabled at (2971): [<c0122af5>] do_softirq+0x55/0x60
>
> other info that might help us debug this:
> no locks held by startproc/4046.
>
> stack backtrace:
> [<c0104042>] dump_trace+0x192/0x1c0
> [<c0104088>] show_trace_log_lvl+0x18/0x30
> [<c010483f>] show_trace+0xf/0x20
> [<c01049a5>] dump_stack+0x15/0x20
> [<c0137291>] print_usage_bug+0x251/0x270
> [<c0137ae7>] mark_lock+0x4b7/0x5f0
> [<c0138aae>] __lock_acquire+0x67e/0xc10
> [<c013939d>] lock_acquire+0x5d/0x80
> [<c0361c59>] _spin_lock+0x29/0x40
> [<c0219091>] cfq_set_request+0x351/0x3b0

Can you do:

$ gdb vmlinux
l *cfq_set_request+0x351

assuming you built with DEBUG_INFO enabled.

--
Jens Axboe

2006-10-30 18:20:42

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

Mark Lord wrote:
>
>I also see it with the SLES10 kernel 2.6.16.21-0.8.
..

Obvious self-correction: not the same problem in the SLES10 kernel.
I just got confused juggling five kernels around. :)

But problem is still there in 2.6.19*.
Rebuilding kernel now with frame pointers and DEBUG_INFO enabled.

Cheers

2006-10-30 18:30:30

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

Jens Axboe wrote:
> Can you do:
>
> $ gdb vmlinux
> l *cfq_set_request+0x351
>
> assuming you built with DEBUG_INFO enabled.

Here it is again, from kernel with FRAME_POINTERS and DEBUG_INFO enabled:

=================================
[ INFO: inconsistent lock state ]
2.6.19-rc3-git7-ml #6
---------------------------------
inconsistent {in-softirq-W} -> {softirq-on-W} usage.
startproc/3964 [HC0[0]:SC0[0]:HE1:SE1] takes:
(&q->__queue_lock){-+..}, at: [<c021780e>] cfq_set_request+0x33e/0x3a0
{in-softirq-W} state was registered at:
[<c0137439>] mark_lock+0x79/0x600
[<c013880d>] __lock_acquire+0x64d/0xc20
[<c013914d>] lock_acquire+0x5d/0x80
[<c035ea8b>] _spin_lock+0x2b/0x40
[<c029ee87>] scsi_device_unbusy+0x67/0xa0
[<c029992c>] scsi_finish_command+0x1c/0xa0
[<c029f04f>] scsi_softirq_done+0xcf/0xf0
[<c020fc8b>] blk_done_softirq+0x6b/0x80
[<c0122732>] __do_softirq+0x92/0x110
[<c0122815>] do_softirq+0x65/0x70
[<c0122c85>] ksoftirqd+0x85/0xd0
[<c0130d48>] kthread+0xe8/0xf0
[<c0103c4b>] kernel_thread_helper+0x7/0x1c
[<ffffffff>] 0xffffffff
irq event stamp: 1927
hardirqs last enabled at (1927): [<c0162a15>] kmem_cache_alloc+0x75/0xb0
hardirqs last disabled at (1926): [<c01629c2>] kmem_cache_alloc+0x22/0xb0
softirqs last enabled at (0): [<c011b653>] copy_process+0x353/0x1290
softirqs last disabled at (0): [<00000000>] 0x0

other info that might help us debug this:
no locks held by startproc/3964.

stack backtrace:
[<c0104088>] dump_trace+0x1c8/0x200
[<c01040da>] show_trace_log_lvl+0x1a/0x30
[<c0104832>] show_trace+0x12/0x20
[<c0104999>] dump_stack+0x19/0x20
[<c0137053>] print_usage_bug+0x243/0x250
[<c0137962>] mark_lock+0x5a2/0x600
[<c0138832>] __lock_acquire+0x672/0xc20
[<c013914d>] lock_acquire+0x5d/0x80
[<c035ea8b>] _spin_lock+0x2b/0x40
[<c021780e>] cfq_set_request+0x33e/0x3a0
[<c020af3f>] elv_set_request+0x1f/0x50
[<c020e40d>] get_request+0x21d/0x250
[<c020ec4c>] get_request_wait+0x1c/0x100
[<c020eebd>] __make_request+0x5d/0x330
[<c020db44>] generic_make_request+0x174/0x230
[<c020fed0>] submit_bio+0x60/0x110
[<c018dcfc>] mpage_bio_submit+0x1c/0x30
[<c018f363>] mpage_readpages+0x103/0x140
[<c01aab49>] reiserfs_readpages+0x19/0x20
[<c014d511>] __do_page_cache_readahead+0x161/0x220
[<c014d632>] blockable_page_cache_readahead+0x62/0xc0
[<c014d86f>] page_cache_readahead+0x11f/0x1d0
[<c0147511>] do_generic_mapping_read+0x501/0x540
[<c01495a3>] generic_file_aio_read+0xf3/0x240
[<c0166020>] do_sync_read+0xd0/0x110
[<c01668e4>] vfs_read+0x94/0x160
[<c0166e2d>] sys_read+0x3d/0x70
[<c0102f4d>] sysenter_past_esp+0x56/0x8d
[<b7f84410>] 0xb7f84410
=======================

(gdb) l *cfq_set_request+0x33e
0xc021780e is in cfq_set_request (block/cfq-iosched.c:1224).
1219 if (unlikely(!cfqd))
1220 return;
1221
1222 spin_lock(cfqd->queue->queue_lock);
1223
1224 cfqq = cic->cfqq[ASYNC];
1225 if (cfqq) {
1226 struct cfq_queue *new_cfqq;
1227 new_cfqq = cfq_get_queue(cfqd, CFQ_KEY_ASYNC, cic->ioc->task,
1228 GFP_ATOMIC);

2006-10-30 18:35:43

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

And while we're at it:
>
> (gdb) l *cfq_set_request+0x33e
> 0xc021780e is in cfq_set_request (block/cfq-iosched.c:1224).
> 1219 if (unlikely(!cfqd))
> 1220 return;
> 1221
> 1222 spin_lock(cfqd->queue->queue_lock);
> 1223
> 1224 cfqq = cic->cfqq[ASYNC];
> 1225 if (cfqq) {
> 1226 struct cfq_queue *new_cfqq;
> 1227 new_cfqq = cfq_get_queue(cfqd, CFQ_KEY_ASYNC, cic->ioc->task,
> 1228 GFP_ATOMIC);

(gdb) l *scsi_device_unbusy+0x67
0xc029ee87 is in scsi_device_unbusy (drivers/scsi/scsi_lib.c:466).
461 (shost->host_failed || shost->host_eh_scheduled)))
462 scsi_eh_wakeup(shost);
463 spin_unlock(shost->host_lock);
464 spin_lock(sdev->request_queue->queue_lock);
465 sdev->device_busy--;
466 spin_unlock_irqrestore(sdev->request_queue->queue_lock, flags);
467 }
468
469 /*
470 * Called for single_lun devices on IO completion. Clear starget_sdev_user,

2006-10-30 18:45:24

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

> (gdb) l *cfq_set_request+0x33e
> 0xc021780e is in cfq_set_request (block/cfq-iosched.c:1224).
> 1219 if (unlikely(!cfqd))
> 1220 return;
> 1221
> 1222 spin_lock(cfqd->queue->queue_lock);

this looks interesting... and buggy ;)
(this is changed_ioprio() )

Jens?

2006-10-30 18:50:37

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Mark Lord wrote:
> (gdb) l *cfq_set_request+0x33e
> 0xc021780e is in cfq_set_request (block/cfq-iosched.c:1224).
> 1219 if (unlikely(!cfqd))
> 1220 return;
> 1221
> 1222 spin_lock(cfqd->queue->queue_lock);
> 1223
> 1224 cfqq = cic->cfqq[ASYNC];
> 1225 if (cfqq) {
> 1226 struct cfq_queue *new_cfqq;
> 1227 new_cfqq = cfq_get_queue(cfqd, CFQ_KEY_ASYNC,
> cic->ioc->task,
> 1228 GFP_ATOMIC);

Bingo, that's a lot better! So that's the real bug, I'm guessing this
got introduced when the ioprio stuff got juggled around recently. Pretty
straight forward, this should fix it for you.

diff --git a/block/cfq-iosched.c b/block/cfq-iosched.c
index d3d7613..25c4e7e 100644
--- a/block/cfq-iosched.c
+++ b/block/cfq-iosched.c
@@ -1215,11 +1215,12 @@ static inline void changed_ioprio(struct
{
struct cfq_data *cfqd = cic->key;
struct cfq_queue *cfqq;
+ unsigned long flags;

if (unlikely(!cfqd))
return;

- spin_lock(cfqd->queue->queue_lock);
+ spin_lock_irqsave(cfqd->queue->queue_lock, flags);

cfqq = cic->cfqq[ASYNC];
if (cfqq) {
@@ -1236,7 +1237,7 @@ static inline void changed_ioprio(struct
if (cfqq)
cfq_mark_cfqq_prio_changed(cfqq);

- spin_unlock(cfqd->queue->queue_lock);
+ spin_unlock_irqrestore(cfqd->queue->queue_lock, flags);
}

static void cfq_ioc_set_ioprio(struct io_context *ioc)

--
Jens Axboe

2006-10-30 18:55:16

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

On Mon, Oct 30 2006, Arjan van de Ven wrote:
>
> > (gdb) l *cfq_set_request+0x33e
> > 0xc021780e is in cfq_set_request (block/cfq-iosched.c:1224).
> > 1219 if (unlikely(!cfqd))
> > 1220 return;
> > 1221
> > 1222 spin_lock(cfqd->queue->queue_lock);
>
> this looks interesting... and buggy ;)
> (this is changed_ioprio() )

Yeah it is, changed_ioprio() used to be called under local_irq_save(),
but it's not anymore.

--
Jens Axboe

2006-10-30 18:59:49

[permalink] [raw]

Subject: Re: 2.6.19-rc3-git7: scsi_device_unbusy: inconsistent lock state

Jens Axboe wrote:
>
> Bingo, that's a lot better! So that's the real bug, I'm guessing this
> got introduced when the ioprio stuff got juggled around recently. Pretty
> straight forward, this should fix it for you.

And it does indeed fix it, thanks!

-ml

2006-10-30 19:02:43