linux-next: spinlock lockup with next-20081118 on powerpc

linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 1648 bytes --]

Hi all,

I got this in my boot test last night:

Begin: Waiting for root file system... ...
BUG: spinlock lockup on CPU#1, vol_id/3246, c000000000b09700
Call Trace:
[c000000040ef7080] [c00000000000fb58] .show_stack+0x70/0x184 (unreliable)
[c000000040ef7130] [c00000000027adac] ._raw_spin_lock+0x140/0x17c
[c000000040ef71d0] [c0000000004ec648] ._spin_lock_irqsave+0x8c/0xc4
[c000000040ef7270] [c0000000000659dc] .lock_timer_base+0x38/0x90
[c000000040ef7310] [c000000000065b50] .__mod_timer+0x4c/0x11c
[c000000040ef73c0] [c00000000025ae9c] .blk_plug_device+0xc0/0xd8
[c000000040ef7440] [c00000000025bb90] .__make_request+0x498/0x518
[c000000040ef74f0] [c000000000259dc8] .generic_make_request+0x24c/0x2a4
[c000000040ef75b0] [c00000000025b6d0] .submit_bio+0x108/0x130
[c000000040ef7670] [c0000000001210e4] .submit_bh+0x174/0x1c0
[c000000040ef7700] [c0000000001259a8] .block_read_full_page+0x34c/0x3b4
[c000000040ef7820] [c000000000129a60] .blkdev_readpage+0x20/0x38
[c000000040ef78a0] [c0000000000c111c] .__do_page_cache_readahead+0x23c/0x2b8
[c000000040ef7980] [c0000000000c1370] .ondemand_readahead+0x1d8/0x210
[c000000040ef7a30] [c0000000000b7f20] .generic_file_aio_read+0x224/0x620
[c000000040ef7b60] [c0000000000f9020] .do_sync_read+0xc4/0x124
[c000000040ef7cf0] [c0000000000f98e0] .vfs_read+0xd8/0x1bc
[c000000040ef7d90] [c0000000000f9f0c] .sys_read+0x4c/0x8c
[c000000040ef7e30] [c0000000000084d4] syscall_exit+0x0/0x40

This was on a Power5 partition.  I am attempting to reproduce the problem.

Any clues?
-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 479 bytes --]

Hi all,

On Wed, 19 Nov 2008 09:30:23 +1100 Stephen Rothwell <sfr@canb.auug.org.au> wrote:
>
> This was on a Power5 partition.  I am attempting to reproduce the problem.

OK, it reproduces.  The machine is a Power5 partition (IBM,9124-720
eServer OpenPower 720) with 1 (2 way threaded) cpu (gr, rev2.1, 1.5GHz),
2G of memory, 2 NUMA nodes running Ubuntu Gutsy.

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Jens Axboe]

On Wed, Nov 19 2008, Stephen Rothwell wrote:
> Hi all,
> 
> I got this in my boot test last night:
> 
> Begin: Waiting for root file system... ...
> BUG: spinlock lockup on CPU#1, vol_id/3246, c000000000b09700
> Call Trace:
> [c000000040ef7080] [c00000000000fb58] .show_stack+0x70/0x184 (unreliable)
> [c000000040ef7130] [c00000000027adac] ._raw_spin_lock+0x140/0x17c
> [c000000040ef71d0] [c0000000004ec648] ._spin_lock_irqsave+0x8c/0xc4
> [c000000040ef7270] [c0000000000659dc] .lock_timer_base+0x38/0x90
> [c000000040ef7310] [c000000000065b50] .__mod_timer+0x4c/0x11c
> [c000000040ef73c0] [c00000000025ae9c] .blk_plug_device+0xc0/0xd8
> [c000000040ef7440] [c00000000025bb90] .__make_request+0x498/0x518
> [c000000040ef74f0] [c000000000259dc8] .generic_make_request+0x24c/0x2a4
> [c000000040ef75b0] [c00000000025b6d0] .submit_bio+0x108/0x130
> [c000000040ef7670] [c0000000001210e4] .submit_bh+0x174/0x1c0
> [c000000040ef7700] [c0000000001259a8] .block_read_full_page+0x34c/0x3b4
> [c000000040ef7820] [c000000000129a60] .blkdev_readpage+0x20/0x38
> [c000000040ef78a0] [c0000000000c111c] .__do_page_cache_readahead+0x23c/0x2b8
> [c000000040ef7980] [c0000000000c1370] .ondemand_readahead+0x1d8/0x210
> [c000000040ef7a30] [c0000000000b7f20] .generic_file_aio_read+0x224/0x620
> [c000000040ef7b60] [c0000000000f9020] .do_sync_read+0xc4/0x124
> [c000000040ef7cf0] [c0000000000f98e0] .vfs_read+0xd8/0x1bc
> [c000000040ef7d90] [c0000000000f9f0c] .sys_read+0x4c/0x8c
> [c000000040ef7e30] [c0000000000084d4] syscall_exit+0x0/0x40
> 
> This was on a Power5 partition.  I am attempting to reproduce the problem.
> 
> Any clues?

