2.6.30-rc4: xfs_fsr hangs

2.6.30-rc4: xfs_fsr hangs

[Alexander Beregalov]

# xfs_db -r /dev/sdc1
xfs_db> frag
actual 23805, ideal 22890, fragmentation factor 3.84%
# xfs_fsr -v /dev/sdc1
/mnt/c start inode=0
ino=158
extents before:3 after:1 DONE ino=158

 then it hangs


INFO: task xfs_fsr:2403 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xfs_fsr       D 00000000  4492  2403   1928
 f3cc9dec 00000046 00000001 00000000 f3cc9de8 ec976680 ec976900 f2d06a50
 ec976680 00000001 f2d06a50 f2d06a4c ffffffff f2d06a4c ec976680 f3cc9df4
 c0447892 f3cc9e20 c04498ad f3cc9e28 f2d06a50 f2d06a74 f3cc9e44 00000246
Call Trace:
 [<c0447892>] schedule+0x12/0x30
 [<c04498ad>] rwsem_down_failed_common+0x6d/0x180
 [<c04499dd>] rwsem_down_write_failed+0x1d/0x30
 [<c0449a2a>] call_rwsem_down_write_failed+0x6/0x8
 [<c026bfce>] ? xfs_ilock+0xee/0x100
 [<c013fcd6>] ? down_write_nested+0x76/0x90
 [<c026bfce>] ? xfs_ilock+0xee/0x100
 [<c026bfce>] xfs_ilock+0xee/0x100
 [<c0290fb4>] xfs_inactive+0x334/0x540
 [<c01b382b>] ? inotify_inode_is_dead+0x1b/0x80
 [<c029d4ef>] xfs_fs_clear_inode+0x1f/0x30
 [<c019b7bb>] clear_inode+0x8b/0x110
 [<c019bf06>] generic_delete_inode+0xe6/0x120
 [<c0449d86>] ? _spin_lock+0x66/0x70
 [<c019c09f>] generic_drop_inode+0x15f/0x230
 [<c02c0958>] ? _atomic_dec_and_lock+0x18/0x40
 [<c019b477>] iput+0x47/0x50
 [<c0198a4f>] dentry_iput+0x6f/0xc0
 [<c0198b74>] d_kill+0x24/0x50
 [<c019a03b>] dput+0x5b/0x120
 [<c018a892>] __fput+0x162/0x240
 [<c018a98f>] fput+0x1f/0x30
 [<c01873f7>] filp_close+0x47/0x70
 [<c018748c>] sys_close+0x6c/0xd0
 [<c0102e48>] sysenter_do_call+0x12/0x36
INFO: lockdep is turned off.

Re: 2.6.30-rc4: xfs_fsr hangs

[Heinz Diehl]

On 01.05.2009, Alexander Beregalov wrote: 

> # xfs_db -r /dev/sdc1
> xfs_db> frag
> actual 23805, ideal 22890, fragmentation factor 3.84%
> # xfs_fsr -v /dev/sdc1
> /mnt/c start inode=0
> ino=158
> extents before:3 after:1 DONE ino=158
> 
>  then it hangs

I can't confirm this here on my systems:

liesel:~ # uname -a
Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux

liesel:~ # xfs_db -r /dev/sdc1
xfs_db> frag
actual 42974, ideal 42842, fragmentation factor 0.31%
xfs_db> quit

liesel:~ # xfs_fsr -v /dev/sdc1
/home start inode=0
ino=248755507
ino=248755507 already fully defragmented.
ino=536871160
extents before:2 after:1 DONE ino=536871160
ino=536875693
extents before:3 after:1 DONE ino=536875693
ino=615920545
extents before:2 after:1 DONE ino=615920545
ino=615920557
extents before:2 after:1 DONE ino=615920557
ino=1092324584
extents before:4 after:1 DONE ino=1092324584
liesel:~ #

Re: 2.6.30-rc4: xfs_fsr hangs

