next-20090206: deadlock on ext4

next-20090206: deadlock on ext4

[Alexander Beregalov]

Hi

I run dbench on ext4 on loop device.

EXT4-fs: barriers enabled
kjournald2 starting: pid 2420, dev loop0:8, commit interval 5 seconds
EXT4 FS on loop0, internal journal on loop0:8
EXT4-fs: delayed allocation enabled
EXT4-fs: file extents enabled
EXT4-fs: mballoc enabled
EXT4-fs: mounted filesystem loop0 with ordered data mode
JBD: barrier-based sync failed on loop0:8 - disabling barriers

INFO: task pdflush:2339 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D 0000000000000002  3112  2339      2
 ffff88007d861990 0000000000000046 ffff88007d861940 ffffffff802971c6
 ffff88007d8618f8 0000000000004000 0000000000000000 ffff8800790bce40
 ffff880035c7ce40 ffff8800790bd1d8 00000000790bce40 0000000000000282
Call Trace:
 [<ffffffff802971c6>] ? mempool_alloc+0x56/0x150
 [<ffffffff8062dbd5>] ? _spin_unlock_irqrestore+0x65/0x80
 [<ffffffff8062ac47>] ? io_schedule+0x37/0x50
 [<ffffffff8062abe3>] schedule+0x13/0x40
 [<ffffffff8062ac47>] io_schedule+0x37/0x50
 [<ffffffff8029442d>] sync_page+0x6d/0x80
 [<ffffffff8062af52>] __wait_on_bit_lock+0x52/0xb0
 [<ffffffff802943c0>] ? sync_page+0x0/0x80
 [<ffffffff802943a4>] __lock_page+0x64/0x70
 [<ffffffff80259460>] ? wake_bit_function+0x0/0x40
 [<ffffffff8029e252>] ? pagevec_lookup_tag+0x22/0x30
 [<ffffffff8029c687>] write_cache_pages+0x247/0x4a0
 [<ffffffff8032b540>] ? __mpage_da_writepage+0x0/0x1b0
 [<ffffffff8034cafe>] ? jbd2_journal_start+0xce/0x140
 [<ffffffff8032b1e3>] ext4_da_writepages+0x263/0x4e0
 [<ffffffff80269f65>] ? print_lock_contention_bug+0x25/0x120
 [<ffffffff80269f65>] ? print_lock_contention_bug+0x25/0x120
 [<ffffffff80269f65>] ? print_lock_contention_bug+0x25/0x120
 [<ffffffff80269f65>] ? print_lock_contention_bug+0x25/0x120
 [<ffffffff8032d090>] ? ext4_da_get_block_write+0x0/0x190
 [<ffffffff8029c93b>] do_writepages+0x2b/0x50
 [<ffffffff802e56a1>] __writeback_single_inode+0xa1/0x3f0
 [<ffffffff802e5ee2>] ? generic_sync_sb_inodes+0x3a2/0x420
 [<ffffffff802e5e88>] generic_sync_sb_inodes+0x348/0x420
 [<ffffffff802e6145>] writeback_inodes+0x65/0x100
 [<ffffffff8029d050>] background_writeout+0xb0/0xe0
 [<ffffffff8029d840>] pdflush+0x110/0x1f0
 [<ffffffff8029cfa0>] ? background_writeout+0x0/0xe0
 [<ffffffff8029d730>] ? pdflush+0x0/0x1f0
 [<ffffffff8029d730>] ? pdflush+0x0/0x1f0
 [<ffffffff80258f76>] kthread+0x56/0x90
 [<ffffffff8020ce5a>] child_rip+0xa/0x20
 [<ffffffff80235759>] ? finish_task_switch+0x89/0x110
 [<ffffffff8062db46>] ? _spin_unlock_irq+0x36/0x60
 [<ffffffff8020c840>] ? restore_args+0x0/0x30
 [<ffffffff80258f20>] ? kthread+0x0/0x90
 [<ffffffff8020ce50>] ? child_rip+0x0/0x20
INFO: lockdep is turned off.
INFO: task kjournald2:2420 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kjournald2    D ffff88007b8d2090  4776  2420      2
 ffff88003d117d40 0000000000000046 0000000000000000 ffff88007b8d2358
 ffff8800790ba720 0000000000004000 0000000000000002 ffff8800790ba720
 ffff88007c820000 ffff8800790baab8 000000028062dbd5 0000000000000286
