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

符永涛
2013-04-18T06:46:04Z

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

Hi Brain and Eric,
If the problem is the agno can't be found in the unlinked list. Can we just
bypass it instead of passing ino=0xffffffff to xfs_inotobp?
Thank you.

2013/4/18 符永涛 <yongtaofu@gmail.com>

> 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: 22520 bytes --]