[Alexander Beregalov]

2009/5/2 Heinz Diehl <htd@fancy-poultry.org>:
> On 01.05.2009, Alexander Beregalov wrote:
>
>> # xfs_db -r /dev/sdc1
>> xfs_db> frag
>> actual 23805, ideal 22890, fragmentation factor 3.84%
>> # xfs_fsr -v /dev/sdc1
>> /mnt/c start inode=0
>> ino=158
>> extents before:3 after:1 DONE ino=158
>>
>>  then it hangs
>
> I can't confirm this here on my systems:
>
> liesel:~ # uname -a
> Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux

I have this problem on two x86_32 hosts.
It runs for about a minute and then hangs.
vmstat 1:
 0  1     80  30856  12284 1289452    0    0 16384 16380  224  301  0  5  0 95
 0  1     80  32020  12196 1287884    0    0 25984 16380  290  470  0 11  0 89
 0  1     80  30732  12132 1289648    0    0 23168 32760  286  413  0  6  0 94
 0  1     80  32220  12128 1287620    0    0 16384 16380  220  303  0  8  0 92
 1  0     80 198312  12108 1137956    0    0 14472 14628  223  284  0 10  3 87
 0  0     80 1118144  12108 218216    0    0     0     0   63   33  0 38 62  0
 0  0     80 1118144  12108 218216    0    0     0     0   24   26  0  0 100  0
 0  0     80 1118144  12108 218216    0    0     0     0   36   28  0  1 99  0
 0  0     80 1118144  12108 218216    0    0     0     0   36   32  1  1 98  0
 0  0     80 1118144  12108 218216    0    0     0     0   78   66  0  1 99  0

Re: 2.6.30-rc4: xfs_fsr hangs

[Eric Sandeen]

Alexander Beregalov wrote:
> 2009/5/2 Heinz Diehl <htd@fancy-poultry.org>:
>> On 01.05.2009, Alexander Beregalov wrote:
>>
>>> # xfs_db -r /dev/sdc1
>>> xfs_db> frag
>>> actual 23805, ideal 22890, fragmentation factor 3.84%
>>> # xfs_fsr -v /dev/sdc1
>>> /mnt/c start inode=0
>>> ino=158
>>> extents before:3 after:1 DONE ino=158
>>>
>>>  then it hangs
>> I can't confirm this here on my systems:
>>
>> liesel:~ # uname -a
>> Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux
> 
> I have this problem on two x86_32 hosts.
> It runs for about a minute and then hangs.

echo w > /proc/sysrq-trigger
dmesg

would show all the sleeping processes...

-Eric

Re: 2.6.30-rc4: xfs_fsr hangs

[Alexander Beregalov]

2009/5/2 Eric Sandeen <sandeen@sandeen.net>:
> Alexander Beregalov wrote:
>> 2009/5/2 Heinz Diehl <htd@fancy-poultry.org>:
>>> On 01.05.2009, Alexander Beregalov wrote:
>>>
>>>> # xfs_db -r /dev/sdc1
>>>> xfs_db> frag
>>>> actual 23805, ideal 22890, fragmentation factor 3.84%
>>>> # xfs_fsr -v /dev/sdc1
>>>> /mnt/c start inode=0
>>>> ino=158
>>>> extents before:3 after:1 DONE ino=158
>>>>
>>>>  then it hangs
>>> I can't confirm this here on my systems:
>>>
>>> liesel:~ # uname -a
>>> Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux
>>
>> I have this problem on two x86_32 hosts.
>> It runs for about a minute and then hangs.
>
> echo w > /proc/sysrq-trigger
> dmesg
>
> would show all the sleeping processes...
It is the same as I posted already:

SysRq : Show Blocked State
  task                PC stack   pid father