Call Trace:
 [<ffffffff8026bf69>] ? trace_hardirqs_on_caller+0x29/0x1e0
 [<ffffffff8034e794>] ? jbd2_journal_commit_transaction+0x1d4/0x19b0
 [<ffffffff8034e799>] ? jbd2_journal_commit_transaction+0x1d9/0x19b0
 [<ffffffff8062abe3>] schedule+0x13/0x40
 [<ffffffff8034e799>] jbd2_journal_commit_transaction+0x1d9/0x19b0
 [<ffffffff8062dba8>] ? _spin_unlock_irqrestore+0x38/0x80
 [<ffffffff80268709>] ? trace_hardirqs_off_caller+0x29/0xe0
 [<ffffffff802358a0>] ? sub_preempt_count+0xc0/0x130
 [<ffffffff80259420>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff8024cefc>] ? try_to_del_timer_sync+0x7c/0x90
 [<ffffffff80354577>] kjournald2+0x117/0x380
 [<ffffffff80259420>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff80354460>] ? kjournald2+0x0/0x380
 [<ffffffff80258f76>] kthread+0x56/0x90
 [<ffffffff8020ce5a>] child_rip+0xa/0x20
 [<ffffffff80235759>] ? finish_task_switch+0x89/0x110
 [<ffffffff8062db46>] ? _spin_unlock_irq+0x36/0x60
 [<ffffffff8020c840>] ? restore_args+0x0/0x30
 [<ffffffff80258f20>] ? kthread+0x0/0x90
 [<ffffffff8020ce50>] ? child_rip+0x0/0x20
INFO: lockdep is turned off.
INFO: task dbench:2685 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
dbench        D 0000000000000001  3296  2685      1
 ffff8800793f9a18 0000000000000046 0000000000000000 ffff88007b8d21c8
 ffff880035c78000 0000000000004000 0000000000000003 ffff880035c78000
 ffff88007d2ace40 ffff880035c78398 000000038062dbd5 0000000000000286
Call Trace:
 [<ffffffff8026bf69>] ? trace_hardirqs_on_caller+0x29/0x1e0
 [<ffffffff8034c6a7>] ? start_this_handle+0x3b7/0x5e0
 [<ffffffff8034c6ac>] ? start_this_handle+0x3bc/0x5e0
 [<ffffffff8062abe3>] schedule+0x13/0x40
 [<ffffffff8034c6ac>] start_this_handle+0x3bc/0x5e0
 [<ffffffff80259420>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff8034caf7>] jbd2_journal_start+0xc7/0x140
 [<ffffffff8029d5e5>] ? balance_dirty_pages_ratelimited_nr+0x365/0x3f0
 [<ffffffff80336575>] ext4_journal_start_sb+0x55/0x90
 [<ffffffff80329ef3>] ext4_da_write_begin+0xf3/0x260
 [<ffffffff802965d7>] generic_file_buffered_write+0x137/0x340
 [<ffffffff80296c19>] __generic_file_aio_write_nolock+0x269/0x470
 [<ffffffff80296f29>] generic_file_aio_write+0x69/0xd0
 [<ffffffff80325838>] ext4_file_write+0x58/0x170
 [<ffffffff802c66a1>] do_sync_write+0xf1/0x140
 [<ffffffff80259420>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff8026bf69>] ? trace_hardirqs_on_caller+0x29/0x1e0
 [<ffffffff80250a72>] ? sys_kill+0xa2/0x1c0
 [<ffffffff802c6d0b>] vfs_write+0xcb/0x170
 [<ffffffff802c6e42>] sys_pwrite64+0x92/0xa0
 [<ffffffff8020bddb>] system_call_fastpath+0x16/0x1b

Re: next-20090206: deadlock on ext4

[Eric Sandeen]

Alexander Beregalov wrote:
> Hi
> 
> I run dbench on ext4 on loop device.
> 
> EXT4-fs: barriers enabled
> kjournald2 starting: pid 2420, dev loop0:8, commit interval 5 seconds
> EXT4 FS on loop0, internal journal on loop0:8
> EXT4-fs: delayed allocation enabled
> EXT4-fs: file extents enabled
> EXT4-fs: mballoc enabled
> EXT4-fs: mounted filesystem loop0 with ordered data mode
> JBD: barrier-based sync failed on loop0:8 - disabling barriers
> 
> INFO: task pdflush:2339 blocked for more than 120 seconds.

Looks a lot like a bug I filed:

http://bugzilla.kernel.org/show_bug.cgi?id=12579

