Re: system hang on latest git

Re: system hang on latest git

[Jens Axboe]

On Tue, Jan 29 2008, Luck, Tony wrote:
> I pulled Linus' tree this morning (git head = 0ba6c33bcddc64a54b5f1c25a696c4767dc76292)
> and built for ia64 (using arch/ia64/configs/tiger_defconfig).   System booted
> OK, but when I stressed it a little (building another kernel with "make -j32")
> it hung.
> 
> The console has a bunch (98) of warnings about tasks blocked for more than 120
> seconds like this:
> INFO: task grep:9168 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> 
> Call Trace:
>  [<a000000100704120>] schedule+0x11c0/0x1340
>                                 spà000001ed8afbf0 bspà000001ed8a1280
>  [<a00000010024e720>] do_get_write_access+0x660/0xbe0
>                                 spà000001ed8afc20 bspà000001ed8a1208
>  [<a00000010024f060>] journal_get_write_access+0x40/0x80
>                                 spà000001ed8afca0 bspà000001ed8a11c8
>  [<a000000100245db0>] __ext3_journal_get_write_access+0x30/0xa0
>                                 spà000001ed8afca0 bspà000001ed8a1190
>  [<a00000010022dea0>] ext3_reserve_inode_write+0x80/0x120
>                                 spà000001ed8afca0 bspà000001ed8a1158
>  [<a00000010022df70>] ext3_mark_inode_dirty+0x30/0x80
>                                 spà000001ed8afca0 bspà000001ed8a1130
>  [<a000000100232530>] ext3_dirty_inode+0xd0/0x120
>                                 spà000001ed8afcc0 bspà000001ed8a1100
>  [<a000000100170e20>] __mark_inode_dirty+0xa0/0x3e0
>                                 spà000001ed8afcc0 bspà000001ed8a10b0
>  [<a00000010015b570>] touch_atime+0x310/0x340
>                                 spà000001ed8afcc0 bspà000001ed8a1088
>  [<a0000001000d6c20>] do_generic_mapping_read+0x780/0x7a0
>                                 spà000001ed8afce0 bspà000001ed8a0fe0
>  [<a0000001000db250>] generic_file_aio_read+0x290/0x340
>                                 spà000001ed8afce0 bspà000001ed8a0f80
>  [<a00000010012c990>] do_sync_read+0x170/0x200
>                                 spà000001ed8afd10 bspà000001ed8a0f40
>  [<a00000010012cbd0>] vfs_read+0x1b0/0x2e0
>                                 spà000001ed8afe20 bspà000001ed8a0ef0
>  [<a00000010012d250>] sys_read+0x70/0xe0
>                                 spà000001ed8afe20 bspà000001ed8a0e78
>  [<a00000010000a4a0>] ia64_ret_from_syscall+0x0/0x20
>                                 spà000001ed8afe30 bspà000001ed8a0e78
> 
> 
> [The stack trace has several variations ... some from sys_read(), some from
> sys_open(), some from sys_execve(), some from sys_mmap() etc. 84/98 stack
> traces pass through the touch_atime->__mark_inode_dirty path ... all 98
> are attached]
> 
> A quick dig into processor state shows 8 cpus are idle.  7 are spinning
> in __spin_lock_irq() from __make_request() and one is in spin_lock() from
> as_merged_requests().

Looks like a deadlock on queue lock and ioc lock, but I don't see
immediately what the problem is. I can't stick around for longer
tonight, but I'll get to the bottom of this tomorrow.

-- 
Jens Axboe

Re: system hang on latest git

[Jens Axboe]

