Re: xfs_iunlink_remove: xfs_inotobp() returned error 22 -- debugging

符永涛
2013-04-18T01:30:20Z

[-- Attachment #1.1: Type: text/plain, Size: 11339 bytes --]

Hi Eric,
The shutdown issue is still not reproduced yet. But I get the following
error today during test.

Apr 18 07:42:51 10 kernel: Call Trace:
Apr 18 07:42:51 10 kernel: [<ffffffffa02d91ef>] ?
xfs_buf_cond_lock+0x2f/0xc0 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff814fe6a5>] schedule_timeout+0x215/0x2e0
Apr 18 07:42:51 10 kernel: [<ffffffffa02d5f07>] ? kmem_zone_alloc+0x77/0xf0
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff814ff5c2>] __down+0x72/0xb0
Apr 18 07:42:51 10 kernel: [<ffffffffa02da652>] ? _xfs_buf_find+0x102/0x280
[xfs]
Apr 18 07:42:51 10 kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 18 07:42:51 10 kernel: glusterfsd D ffffffff8160b3c0 0
14522 1 0x00000083
Apr 18 07:42:51 10 kernel: ffff882015a63a28 0000000000000082
0000000000000000 0000000000000000
Apr 18 07:42:51 10 kernel: ffff882015a639b8 ffffffffa02d91ef
ffff882015a639d8 0000000000000246
Apr 18 07:42:51 10 kernel: ffff880e70491af8 ffff882015a63fd8
000000000000fb88 ffff880e70491af8
Apr 18 07:42:51 10 kernel: Call Trace:
Apr 18 07:42:51 10 kernel: [<ffffffffa02d91ef>] ?
xfs_buf_cond_lock+0x2f/0xc0 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff814fe6a5>] schedule_timeout+0x215/0x2e0
Apr 18 07:42:51 10 kernel: [<ffffffffa02d5f07>] ? kmem_zone_alloc+0x77/0xf0
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff814ff5c2>] __down+0x72/0xb0
Apr 18 07:42:51 10 kernel: [<ffffffffa02da652>] ? _xfs_buf_find+0x102/0x280
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff81097ef1>] down+0x41/0x50
Apr 18 07:42:51 10 kernel: [<ffffffffa02da493>] xfs_buf_lock+0x53/0x110
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02da652>] _xfs_buf_find+0x102/0x280
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02da83b>] xfs_buf_get+0x6b/0x1a0 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02daeac>] xfs_buf_read+0x2c/0x100
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02d0af8>]
xfs_trans_read_buf+0x1f8/0x400 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02b3444>] xfs_read_agi+0x74/0x100
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02b967b>] xfs_iunlink+0x5b/0x180 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff810724c7>] ? current_fs_time+0x27/0x30
Apr 18 07:42:51 10 kernel: [<ffffffffa02d12a7>] ?
xfs_trans_ichgtime+0x27/0xa0 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02d15fb>] xfs_droplink+0x5b/0x70 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffffa02d2f9e>] xfs_remove+0x27e/0x3a0 [xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff81186fd3>] ?
generic_permission+0x23/0xb0
Apr 18 07:42:51 10 kernel: [<ffffffffa02e0968>] xfs_vn_unlink+0x48/0x90
[xfs]
Apr 18 07:42:51 10 kernel: [<ffffffff81188c0f>] vfs_unlink+0x9f/0xe0
Apr 18 07:42:51 10 kernel: [<ffffffff8118795a>] ? lookup_hash+0x3a/0x50
Apr 18 07:42:51 10 kernel: [<ffffffff8118b143>] do_unlinkat+0x183/0x1c0
Apr 18 07:42:51 10 kernel: [<ffffffff81017938>] ?
syscall_trace_enter+0x1d8/0x1e0
Apr 18 07:42:51 10 kernel: [<ffffffff8118b196>] sys_unlink+0x16/0x20
Apr 18 07:42:51 10 kernel: [<ffffffff8100b308>] tracesys+0xd9/0xde

Thank you.

2013/4/17 Eric Sandeen <sandeen@sandeen.net>