xfs_fsr       D 00000000  5304  3393      1
 ef479dec 00000046 00000001 00000000 ef479de8 f2a58000 f2a58280 f3123830
 f2a58000 00000001 f3123830 f312382c ffffffff f312382c f2a58000 ef479df4
 c0447892 ef479e20 c04498ad ef479e28 f3123830 f3123854 ef479e44 00000246
Call Trace:
 [<c0447892>] schedule+0x12/0x30
 [<c04498ad>] rwsem_down_failed_common+0x6d/0x180
 [<c04499dd>] rwsem_down_write_failed+0x1d/0x30
 [<c0449a2a>] call_rwsem_down_write_failed+0x6/0x8
 [<c026bfce>] ? xfs_ilock+0xee/0x100
 [<c013fcd6>] ? down_write_nested+0x76/0x90
 [<c026bfce>] ? xfs_ilock+0xee/0x100
 [<c026bfce>] xfs_ilock+0xee/0x100
 [<c0290fb4>] xfs_inactive+0x334/0x540
 [<c01b382b>] ? inotify_inode_is_dead+0x1b/0x80
 [<c029d4ef>] xfs_fs_clear_inode+0x1f/0x30
 [<c019b7bb>] clear_inode+0x8b/0x110
 [<c019bf06>] generic_delete_inode+0xe6/0x120
 [<c0449d86>] ? _spin_lock+0x66/0x70
 [<c019c09f>] generic_drop_inode+0x15f/0x230
 [<c02c0958>] ? _atomic_dec_and_lock+0x18/0x40
 [<c019b477>] iput+0x47/0x50
 [<c0198a4f>] dentry_iput+0x6f/0xc0
 [<c0198b74>] d_kill+0x24/0x50
 [<c019a03b>] dput+0x5b/0x120
 [<c018a892>] __fput+0x162/0x240
 [<c018a98f>] fput+0x1f/0x30
 [<c01873f7>] filp_close+0x47/0x70
 [<c018748c>] sys_close+0x6c/0xd0
 [<c0102e48>] sysenter_do_call+0x12/0x36

Re: 2.6.30-rc4: xfs_fsr hangs

[Eric Sandeen]

Alexander Beregalov wrote:
> 2009/5/2 Eric Sandeen <sandeen@sandeen.net>:
>> Alexander Beregalov wrote:
>>> 2009/5/2 Heinz Diehl <htd@fancy-poultry.org>:
>>>> On 01.05.2009, Alexander Beregalov wrote:
>>>>
>>>>> # xfs_db -r /dev/sdc1
>>>>> xfs_db> frag
>>>>> actual 23805, ideal 22890, fragmentation factor 3.84%
>>>>> # xfs_fsr -v /dev/sdc1
>>>>> /mnt/c start inode=0
>>>>> ino=158
>>>>> extents before:3 after:1 DONE ino=158
>>>>>
>>>>>  then it hangs
>>>> I can't confirm this here on my systems:
>>>>
>>>> liesel:~ # uname -a
>>>> Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux
>>> I have this problem on two x86_32 hosts.
>>> It runs for about a minute and then hangs.
>> echo w > /proc/sysrq-trigger
>> dmesg
>>
>> would show all the sleeping processes...
> It is the same as I posted already:

hum, only 1 thread, interesting...

Thanks,
-Eric

Re: 2.6.30-rc4: xfs_fsr hangs

[Ed Tomlinson]