but I'm having trouble reproducing it, now.  I'll try dbench!

-Eric

Re: next-20090206: deadlock on ext4

[Alexander Beregalov]

2009/2/6 Eric Sandeen <sandeen@redhat.com>:
> Alexander Beregalov wrote:
>> Hi
>>
>> I run dbench on ext4 on loop device.
>>
>> EXT4-fs: barriers enabled
>> kjournald2 starting: pid 2420, dev loop0:8, commit interval 5 seconds
>> EXT4 FS on loop0, internal journal on loop0:8
>> EXT4-fs: delayed allocation enabled
>> EXT4-fs: file extents enabled
>> EXT4-fs: mballoc enabled
>> EXT4-fs: mounted filesystem loop0 with ordered data mode
>> JBD: barrier-based sync failed on loop0:8 - disabling barriers
>>
>> INFO: task pdflush:2339 blocked for more than 120 seconds.
>
> Looks a lot like a bug I filed:
>
> http://bugzilla.kernel.org/show_bug.cgi?id=12579
>
> but I'm having trouble reproducing it, now.  I'll try dbench!
Yes, I can reproduce it easy with dbench.

Re: next-20090206: deadlock on ext4

[Eric Sandeen]

Alexander Beregalov wrote:
> 2009/2/6 Eric Sandeen <sandeen@redhat.com>:
>> Alexander Beregalov wrote:
>>> Hi
>>>
>>> I run dbench on ext4 on loop device.
>>>
>>> EXT4-fs: barriers enabled
>>> kjournald2 starting: pid 2420, dev loop0:8, commit interval 5 seconds
>>> EXT4 FS on loop0, internal journal on loop0:8
>>> EXT4-fs: delayed allocation enabled
>>> EXT4-fs: file extents enabled
>>> EXT4-fs: mballoc enabled
>>> EXT4-fs: mounted filesystem loop0 with ordered data mode
>>> JBD: barrier-based sync failed on loop0:8 - disabling barriers
>>>
>>> INFO: task pdflush:2339 blocked for more than 120 seconds.
>> Looks a lot like a bug I filed:
>>
>> http://bugzilla.kernel.org/show_bug.cgi?id=12579
>>
>> but I'm having trouble reproducing it, now.  I'll try dbench!
> Yes, I can reproduce it easy with dbench.

Do you only hit it on loopback?  What is the filesystem hosting the loop
file?

Thanks,
-Eric

Re: next-20090206: deadlock on ext4

[Alexander Beregalov]

2009/2/6 Eric Sandeen <sandeen@redhat.com>:
> Alexander Beregalov wrote:
>> 2009/2/6 Eric Sandeen <sandeen@redhat.com>:
>>> Alexander Beregalov wrote:
>>>> Hi
>>>>
>>>> I run dbench on ext4 on loop device.
>>>>
>>>> EXT4-fs: barriers enabled
>>>> kjournald2 starting: pid 2420, dev loop0:8, commit interval 5 seconds
>>>> EXT4 FS on loop0, internal journal on loop0:8
>>>> EXT4-fs: delayed allocation enabled
>>>> EXT4-fs: file extents enabled
>>>> EXT4-fs: mballoc enabled
>>>> EXT4-fs: mounted filesystem loop0 with ordered data mode
>>>> JBD: barrier-based sync failed on loop0:8 - disabling barriers
>>>>
>>>> INFO: task pdflush:2339 blocked for more than 120 seconds.
>>> Looks a lot like a bug I filed:
>>>
>>> http://bugzilla.kernel.org/show_bug.cgi?id=12579
>>>
>>> but I'm having trouble reproducing it, now.  I'll try dbench!
>> Yes, I can reproduce it easy with dbench.
>
> Do you only hit it on loopback?  What is the filesystem hosting the loop
> file?

I have reproduced it with 2.6.29-rc4.
Loop file was on XFS.
I can not reproduce it on ext4 on raw device.
Let me know if I can do anything else to help resolving it.

Re: next-20090206: deadlock on ext4

[Eric Sandeen]

Alexander Beregalov wrote:

> I have reproduced it with 2.6.29-rc4.
> Loop file was on XFS.
> I can not reproduce it on ext4 on raw device.
> Let me know if I can do anything else to help resolving it.
>   
Can you try this patch from Aneesh?  Works for me...

Thanks,
-Eric

From: Aneesh Kumar K.V <aneesh.kumar@linux.vnet.ibm.com>
Subject: [PATCH] ext4: Don't use the range_cylic mode implemented by
write_cache_pages