On Tue, Jan 29 2008, Jens Axboe wrote:
> On Tue, Jan 29 2008, Luck, Tony wrote:
> > I pulled Linus' tree this morning (git head = 0ba6c33bcddc64a54b5f1c25a696c4767dc76292)
> > and built for ia64 (using arch/ia64/configs/tiger_defconfig).   System booted
> > OK, but when I stressed it a little (building another kernel with "make -j32")
> > it hung.
> > 
> > The console has a bunch (98) of warnings about tasks blocked for more than 120
> > seconds like this:
> > INFO: task grep:9168 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > 
> > Call Trace:
> >  [<a000000100704120>] schedule+0x11c0/0x1340
> >                                 spà000001ed8afbf0 bspà000001ed8a1280
> >  [<a00000010024e720>] do_get_write_access+0x660/0xbe0
> >                                 spà000001ed8afc20 bspà000001ed8a1208
> >  [<a00000010024f060>] journal_get_write_access+0x40/0x80
> >                                 spà000001ed8afca0 bspà000001ed8a11c8
> >  [<a000000100245db0>] __ext3_journal_get_write_access+0x30/0xa0
> >                                 spà000001ed8afca0 bspà000001ed8a1190
> >  [<a00000010022dea0>] ext3_reserve_inode_write+0x80/0x120
> >                                 spà000001ed8afca0 bspà000001ed8a1158
> >  [<a00000010022df70>] ext3_mark_inode_dirty+0x30/0x80
> >                                 spà000001ed8afca0 bspà000001ed8a1130
> >  [<a000000100232530>] ext3_dirty_inode+0xd0/0x120
> >                                 spà000001ed8afcc0 bspà000001ed8a1100
> >  [<a000000100170e20>] __mark_inode_dirty+0xa0/0x3e0
> >                                 spà000001ed8afcc0 bspà000001ed8a10b0
> >  [<a00000010015b570>] touch_atime+0x310/0x340
> >                                 spà000001ed8afcc0 bspà000001ed8a1088
> >  [<a0000001000d6c20>] do_generic_mapping_read+0x780/0x7a0
> >                                 spà000001ed8afce0 bspà000001ed8a0fe0
> >  [<a0000001000db250>] generic_file_aio_read+0x290/0x340
> >                                 spà000001ed8afce0 bspà000001ed8a0f80
> >  [<a00000010012c990>] do_sync_read+0x170/0x200
> >                                 spà000001ed8afd10 bspà000001ed8a0f40
> >  [<a00000010012cbd0>] vfs_read+0x1b0/0x2e0
> >                                 spà000001ed8afe20 bspà000001ed8a0ef0
> >  [<a00000010012d250>] sys_read+0x70/0xe0
> >                                 spà000001ed8afe20 bspà000001ed8a0e78
> >  [<a00000010000a4a0>] ia64_ret_from_syscall+0x0/0x20
> >                                 spà000001ed8afe30 bspà000001ed8a0e78
> > 
> > 
> > [The stack trace has several variations ... some from sys_read(), some from
> > sys_open(), some from sys_execve(), some from sys_mmap() etc. 84/98 stack
> > traces pass through the touch_atime->__mark_inode_dirty path ... all 98
> > are attached]
> > 
> > A quick dig into processor state shows 8 cpus are idle.  7 are spinning
> > in __spin_lock_irq() from __make_request() and one is in spin_lock() from
> > as_merged_requests().
> 
> Looks like a deadlock on queue lock and ioc lock, but I don't see
> immediately what the problem is. I can't stick around for longer
> tonight, but I'll get to the bottom of this tomorrow.

Actually, can you try this? It has a known race but nothing to worry
about, and it removes ioc->lock from irq context.

diff --git a/block/as-iosched.c b/block/as-iosched.c
index b201d16..585aad2 100644
--- a/block/as-iosched.c
+++ b/block/as-iosched.c
@@ -235,10 +235,8 @@ static void as_put_io_context(struct request *rq)
 	aic = RQ_IOC(rq)->aic;
 
 	if (rq_is_sync(rq) && aic) {
-		spin_lock(&aic->lock);
 		set_bit(AS_TASK_IORUNNING, &aic->state);
 		aic->last_end_request = jiffies;
-		spin_unlock(&aic->lock);
 	}
 
 	put_io_context(RQ_IOC(rq));

-- 
Jens Axboe

Re: system hang on latest git

[Jens Axboe]

On Tue, Jan 29 2008, Olof Johansson wrote:
> On Tue, Jan 29, 2008 at 09:16:48PM +0100, Jens Axboe wrote:
> 
> > Actually, can you try this? It has a known race but nothing to worry
> > about, and it removes ioc->lock from irq context.
> 
> I just tried this myself, since I saw hangs within seconds of running
> 'aiostress' from autotest on this morning's kernel as well (g0ba6c33).
> 
> It didn't help. My config is 2 cores (powerpc), built with
> arch/powerpc/configs/pasemi_defconfig. Hardware is sata disk on marvell
> 7042.