Strange, so it gets stuck on the timer lock, very weird. You don't
happen to have output showing that the other CPU is up to at that point?

-- 
Jens Axboe

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 1603 bytes --]

Hi Jens,

On Wed, 19 Nov 2008 10:16:28 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
>
> Strange, so it gets stuck on the timer lock, very weird. You don't
> happen to have output showing that the other CPU is up to at that point?

Unfortunately, no, but I will see what I can find tomorrow.

Today's linux-next still has a problem, but it is slightly different:

Unable to handle kernel paging request for data at address 0x00000000
Faulting instruction address: 0xc000000000503030
cpu 0x0: Vector: 300 (Data Access) at [c00000000ffffa40]
    pc: c000000000503030: ._spin_lock_irqsave+0x40/0x110
    lr: c0000000002571f8: .blk_rq_timed_out_timer+0x48/0x190
    sp: c00000000ffffcc0
   msr: 8000000000009032
   dar: 0
 dsisr: 40000000
  current = 0xc000000022d31040
  paca    = 0xc000000000897300
    pid   = 3399, comm = ckbcomp
enter ? for help
[c00000000ffffd50] c0000000002571f8 .blk_rq_timed_out_timer+0x48/0x190
[c00000000ffffe00] c00000000006c2f4 .run_timer_softirq+0x1c4/0x2a0
[c00000000ffffed0] c000000000065298 .__do_softirq+0xe8/0x1f0
[c00000000fffff90] c000000000029224 .call_do_softirq+0x14/0x24
[c000000022ad3c80] c00000000000d420 .do_softirq+0xf0/0x140
[c000000022ad3d20] c0000000000654a4 .irq_exit+0x74/0x90
[c000000022ad3da0] c000000000025844 .timer_interrupt+0x134/0x150
[c000000022ad3e30] c000000000003700 decrementer_common+0x100/0x180
--- Exception: 901 (Decrementer) at 000000000ff52440

I am currently bisecting yesterday's linux-next.
-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Jens Axboe]

On Wed, Nov 19 2008, Stephen Rothwell wrote:
> Hi Jens,
> 
> On Wed, 19 Nov 2008 10:16:28 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
> >
> > Strange, so it gets stuck on the timer lock, very weird. You don't
> > happen to have output showing that the other CPU is up to at that point?
> 
> Unfortunately, no, but I will see what I can find tomorrow.
> 
> Today's linux-next still has a problem, but it is slightly different:
> 
> Unable to handle kernel paging request for data at address 0x00000000
> Faulting instruction address: 0xc000000000503030
> cpu 0x0: Vector: 300 (Data Access) at [c00000000ffffa40]
>     pc: c000000000503030: ._spin_lock_irqsave+0x40/0x110
>     lr: c0000000002571f8: .blk_rq_timed_out_timer+0x48/0x190
>     sp: c00000000ffffcc0
>    msr: 8000000000009032
>    dar: 0
>  dsisr: 40000000
>   current = 0xc000000022d31040
>   paca    = 0xc000000000897300
>     pid   = 3399, comm = ckbcomp
> enter ? for help
> [c00000000ffffd50] c0000000002571f8 .blk_rq_timed_out_timer+0x48/0x190
> [c00000000ffffe00] c00000000006c2f4 .run_timer_softirq+0x1c4/0x2a0
> [c00000000ffffed0] c000000000065298 .__do_softirq+0xe8/0x1f0
> [c00000000fffff90] c000000000029224 .call_do_softirq+0x14/0x24
> [c000000022ad3c80] c00000000000d420 .do_softirq+0xf0/0x140
> [c000000022ad3d20] c0000000000654a4 .irq_exit+0x74/0x90
> [c000000022ad3da0] c000000000025844 .timer_interrupt+0x134/0x150
> [c000000022ad3e30] c000000000003700 decrementer_common+0x100/0x180
> --- Exception: 901 (Decrementer) at 000000000ff52440

