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

符永涛
2013-04-20T11:52:21Z

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

Hi Brain,
Here is the file:
find . -inum 539274
./crashtest/.glusterfs/indices/xattrop
[root@10.23.72.94 xfsd]# ls -lih ./crashtest/.glusterfs/indices/xattrop
total 0
539275 ---------- 2 root root 0 Apr 20 17:17
132ef294-71d1-4435-8daa-aa002e67cb6e
539275 ---------- 2 root root 0 Apr 20 17:17
xattrop-f3ad589a-b8dc-4416-ab84-fc9ad4033540
find . -inum 539275
./crashtest/.glusterfs/indices/xattrop/xattrop-f3ad589a-b8dc-4416-ab84-fc9ad4033540
./crashtest/.glusterfs/indices/xattrop/132ef294-71d1-4435-8daa-aa002e67cb6e
I'm not sure if it is normal or glusterfs fall in infinite loop. Is there a
change that the kernel fall into dead loop?
I'll study it.

2013/4/20 Brian Foster <bfoster@redhat.com>

> On 04/20/2013 06:10 AM, 符永涛 wrote:
> > Dear Eric,
> > I have applied your latest patch and collected the following log:
> >
> > /var/log/message
> > Apr 20 17:28:23 10 kernel: XFS (sdb): xfs_iunlink_remove: xfs_inotobp()
> > returned error 22 for inode 0x1b20b ag 0 agino 1b20b
> > Apr 20 17:28:23 10 kernel:
> > Apr 20 17:28:23 10 kernel: XFS (sdb): xfs_inactive: xfs_ifree returned
> > error 22
> > Apr 20 17:28:23 10 kernel: XFS (sdb): xfs_do_force_shutdown(0x1) called
> > from line 1184 of file fs/xfs/xfs_vnodeops.c. Return address =
> > 0xffffffffa02d4d0a
> > Apr 20 17:28:23 10 kernel: XFS (sdb): I/O Error Detected. Shutting down
> > filesystem
> > Apr 20 17:28:23 10 kernel: XFS (sdb): Please umount the filesystem and
> > rectify the problem(s)
> > Apr 20 17:28:37 10 kernel: XFS (sdb): xfs_log_force: error 5 returned.
> > Apr 20 17:29:07 10 kernel: XFS (sdb): xfs_log_force: error 5 returned.
> > Apr 20 17:29:37 10 kernel: XFS (sdb): xfs_log_force: error 5 returned.
> > Apr 20 17:30:07 10 kernel: XFS (sdb): xfs_log_force: error 5 returned.
> >
> > debugfs trace:
> >
> https://docs.google.com/file/d/0B7n2C4T5tfNCTlZGUVpnZENrZ3M/edit?usp=sharing
> >
>
> FWIW...
>
> <...>-6908 [001] 8739.967623: xfs_iunlink: dev 8:16 ino 0x83a8b mode
> 0100000, flags 0x0
> <...>-6909 [001] 8739.970252: xfs_iunlink: dev 8:16 ino 0x83a8b mode
> 0100000, flags 0x0
>
> 0x83a8b and 0x1b20b both hash to unlinked list bucket 11.
>
> As to the rest of the trace, there appears to be a significant amount of
> link activity on (directory) inode 0x83a8a (the immediately prior inode
> to the inode involved in the race). The name data in the trace suggests
> activity somewhere under .glusterfs. A couple questions:
>
> 1.) Any idea what entries point to this inode right now (e.g., how many
> links on this inode) and where it resides in the fs (path)?
>
> 2.) Can you associate this kind of heavy remove/link pattern on a single
> inode to a higher level activity? For example, if you were to watch the
> trace data live, is this a normal pattern you observe? Does it only
> occur when a rebalance is in progress? Or when a rebalance finishes? Any
> detailed observations you can make in that regard could be helpful.
>
> Brian
>
> > Thank you.
> >
> >
> > 2013/4/20 符永涛 <yongtaofu@gmail.com <mailto:yongtaofu@gmail.com>>
> >
> > Hi Eric,
> > The xfs module is loaded from system kernel, it happens on our
> > production server too (I did not touch that till now) and if the xfs
> > module is mess up the systemstap may also not working but now it
> > works. As you have mentioned, strange thing is xfs shutdown always
> > happens when glusterfs rebalance completes.
> >
> >
> > 2013/4/20 Eric Sandeen <sandeen@sandeen.net
> > <mailto:sandeen@sandeen.net>>
> >
> > On 4/19/13 9:03 PM, 符永涛 wrote:
> > > Hi Eric,
> > > I will enable them and run test again. I can only reproduce it
> > with
> > > glusterfs rebalance. Glusterfs uses a mechanism it called
> > syncop to
> > > unlink file. For rebalance it uses
> > > syncop_unlink(glusterfs/libglusterfs/src/syncop.c). In the
> > glusterfs
> > > sync_task framework(glusterfs/libglusterfs/src/syncop.c) it
> uses
> > > "makecontext/swapcontext"
> > >
> > <
> http://www.opengroup.org/onlinepubs/009695399/functions/makecontext.html>.
> > > Does it leads to racing unlink from different CPU core?
> >
> > Yep, I understand that it's rebalance. It dies when rebalance
> > finishes because an
> > open but unlinked file trips over the corrupted list from
> > earlier, it seems.
> >
> > I don't know why makecontext would matter...
> >
> > Just to be sure, you are definitely loading the xfs module from
> > the kernel you built, right, and you don't have a "priority"
> > module getting loaded from elsewhere? Seems unlikely, but just
> > to be sure.
> >
> > > Thank you.
> >
> > You could also add this patch to the xfs tracepoints to print
> > more information about the inodes - the mode & flags.
> >
> > -Eric
> >
> >
> > diff --git a/fs/xfs/linux-2.6/xfs_trace.h
> > b/fs/xfs/linux-2.6/xfs_trace.h
> > index e8ce644..c314b87 100644
> > --- a/fs/xfs/linux-2.6/xfs_trace.h
> > +++ b/fs/xfs/linux-2.6/xfs_trace.h
> > @@ -544,14 +544,18 @@ DECLARE_EVENT_CLASS(xfs_inode_class,
> > TP_STRUCT__entry(
> > __field(dev_t, dev)
> > __field(xfs_ino_t, ino)
> > + __field(__u16, mode)
> > + __field(unsigned long, flags)
> > ),
> > TP_fast_assign(
> > __entry->dev = VFS_I(ip)->i_sb->s_dev;
> > __entry->ino = ip->i_ino;
> > + __entry->mode = VFS_I(ip)->i_mode;
> > + __entry->flags = ip->i_flags;
> > ),
> > - TP_printk("dev %d:%d ino 0x%llx",
> > + TP_printk("dev %d:%d ino 0x%llx mode 0%o, flags 0x%lx",
> > MAJOR(__entry->dev), MINOR(__entry->dev),
> > - __entry->ino)
> > + __entry->ino, __entry->mode, __entry->flags)
> > )
> >
> > #define DEFINE_INODE_EVENT(name) \
> >
> >
> >
> >
> >
> >
> > --
> > 符永涛
> >
> >
> >
> >
> > --
> > 符永涛
>
>

--
符永涛

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