Please try this.

diff --git a/block/as-iosched.c b/block/as-iosched.c
index b201d16..9603684 100644
--- a/block/as-iosched.c
+++ b/block/as-iosched.c
@@ -1275,9 +1275,13 @@ static void as_merged_requests(struct request_queue *q, struct request *req,
 			 * Don't copy here but swap, because when anext is
 			 * removed below, it must contain the unused context
 			 */
-			double_spin_lock(&rioc->lock, &nioc->lock, rioc < nioc);
-			swap_io_context(&rioc, &nioc);
-			double_spin_unlock(&rioc->lock, &nioc->lock, rioc < nioc);
+			if (rioc != nioc) {
+				double_spin_lock(&rioc->lock, &nioc->lock,
+								rioc < nioc);
+				swap_io_context(&rioc, &nioc);
+				double_spin_unlock(&rioc->lock, &nioc->lock,
+								rioc < nioc);
+			}
 		}
 	}
 

> Stacktraces:
> 
> 0:mon> t           
> [link register   ] c000000000221984 .as_merged_requests+0x164/0x1e0
> [c00000007e8ff750] c00000007e8ff800 (unreliable)
> [c00000007e8ff800] c000000000212f20 .elv_merge_requests+0x50/0xb0
> [c00000007e8ff890] c000000000218c98 .attempt_merge+0x318/0x3d0
> [c00000007e8ff940] c00000000021af98 .__make_request+0x2f8/0x720
> [c00000007e8ffa20] c000000000216e6c .generic_make_request+0x22c/0x2f0
> [c00000007e8ffad0] c000000000216fd8 .submit_bio+0xa8/0x150
> [c00000007e8ffb90] c0000000000efa7c .submit_bh+0x15c/0x1e0
> [c00000007e8ffc20] c000000000145d5c .journal_do_submit_data+0x6c/0xb0
> [c00000007e8ffcc0] c000000000147460 .journal_commit_transaction+0x1640/0x16e0
> [c00000007e8ffe10] c00000000014c238 .kjournald+0x108/0x2f0
> [c00000007e8fff00] c000000000067ca8 .kthread+0xc8/0xe0
> [c00000007e8fff90] c0000000000237bc .kernel_thread+0x4c/0x68
> 0:mon> c1
> 1:mon> t
> [link register   ] c00000000033c20c .scsi_device_unbusy+0x8c/0x120
> [c00000007e10b6f0] c00000000033c1a8 .scsi_device_unbusy+0x28/0x120 (unreliable)
> [c00000007e10b780] c000000000333078 .scsi_finish_command+0x38/0x130
> [c00000007e10b810] c00000000033c478 .scsi_softirq_done+0xd8/0x1a0
> [c00000007e10b8b0] c00000000021a780 .blk_done_softirq+0xb0/0xe0
> [c00000007e10b940] c000000000051e58 .__do_softirq+0xe8/0x1d0
> [c00000007e10ba00] c00000000000ac64 .do_softirq+0x64/0xa0
> [c00000007e10ba80] c000000000051b84 .irq_exit+0xc4/0xd0
> [c00000007e10bb00] c00000000000b3c0 .do_IRQ+0xe0/0x120
> [c00000007e10bb80] c00000000000405c hardware_interrupt_entry+0x18/0x3c
> --- Exception: 501 (Hardware Interrupt) at c000000000010564 .cpu_idle+0xb4/0x160
> [c00000007e10be70] c000000000010524 .cpu_idle+0x74/0x160 (unreliable)
> [c00000007e10bf00] c000000000540e6c
> [c00000007e10bf90] c000000000007364 .start_secondary_prolog+0xc/0x10
> 
> 
> scsi_device_busy is sitting on:
> 
>         spin_lock(sdev->request_queue->queue_lock);
> 
> and as_merged_requests on the second lock at:
> 
> 	double_spin_lock(&rioc->lock, &nioc->lock, rioc < nioc);
> 
> 