With delayed allocation we lock the page in write_cache_pages and 
try to build an in memory extent of contiguous blocks. This is 
needed so that we can get a large contiguous blocks request. Now 
with range_cyclic mode in write_cache_pages if we have not done an 
I/O we loop back to 0 index and try to write the page.  That would 
imply we will attempt to take page lock of lower index page holding
the page lock of higher index page. This can cause a dead lock with
other writeback thread.

Signed-off-by: Aneesh Kumar K.V <aneesh.kumar@linux.vnet.ibm.com>
Reviewed-by: Eric Sandeen <sandeen@redhat.com>
Tested-by: Eric Sandeen <sandeen@redhat.com>
---
 fs/ext4/inode.c |   20 ++++++++++++++++++--
 1 files changed, 18 insertions(+), 2 deletions(-)

Index: linux-2.6.28.x86_64/fs/ext4/inode.c
===================================================================
--- linux-2.6.28.x86_64.orig/fs/ext4/inode.c
+++ linux-2.6.28.x86_64/fs/ext4/inode.c
@@ -2437,6 +2437,7 @@ static int ext4_da_writepages(struct add
 	int no_nrwrite_index_update;
 	int pages_written = 0;
 	long pages_skipped;
+       int range_cyclic = 0, cycled = 1, io_done = 0;
 	int needed_blocks, ret = 0, nr_to_writebump = 0;
 	struct ext4_sb_info *sbi = EXT4_SB(mapping->host->i_sb);
 
@@ -2488,9 +2489,14 @@ static int ext4_da_writepages(struct add
 	if (wbc->range_start == 0 && wbc->range_end == LLONG_MAX)
 		range_whole = 1;
 
-	if (wbc->range_cyclic)
+       if (wbc->range_cyclic) {
 		index = mapping->writeback_index;
-	else
+	       wbc->range_start = index << PAGE_CACHE_SHIFT;
+	       wbc->range_end  = LLONG_MAX;
+	       wbc->range_cyclic = 0;
+	       range_cyclic = 1;
+	       cycled = 0;
+       } else
 		index = wbc->range_start >> PAGE_CACHE_SHIFT;
 
 	mpd.wbc = wbc;
@@ -2504,6 +2510,7 @@ static int ext4_da_writepages(struct add
 	wbc->no_nrwrite_index_update = 1;
 	pages_skipped = wbc->pages_skipped;
 
+retry:
 	while (!ret && wbc->nr_to_write > 0) {
 
 		/*
@@ -2546,6 +2553,7 @@ static int ext4_da_writepages(struct add
 			pages_written += mpd.pages_written;
 			wbc->pages_skipped = pages_skipped;
 			ret = 0;
+		       io_done = 1;
 		} else if (wbc->nr_to_write)
 			/*
 			 * There is no more writeout needed
@@ -2554,6 +2562,13 @@ static int ext4_da_writepages(struct add
 			 */
 			break;
 	}
+       if (!io_done && !cycled) {
+	       cycled = 1;
+	       index = 0;
+	       wbc->range_start = index << PAGE_CACHE_SHIFT;
+	       wbc->range_end  = mapping->writeback_index - 1;
+	       goto retry;
+       }
 	if (pages_skipped != wbc->pages_skipped)
 		printk(KERN_EMERG "This should not happen leaving %s "
 				"with nr_to_write = %ld ret = %d\n",
@@ -2561,6 +2576,7 @@ static int ext4_da_writepages(struct add
 
 	/* Update index */
 	index += pages_written;
+       wbc->range_cyclic = range_cyclic;
 	if (wbc->range_cyclic || (range_whole && wbc->nr_to_write > 0))
 		/*
 		 * set the writeback_index so that range_cyclic

Re: next-20090206: deadlock on ext4

[Alexander Beregalov]

2009/2/14 Eric Sandeen <sandeen@redhat.com>:
> Alexander Beregalov wrote:
>
>> I have reproduced it with 2.6.29-rc4.
>> Loop file was on XFS.
>> I can not reproduce it on ext4 on raw device.
>> Let me know if I can do anything else to help resolving it.
>>
> Can you try this patch from Aneesh?  Works for me...
>

Yes, it works, I can not reproduce the bug on
2.6.29-rc5-00122-g5955c7a which contains 2acf2c261b82
"ext4: Implement range_cyclic in ext4_da_writepages instead of
write_cache_pages"

Thanks