> On Apr 16, 2013, at 8:48 PM, 符永涛 <yongtaofu@gmail.com> wrote:
>
> Hi Brain,
> Can I change as following?
>
>
> ASSERTS are no-ops in a non-debug kernel, so this won't change any
> behavior. I hope we'll know more if we get new traces from your patched
> kernel....
>
> Eric
>
> --- a/xfs_inode.c
> +++ b/xfs_inode.c
> @@ -1773,6 +1773,8 @@ xfs_iunlink_remove(
> if (last_ibp != NULL) {
> xfs_trans_brelse(tp, last_ibp);
> }
> + ASSERT(next_agino != NULLAGINO);
> + ASSERT(next_agino != 0);
> next_ino = XFS_AGINO_TO_INO(mp, agno, next_agino);
> error = xfs_inotobp(mp, tp, next_ino, &last_dip,
> &last_ibp, &last_offset, 0);
> @@ -1783,8 +1785,6 @@ xfs_iunlink_remove(
> return error;
> }
> next_agino =
> be32_to_cpu(last_dip->di_next_unlinked);
> - ASSERT(next_agino != NULLAGINO);
> - ASSERT(next_agino != 0);
> }
> /*
> * Now last_ibp points to the buffer previous to us on
>
> Thank you.
>
>
> 2013/4/17 符永涛 <yongtaofu@gmail.com>
>
>> Hi Brain,
>> If it is because NULLAGINO is passed in to xfs_inotobp().
>> Can I move the following two lines before xfs_inotobp?
>>
>> For example:
>>
>> 1767 while (next_agino != agino) {
>> 1768 /*
>> 1769 * If the last inode wasn't the one pointing
>> to
>> 1770 * us, then release its buffer since we're
>> not
>> 1771 * going to do anything with it.
>> 1772 */
>> 1773 if (last_ibp != NULL) {
>> 1774 xfs_trans_brelse(tp, last_ibp);
>> 1775 }
>> 1776 next_ino = XFS_AGINO_TO_INO(mp, agno,
>> next_agino);
>> + ASSERT(next_agino != NULLAGINO);
>> + ASSERT(next_agino != 0);
>> 1777 error = xfs_inotobp(mp, tp, next_ino,
>> &last_dip,
>> 1778 &last_ibp, &last_offset,
>> 0);
>> 1779 if (error) {
>> 1780 xfs_warn(mp,
>> 1781 "%s: xfs_inotobp() returned
>> error %d.",
>> 1782 __func__, error);
>> 1783 return error;
>> 1784 }
>> 1785 next_agino =
>> be32_to_cpu(last_dip->di_next_unlinked);
>> - //ASSERT(next_agino != NULLAGINO);
>> - //ASSERT(next_agino != 0);
>> 1788 }
>> I don't understand xfs well and correct me if I'm totally wrong.
>> Thank you very much.
>>
>>
>> 2013/4/17 符永涛 <yongtaofu@gmail.com>
>>
>>> Hi Brain,
>>> I want to ask a question, according to the shutdown trace. The ino in xfs_iunlink_remove
>>> is 0x113, why xfs_imap got ino=0xffffffff ?
>>>
>>> --- xfs_imap -- module("xfs").function("xfs_imap@fs
>>> /xfs/xfs_ialloc.c:1257").return -- return=0x16
>>> vars: mp=0xffff882017a50800 tp=0xffff881c81797c70 ino=0xffffffff
>>>
>>> --- xfs_iunlink_remove -- module("xfs").function("xfs_iunlink_remove@fs
>>> /xfs/xfs_inode.c:1680").return -- return=0x16
>>> vars: tp=0xffff881c81797c70 ip=0xffff881003c13c00 next_ino=? mp=? agi=?
>>> dip=? agibp=0xffff880109b47e20 ibp=? agno=? agino=? next_agino=? last_ibp=?
>>> last_dip=0xffff882000000000 bucket_index=? offset=?
>>> last_offset=0xffffffffffff8810 error=? __func__=[...]
>>> ip: i_ino = 0x113, i_flags = 0x0
>>>
>>> Thank you.
>>>
>>>
>>>
>>> 2013/4/17 符永涛 <yongtaofu@gmail.com>
>>>
>>>> Hi Brain,
>>>> Thank you for your update, and I have applied your last kernel patch.
>>>> However it is not easy to reproduce especially in out test environment.
>>>> Till now is not happens again. I'll update the kernel patch now. BTW is
>>>> there any findings in the logs of previous thread?
>>>> http://oss.sgi.com/archives/xfs/2013-04/msg00327.html
>>>> I guess it tend to happen during glusterfs rebalance because glusterfs
>>>> moves a lot of file from one server to another and then unlink it.
>>>>
>>>> Thank you.
>>>>
>>>>
>>>> 2013/4/17 Brian Foster <bfoster@redhat.com>
>>>>
>>>>> On 04/16/2013 12:24 PM, Dave Chinner wrote:
>>>>> > On Mon, Apr 15, 2013 at 07:14:39PM -0400, Brian Foster wrote:
>>>>> >> Hi,
>>>>> >>
>>>>> >> Thanks for the data in the previous thread:
>>>>> >>
>>>>> >> http://oss.sgi.com/archives/xfs/2013-04/msg00327.html
>>>>> >>
>>>>> ...
>>>>> >>
>>>>> >> echo 1 >
>>>>> /sys/kernel/debug/tracing/events/xfs/xfs_iunlink/enable
>>>>> >> echo 1 >
>>>>> /sys/kernel/debug/tracing/events/xfs/xfs_iunlink_remove/enable
>>>>> >> ... reproduce ...
>>>>> >> cat /sys/kernel/debug/tracing/trace > trace.output
>>>>> >
>>>>> > It's better to use trace-cmd for this. it will result in less
>>>>> > dropped events. i.e.:
>>>>> >
>>>>> > $ trace-cmd record -e xfs_iunlink\*
>>>>> > ... reproduce ...
>>>>> > ^C
>>>>> > $ trace-cmd report > trace.output
>>>>> >
>>>>> >> --- a/fs/xfs/linux-2.6/xfs_trace.h
>>>>> >> +++ b/fs/xfs/linux-2.6/xfs_trace.h
>>>>> >> @@ -581,6 +581,8 @@ DEFINE_INODE_EVENT(xfs_file_fsync);
>>>>> ...
>>>>> >
>>>>> > I would suggest that the the tracing shoul dbe at entry of the
>>>>> > function, otherwise we won't get a tracepoint for the operation that
>>>>> > triggers the shutdown. (That's the reason most tracepoints in XFS
>>>>> > are at function entry...)
>>>>> >
>>>>>
>>>>> Good points, thanks Dave. A v2 that pulls up the tracepoints towards
>>>>> function entry is appended.
>>>>>
>>>>> Brian
>>>>>
>>>>> From 280943e78ebe0b97a774cba51e7815c42f044b55 Mon Sep 17 00:00:00 2001
>>>>> From: Brian Foster <bfoster@redhat.com>
>>>>> Date: Mon, 15 Apr 2013 18:16:24 -0400
>>>>> Subject: [PATCH v2] xfs: add tracepoints for xfs_iunlink and
>>>>> xfs_iunlink_remove
>>>>>
>>>>> ---
>>>>> fs/xfs/linux-2.6/xfs_trace.h | 2 ++
>>>>> fs/xfs/xfs_inode.c | 4 ++++
>>>>> 2 files changed, 6 insertions(+), 0 deletions(-)
>>>>>
>>>>> diff --git a/fs/xfs/linux-2.6/xfs_trace.h
>>>>> b/fs/xfs/linux-2.6/xfs_trace.h
>>>>> index adc6ec4..338a0f9 100644
>>>>> --- a/fs/xfs/linux-2.6/xfs_trace.h
>>>>> +++ b/fs/xfs/linux-2.6/xfs_trace.h
>>>>> @@ -583,6 +583,8 @@ DEFINE_INODE_EVENT(xfs_file_fsync);
>>>>> DEFINE_INODE_EVENT(xfs_destroy_inode);
>>>>> DEFINE_INODE_EVENT(xfs_dirty_inode);
>>>>> DEFINE_INODE_EVENT(xfs_clear_inode);
>>>>> +DEFINE_INODE_EVENT(xfs_iunlink);
>>>>> +DEFINE_INODE_EVENT(xfs_iunlink_remove);
>>>>>
>>>>> DEFINE_INODE_EVENT(xfs_dquot_dqalloc);
>>>>> DEFINE_INODE_EVENT(xfs_dquot_dqdetach);
>>>>> diff --git a/fs/xfs/xfs_inode.c b/fs/xfs/xfs_inode.c
>>>>> index 19900f0..d705c77 100644
>>>>> --- a/fs/xfs/xfs_inode.c
>>>>> +++ b/fs/xfs/xfs_inode.c
>>>>> @@ -1615,6 +1615,8 @@ xfs_iunlink(
>>>>>
>>>>> mp = tp->t_mountp;
>>>>>
>>>>> + trace_xfs_iunlink(ip);
>>>>> +
>>>>> /*
>>>>> * Get the agi buffer first. It ensures lock ordering
>>>>> * on the list.
>>>>> @@ -1694,6 +1696,8 @@ xfs_iunlink_remove(
>>>>> mp = tp->t_mountp;
>>>>> agno = XFS_INO_TO_AGNO(mp, ip->i_ino);
>>>>>
>>>>> + trace_xfs_iunlink_remove(ip);
>>>>> +
>>>>> /*
>>>>> * Get the agi buffer first. It ensures lock ordering
>>>>> * on the list.
>>>>> --
>>>>> 1.7.7.6
>>>>>
>>>>>
>>>>
>>>>
>>>> --
>>>> 符永涛
>>>>
>>>
>>>
>>>
>>> --
>>> 符永涛
>>>
>>
>>
>>
>> --
>> 符永涛
>>
>
>
>
> --
> 符永涛
>
> _______________________________________________
> xfs mailing list
> xfs@oss.sgi.com
> http://oss.sgi.com/mailman/listinfo/xfs
>
>

--
符永涛

[-- Attachment #1.2: Type: text/html, Size: 21790 bytes --]