The latter is the problem, but since the queue lock is also held before
doing the double_spin_lock(), we get into even more trouble. The locking
hierarchy is fine, it's always queue lock -> io context locks, so the
above patch should be all that is needed to fix this.

My initial analysis was wrong, that's all :/

-- 
Jens Axboe

Re: system hang on latest git

[Olof Johansson]

On Tue, Jan 29, 2008 at 09:16:48PM +0100, Jens Axboe wrote:

> Actually, can you try this? It has a known race but nothing to worry
> about, and it removes ioc->lock from irq context.

I just tried this myself, since I saw hangs within seconds of running
'aiostress' from autotest on this morning's kernel as well (g0ba6c33).

It didn't help. My config is 2 cores (powerpc), built with
arch/powerpc/configs/pasemi_defconfig. Hardware is sata disk on marvell
7042.

Stacktraces:

0:mon> t           
[link register   ] c000000000221984 .as_merged_requests+0x164/0x1e0
[c00000007e8ff750] c00000007e8ff800 (unreliable)
[c00000007e8ff800] c000000000212f20 .elv_merge_requests+0x50/0xb0
[c00000007e8ff890] c000000000218c98 .attempt_merge+0x318/0x3d0
[c00000007e8ff940] c00000000021af98 .__make_request+0x2f8/0x720
[c00000007e8ffa20] c000000000216e6c .generic_make_request+0x22c/0x2f0
[c00000007e8ffad0] c000000000216fd8 .submit_bio+0xa8/0x150
[c00000007e8ffb90] c0000000000efa7c .submit_bh+0x15c/0x1e0
[c00000007e8ffc20] c000000000145d5c .journal_do_submit_data+0x6c/0xb0
[c00000007e8ffcc0] c000000000147460 .journal_commit_transaction+0x1640/0x16e0
[c00000007e8ffe10] c00000000014c238 .kjournald+0x108/0x2f0
[c00000007e8fff00] c000000000067ca8 .kthread+0xc8/0xe0
[c00000007e8fff90] c0000000000237bc .kernel_thread+0x4c/0x68
0:mon> c1
1:mon> t
[link register   ] c00000000033c20c .scsi_device_unbusy+0x8c/0x120
[c00000007e10b6f0] c00000000033c1a8 .scsi_device_unbusy+0x28/0x120 (unreliable)
[c00000007e10b780] c000000000333078 .scsi_finish_command+0x38/0x130
[c00000007e10b810] c00000000033c478 .scsi_softirq_done+0xd8/0x1a0
[c00000007e10b8b0] c00000000021a780 .blk_done_softirq+0xb0/0xe0
[c00000007e10b940] c000000000051e58 .__do_softirq+0xe8/0x1d0
[c00000007e10ba00] c00000000000ac64 .do_softirq+0x64/0xa0
[c00000007e10ba80] c000000000051b84 .irq_exit+0xc4/0xd0
[c00000007e10bb00] c00000000000b3c0 .do_IRQ+0xe0/0x120
[c00000007e10bb80] c00000000000405c hardware_interrupt_entry+0x18/0x3c
--- Exception: 501 (Hardware Interrupt) at c000000000010564 .cpu_idle+0xb4/0x160
[c00000007e10be70] c000000000010524 .cpu_idle+0x74/0x160 (unreliable)
[c00000007e10bf00] c000000000540e6c
[c00000007e10bf90] c000000000007364 .start_secondary_prolog+0xc/0x10


scsi_device_busy is sitting on:

        spin_lock(sdev->request_queue->queue_lock);

and as_merged_requests on the second lock at:

	double_spin_lock(&rioc->lock, &nioc->lock, rioc < nioc);


-Olof

Re: system hang on latest git

[Olof Johansson]

On Tue, Jan 29, 2008 at 10:38:52PM +0100, Jens Axboe wrote:
> Please try this.

[...]

> The latter is the problem, but since the queue lock is also held before
> doing the double_spin_lock(), we get into even more trouble. The locking
> hierarchy is fine, it's always queue lock -> io context locks, so the
> above patch should be all that is needed to fix this.
> 
> My initial analysis was wrong, that's all :/

Yep, looks much better now.

Tested-by: Olof Johansson <olof@lixom.net>


-Olof