That's even more weird, how could 'data' passed in to the timer ever be
0? It's setup like this:

        setup_timer(&q->timeout, blk_rq_timed_out_timer, (unsigned long) q);

when we allocate the queue. How did this trigger?

-- 
Jens Axboe

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 1861 bytes --]

Hi Jens,

On Wed, 19 Nov 2008 10:43:00 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
>
> On Wed, Nov 19 2008, Stephen Rothwell wrote:
> > 
> > Unable to handle kernel paging request for data at address 0x00000000
> > Faulting instruction address: 0xc000000000503030
> > cpu 0x0: Vector: 300 (Data Access) at [c00000000ffffa40]
> >     pc: c000000000503030: ._spin_lock_irqsave+0x40/0x110
> >     lr: c0000000002571f8: .blk_rq_timed_out_timer+0x48/0x190
> >     sp: c00000000ffffcc0
> >    msr: 8000000000009032
> >    dar: 0
> >  dsisr: 40000000
> >   current = 0xc000000022d31040
> >   paca    = 0xc000000000897300
> >     pid   = 3399, comm = ckbcomp
> > enter ? for help
> > [c00000000ffffd50] c0000000002571f8 .blk_rq_timed_out_timer+0x48/0x190
> > [c00000000ffffe00] c00000000006c2f4 .run_timer_softirq+0x1c4/0x2a0
> > [c00000000ffffed0] c000000000065298 .__do_softirq+0xe8/0x1f0
> > [c00000000fffff90] c000000000029224 .call_do_softirq+0x14/0x24
> > [c000000022ad3c80] c00000000000d420 .do_softirq+0xf0/0x140
> > [c000000022ad3d20] c0000000000654a4 .irq_exit+0x74/0x90
> > [c000000022ad3da0] c000000000025844 .timer_interrupt+0x134/0x150
> > [c000000022ad3e30] c000000000003700 decrementer_common+0x100/0x180
> > --- Exception: 901 (Decrementer) at 000000000ff52440
> 
> That's even more weird, how could 'data' passed in to the timer ever be
> 0? It's setup like this:

'data' above is generic, not a variable name. The 0 is probably the
address of the spinlock (though I need to check more to be sure) as it
crashed inside _spin_lock_irqsave.

>         setup_timer(&q->timeout, blk_rq_timed_out_timer, (unsigned long) q);
> 
> when we allocate the queue. How did this trigger?

Not sure what you mean?
-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Jens Axboe]

On Wed, Nov 19 2008, Stephen Rothwell wrote:
> Hi Jens,
> 
> On Wed, 19 Nov 2008 10:43:00 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
> >
> > On Wed, Nov 19 2008, Stephen Rothwell wrote:
> > > 
> > > Unable to handle kernel paging request for data at address 0x00000000
> > > Faulting instruction address: 0xc000000000503030
> > > cpu 0x0: Vector: 300 (Data Access) at [c00000000ffffa40]
> > >     pc: c000000000503030: ._spin_lock_irqsave+0x40/0x110
> > >     lr: c0000000002571f8: .blk_rq_timed_out_timer+0x48/0x190
> > >     sp: c00000000ffffcc0
> > >    msr: 8000000000009032
> > >    dar: 0
> > >  dsisr: 40000000
> > >   current = 0xc000000022d31040
> > >   paca    = 0xc000000000897300
> > >     pid   = 3399, comm = ckbcomp
> > > enter ? for help
> > > [c00000000ffffd50] c0000000002571f8 .blk_rq_timed_out_timer+0x48/0x190
> > > [c00000000ffffe00] c00000000006c2f4 .run_timer_softirq+0x1c4/0x2a0
> > > [c00000000ffffed0] c000000000065298 .__do_softirq+0xe8/0x1f0
> > > [c00000000fffff90] c000000000029224 .call_do_softirq+0x14/0x24
> > > [c000000022ad3c80] c00000000000d420 .do_softirq+0xf0/0x140
> > > [c000000022ad3d20] c0000000000654a4 .irq_exit+0x74/0x90
> > > [c000000022ad3da0] c000000000025844 .timer_interrupt+0x134/0x150
> > > [c000000022ad3e30] c000000000003700 decrementer_common+0x100/0x180
> > > --- Exception: 901 (Decrementer) at 000000000ff52440
> > 
> > That's even more weird, how could 'data' passed in to the timer ever be
> > 0? It's setup like this:
> 
> 'data' above is generic, not a variable name. The 0 is probably the