On Saturday 02 May 2009 16:14:00 Eric Sandeen wrote:
> Alexander Beregalov wrote:
> > 2009/5/2 Eric Sandeen <sandeen@sandeen.net>:
> >> Alexander Beregalov wrote:
> >>> 2009/5/2 Heinz Diehl <htd@fancy-poultry.org>:
> >>>> On 01.05.2009, Alexander Beregalov wrote:
> >>>>
> >>>>> # xfs_db -r /dev/sdc1
> >>>>> xfs_db> frag
> >>>>> actual 23805, ideal 22890, fragmentation factor 3.84%
> >>>>> # xfs_fsr -v /dev/sdc1
> >>>>> /mnt/c start inode=0
> >>>>> ino=158
> >>>>> extents before:3 after:1 DONE ino=158
> >>>>>
> >>>>>  then it hangs
> >>>> I can't confirm this here on my systems:
> >>>>
> >>>> liesel:~ # uname -a
> >>>> Linux liesel 2.6.30-rc4 #1 SMP PREEMPT Sat May 2 11:49:13 CEST 2009 x86_64 x86_64 x86_64 GNU/Linux
> >>> I have this problem on two x86_32 hosts.
> >>> It runs for about a minute and then hangs.
> >> echo w > /proc/sysrq-trigger
> >> dmesg
> >>
> >> would show all the sleeping processes...
> > It is the same as I posted already:
> 
> hum, only 1 thread, interesting...
 
I have also had strange stalls with rc4 (but not with rc3).  In one case sysrq would just print the title of commands no
data would follow.  Do not know if this is related but it may be that this is not just an xfs issue.

Ed Tomlinson

Re: 2.6.30-rc4: xfs_fsr hangs

[Eric Sandeen]

Alexander Beregalov wrote:
> # xfs_db -r /dev/sdc1
> xfs_db> frag
> actual 23805, ideal 22890, fragmentation factor 3.84%
> # xfs_fsr -v /dev/sdc1
> /mnt/c start inode=0
> ino=158
> extents before:3 after:1 DONE ino=158
> 
>  then it hangs

Ok, yep with the testcase I proposed I see this on the fedora
2.6.30-rc4.git3 x86 kernel as well:

# for I in `seq 10 -1 0`; do
 dd if=/dev/zero of=fragfile bs=4k count=1 seek=$I conv=notrunc oflag=sync
done

# xfs_fsr fragfile

=====================================
[ BUG: bad unlock balance detected! ]
-------------------------------------
xfs_fsr/1459 is trying to release lock (&(&ip->i_iolock)->mr_lock) at:
[<e248dedb>] xfs_iunlock+0x2c/0x92 [xfs]
but there are no more locks to release!

other info that might help us debug this:
no locks held by xfs_fsr/1459.

stack backtrace:
Pid: 1459, comm: xfs_fsr Not tainted 2.6.30-0.78.rc4.git3.fc12.i586 #1
Call Trace:
 [<c07e2f2e>] ? printk+0x22/0x3c
 [<c0465f34>] print_unlock_inbalance_bug+0xb3/0xd1
 [<e248dedb>] ? xfs_iunlock+0x2c/0x92 [xfs]
 [<c04661e2>] lock_release+0xd0/0x1a6
 [<c04571ce>] up_write+0x29/0x50
 [<e248dedb>] xfs_iunlock+0x2c/0x92 [xfs]
 [<e2496bdb>] xfs_swap_extents+0x427/0x4cc [xfs]
 [<e2496d5a>] xfs_swapext+0xda/0x11c [xfs]
 [<c0a4586d>] ? kobject_uevent_init+0x30/0x6d
 [<e24b2386>] xfs_file_ioctl+0x4ac/0x67e [xfs]
 [<c0592f00>] ? avc_has_perm_noaudit+0x3b1/0x3cc
 [<e24b1eda>] ? xfs_file_ioctl+0x0/0x67e [xfs]
 [<c04ec8fa>] vfs_ioctl+0x29/0x91
 [<c04ecdf8>] do_vfs_ioctl+0x496/0x4e3
 [<c0a4586d>] ? kobject_uevent_init+0x30/0x6d
 [<c05946b7>] ? selinux_file_ioctl+0x4d/0x62
 [<c0a4586d>] ? kobject_uevent_init+0x30/0x6d
 [<c04ece9a>] sys_ioctl+0x55/0x86
 [<c040c6cb>] ? syscall_trace_enter+0xea/0x10f
 [<c040419c>] syscall_call+0x7/0xb
 [<c0a4586d>] ? kobject_uevent_init+0x30/0x6d