;-) I'm aware of that, I meant the 'timer' data argument. But you are
right, it's probably q->queue_lock being NULL here or we would have
oopsed earlier. There's no code line.

> address of the spinlock (though I need to check more to be sure) as it
> crashed inside _spin_lock_irqsave.

Do you know what device this might be? It still makes no sense, if the
timer was added, we went through the normal IO paths and we would have
crashed on NULL ->queue_lock much earlier.

-- 
Jens Axboe

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 1006 bytes --]

Hi Jens,

On Wed, 19 Nov 2008 11:58:33 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
>
> ;-) I'm aware of that, I meant the 'timer' data argument. But you are
> right, it's probably q->queue_lock being NULL here or we would have
> oopsed earlier. There's no code line.
> 
> > address of the spinlock (though I need to check more to be sure) as it
> > crashed inside _spin_lock_irqsave.
> 
> Do you know what device this might be? It still makes no sense, if the
> timer was added, we went through the normal IO paths and we would have
> crashed on NULL ->queue_lock much earlier.

I don't know much more, but I may find out tomorrow with Paul's help.
However it bisects down to commit
279430a72bb6e83d335b4219e9af5557e2ff3350 "block: leave the request
timeout timer running even on an empty list" and reverting that commit on
next-20081118 makes the spinlock lockup go away.

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Jens Axboe]

On Thu, Nov 20 2008, Stephen Rothwell wrote:
> Hi Jens,
> 
> On Wed, 19 Nov 2008 11:58:33 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
> >
> > ;-) I'm aware of that, I meant the 'timer' data argument. But you are
> > right, it's probably q->queue_lock being NULL here or we would have
> > oopsed earlier. There's no code line.
> > 
> > > address of the spinlock (though I need to check more to be sure) as it
> > > crashed inside _spin_lock_irqsave.
> > 
> > Do you know what device this might be? It still makes no sense, if the
> > timer was added, we went through the normal IO paths and we would have
> > crashed on NULL ->queue_lock much earlier.
> 
> I don't know much more, but I may find out tomorrow with Paul's help.
> However it bisects down to commit
> 279430a72bb6e83d335b4219e9af5557e2ff3350 "block: leave the request
> timeout timer running even on an empty list" and reverting that commit on
> next-20081118 makes the spinlock lockup go away.

Are you removing devices or modules? We have a bug there it seems, does
this help?

diff --git a/block/blk-core.c b/block/blk-core.c
index 04267d6..44f547c 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
 void blk_sync_queue(struct request_queue *q)
 {
 	del_timer_sync(&q->unplug_timer);
+	del_timer_sync(&q->timeout);
 	kblockd_flush_work(&q->unplug_work);
 }
 EXPORT_SYMBOL(blk_sync_queue);

-- 
Jens Axboe

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 473 bytes --]

Hi Jens,

On Wed, 19 Nov 2008 14:34:09 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
>
> Are you removing devices or modules? We have a bug there it seems, does
> this help?

This is early in boot (we are waiting for the root device while running
on the initramfs) so there could well be modules being unloaded.

That patch makes the problem go away.

-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: linux-next: spinlock lockup with next-20081118 on powerpc

[Jens Axboe]

On Thu, Nov 20 2008, Stephen Rothwell wrote:
> Hi Jens,
> 
> On Wed, 19 Nov 2008 14:34:09 +0100 Jens Axboe <jens.axboe@oracle.com> wrote:
> >
> > Are you removing devices or modules? We have a bug there it seems, does
> > this help?
> 
> This is early in boot (we are waiting for the root device while running
> on the initramfs) so there could well be modules being unloaded.
> 
> That patch makes the problem go away.

Excellent, since it was an apparent but, I already updated the original
patch with this hunk.

Thanks a lot for your bisection work, Stephen!

-- 
Jens Axboe