there are 2 subsequent unlocks for the same inode:

1:
xfs_iunlock: ip ca2304c0 ino 132  flags 0x5
Pid: 3648, comm: xfs_fsr Not tainted 2.6.30-0.78.rc4.git3.fc12.i586 #1
Call Trace:
 [<e3a81ee7>] xfs_iunlock+0x38/0xb9 [xfs]
 [<e3a82404>] xfs_iput+0x20/0x40 [xfs]
 [<e3a8793b>] xfs_inode_item_unlock+0x82/0x97 [xfs]
 [<e3a9a288>] xfs_trans_unlock_chunk+0x96/0xe1 [xfs]
 [<e3a9a37a>] xfs_trans_unlock_items+0x4f/0xd4 [xfs]
 [<e3a985a9>] _xfs_trans_commit+0x275/0x307 [xfs]
 [<e3a8ac27>] xfs_swap_extents+0x403/0x4cc [xfs]
 [<e3a8adca>] xfs_swapext+0xda/0x11c [xfs]
 [<e3aa63f6>] xfs_file_ioctl+0x4ac/0x67e [xfs]
 [<c04ec8fa>] vfs_ioctl+0x29/0x91
 [<c04ecdf8>] do_vfs_ioctl+0x496/0x4e3
 [<c04ece9a>] sys_ioctl+0x55/0x86
 [<c040419c>] syscall_call+0x7/0xb

2:
xfs_iunlock: ip ca230980 ino 131  flags 0x5
Pid: 3648, comm: xfs_fsr Not tainted 2.6.30-0.78.rc4.git3.fc12.i586 #1
Call Trace:
 [<e3a81ee7>] xfs_iunlock+0x38/0xb9 [xfs]
 [<e3a8ac4b>] xfs_swap_extents+0x427/0x4cc [xfs]
 [<e3a8adca>] xfs_swapext+0xda/0x11c [xfs]
 [<e3aa63f6>] xfs_file_ioctl+0x4ac/0x67e [xfs]
 [<c04ec8fa>] vfs_ioctl+0x29/0x91
 [<c04ecdf8>] do_vfs_ioctl+0x496/0x4e3
 [<c04ece9a>] sys_ioctl+0x55/0x86
 [<c040419c>] syscall_call+0x7/0xb

Looking into it ... not sure offhand what caused this.

-Eric

Re: 2.6.30-rc4: xfs_fsr hangs

[Eric Sandeen]

Eric Sandeen wrote:

> there are 2 subsequent unlocks for the same inode:
> 
> 1:
> xfs_iunlock: ip ca2304c0 ino 132  flags 0x5

...

> 2:
> xfs_iunlock: ip ca230980 ino 131  flags 0x5


Ugh no, those are 2 different inodes.... I can read, really.  :)  still,
looking into it.

-Eric

Re: 2.6.30-rc4: xfs_fsr hangs

[Felix Blyakher]

On May 7, 2009, at 6:55 PM, Eric Sandeen wrote:

> Eric Sandeen wrote:
>
>> there are 2 subsequent unlocks for the same inode:
>>
>> 1:
>> xfs_iunlock: ip ca2304c0 ino 132  flags 0x5
>
> ...
>
>> 2:
>> xfs_iunlock: ip ca230980 ino 131  flags 0x5
>
>
> Ugh no, those are 2 different inodes.... I can read, really.  :)   
> still,
> looking into it.

I've been chasing this as well, and I found the double xfs iolock
unlock which is causing xfs_fsr deadlock itself. I have a fix tested.
The patch is coming.

Felix

>
>
> -Eric
> --
> To unsubscribe from this list: send the line "unsubscribe linux- 
> kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

Re: 2.6.30-rc4: xfs_fsr hangs

[Eric Sandeen]

Felix Blyakher wrote:

> I've been chasing this as well, and I found the double xfs iolock
> unlock which is causing xfs_fsr deadlock itself. I have a fix tested.
> The patch is coming.
>
> Felix
>   
Oh :)  I just sent this one to the list ...  :)

XFS: Fix double unlock of inodes in xfs_swap_extents()

commit ef8f7fc549bf345d92f396f5aa7b152b4969cbf7 had an error
where we would try to re-unlock the inodes after they had been
committed in the transaction; this double unlock caused a

=====================================
[ BUG: bad unlock balance detected! ]
-------------------------------------
xfs_fsr/1459 is trying to release lock (&(&ip->i_iolock)->mr_lock) at:
[<e248dedb>] xfs_iunlock+0x2c/0x92 [xfs]
but there are no more locks to release!

Signed-off-by: Eric Sandeen <sandeen@sandeen.net>
---

Index: linux-2.6/fs/xfs/xfs_dfrag.c
===================================================================
--- linux-2.6.orig/fs/xfs/xfs_dfrag.c
+++ linux-2.6/fs/xfs/xfs_dfrag.c
@@ -347,13 +347,15 @@ xfs_swap_extents(
 
 	error = xfs_trans_commit(tp, XFS_TRANS_SWAPEXT);
 
-out_unlock:
-	xfs_iunlock(ip,  XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
-	xfs_iunlock(tip, XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
 out:
 	kmem_free(tempifp);
 	return error;
 
+out_unlock:
+	xfs_iunlock(ip,  XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
+	xfs_iunlock(tip, XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
+	goto out;
+
 out_trans_cancel:
 	xfs_trans_cancel(tp, 0);
 	goto out_unlock;

Re: 2.6.30-rc4: xfs_fsr hangs

[Felix Blyakher]

On May 7, 2009, at 8:09 PM, Eric Sandeen wrote:

> Felix Blyakher wrote:
>
>> I've been chasing this as well, and I found the double xfs iolock
>> unlock which is causing xfs_fsr deadlock itself. I have a fix tested.
>> The patch is coming.
>>
>> Felix
>>
> Oh :)  I just sent this one to the list ...  :)

Oh :) And I did as well.

And guess what, the fix is exactly the same.
Great minds think alike :)

Felix

>
>
> XFS: Fix double unlock of inodes in xfs_swap_extents()
>
> commit ef8f7fc549bf345d92f396f5aa7b152b4969cbf7 had an error
> where we would try to re-unlock the inodes after they had been
> committed in the transaction; this double unlock caused a
>
> =====================================
> [ BUG: bad unlock balance detected! ]
> -------------------------------------
> xfs_fsr/1459 is trying to release lock (&(&ip->i_iolock)->mr_lock) at:
> [<e248dedb>] xfs_iunlock+0x2c/0x92 [xfs]
> but there are no more locks to release!
>
> Signed-off-by: Eric Sandeen <sandeen@sandeen.net>
> ---
>
> Index: linux-2.6/fs/xfs/xfs_dfrag.c
> ===================================================================
> --- linux-2.6.orig/fs/xfs/xfs_dfrag.c
> +++ linux-2.6/fs/xfs/xfs_dfrag.c
> @@ -347,13 +347,15 @@ xfs_swap_extents(
>
> 	error = xfs_trans_commit(tp, XFS_TRANS_SWAPEXT);
>
> -out_unlock:
> -	xfs_iunlock(ip,  XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
> -	xfs_iunlock(tip, XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
> out:
> 	kmem_free(tempifp);
> 	return error;
>
> +out_unlock:
> +	xfs_iunlock(ip,  XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
> +	xfs_iunlock(tip, XFS_ILOCK_EXCL | XFS_IOLOCK_EXCL);
> +	goto out;
> +
> out_trans_cancel:
> 	xfs_trans_cancel(tp, 0);
> 	goto out_unlock;
>
>
>
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux- 
> kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/