Re: Possible XFS bug encountered in 3.14.0-rc3+

[Ben Myers <bpm@sgi.com>]

On Thu, Mar 13, 2014 at 02:47:58PM +0000, Mears, Morgan wrote:
> On Wed, Mar 12, 2014 at 07:03:14PM -0400, Dave Chinner wrote:
> > On Wed, Mar 12, 2014 at 08:14:32PM +0000, Mears, Morgan wrote:
> >> Hi,
> >> 
> >> Please CC me on any responses; I don't subscribe to this list.
> >> 
> >> I ran into a possible XFS bug while doing some Oracle benchmarking.  My test
> >> system is running a 3.14.0-rc3+ kernel built from the for-next branch of
> >> git://git.kernel.org/pub/scm/linux/kernel/git/device-mapper/linux-dm.git
> >> on 2014-02-19 (last commit 1342f11e713792e53e4b7aa21167fe9caca81c4a).
> >> 
> >> The XFS instance in question is 200 GB and should have all default
> >> parameters (mkfs.xfs /dev/mapper/<my_lun_partition>).  It contains Oracle
> >> binaries and trace files.  At the time the issue occurred I had been
> >> running Oracle with SQL*NET server tracing enabled.  The affected XFS
> >> had filled up 100% with trace files several times; I was periodically
> >> executing rm -f * in the trace file directory, which would reduce the
> >> file system occupancy from 100% to 3%.  I had an Oracle load generating
> >> tool running, so new log files were being created with some frequency.
> >> 
> >> The issue occurred during one of my rm -f * executions; afterwards the
> >> file system would only produce errors.  Here is the traceback:
> >> 
> >> [1552067.297192] XFS: Internal error XFS_WANT_CORRUPTED_GOTO at line 1602 of file fs/xfs/xfs_alloc.c.  Caller 0xffffffffa04c4905
> > 
> > So, freeing a range that is already partially free. The problem
> > appears to be in AG 15, according to the repair output.
> > 
> >> https://dl.dropboxusercontent.com/u/31522929/xfs-double-free-xfs_metadump-before-repair.gz
> > 
> > AGF 15 is full:
> > 
> > xfs_db> agf 15
> > xfs_db> p
> > magicnum = 0x58414746
> > versionnum = 1
> > seqno = 15
> > length = 3276783
> > bnoroot = 1
> > cntroot = 2
> > bnolevel = 1
> > cntlevel = 1
> > flfirst = 0
> > fllast = 3
> > flcount = 4
> > freeblks = 1
> > longest = 1
> > btreeblks = 0
> > uuid = 00000000-0000-0000-0000-000000000000
> > lsn = 0
> > crc = 0
> > 
> > And the one free block (other than the minimum 4 on teh AGFL) is:
> > 
> > xfs_db> p
> > magic = 0x41425442
> > level = 0
> > numrecs = 1
> > leftsib = null
> > rightsib = null
> > recs[1] = [startblock,blockcount] 1:[3119876,1]
> > 
> > But:
> > 
> > data fork in ino 940862056 claims dup extent, off - 11, start - 58836692, cnt 1
> > correcting nextents for inode 940862056
> > bad data fork in inode 940862056
> > would have cleared inode 940862056
> > 
> > the block number here is in AG 14, which has much more free space:
> > 
> > xfs_db> p
> > magicnum = 0x58414746
> > versionnum = 1
> > seqno = 14
> > length = 3276783
> > bnoroot = 1
> > cntroot = 2
> > bnolevel = 1
> > cntlevel = 1
> > flfirst = 42
> > fllast = 45
> > flcount = 4
> > freeblks = 2092022
> > longest = 2078090
> > btreeblks = 0
> > 
> > which is in 2 extents:
> > 
> > xfs_db> a bnoroot
> > xfs_db> p
> > magic = 0x41425442
> > level = 0
> > numrecs = 2
> > leftsib = null
> > rightsib = null
> > recs[1-2] = [startblock,blockcount] 1:[102466,13932] 2:[116476,2078090]
> > xfs_db> convert agno 14 agbno 102466 fsb
> > 0x3819042 (58822722)
> > xfs_db> convert agno 14 agbno 116476 fsb
> > 0x381c6fc (58836732)
> > 
> > and so 58836692 is just short of the second free space. Looking at
> > all the other dup extent claims, they a remostly adjacent to the
> > left edge of these two free spaces. No surprise - that's the way
> > allocation occurs.
> > 
> > So, we've got a state where the allocation btree contains a
> > corruption, so a shutdown occurs. The log has captured that
> > corruption when it was made, so log recovery reintroduces that
> > corruption. And so when the extent is freed after log recovery, the
> > corruption is tripped over again.
> > 
> > There's two checkpoints in the log, both very small. The last
> > modification to AGI 14 is there before it:
> > 
> > BUF: cnt:2 total:2 a:0x669350 len:24 a:0x6693d0 len:128 
> >         BUF:  #regs:2   start blkno:0x15dff891   len:1   bmap size:1   flags:0x2800
> >         AGF Buffer: (XAGF)
> >             ver:1  seq#:14  len:3276783  
> >             root BNO:1  CNT:2
> >             level BNO:1  CNT:1
> >             1st:42  last:45  cnt:4  freeblks:2092020  longest:2078090
> > 
> > As is the freespace btree buffer modification:
> > 
> > BUF: cnt:2 total:2 a:0x669460 len:24 a:0x6694e0 len:128 
> >         BUF:  #regs:2   start blkno:0x15dff898   len:8   bmap size:1   flags:0x2000
> >         BUF DATA
> >  0 42544241  4000000 ffffffff ffffffff cb620100  1000000 fc7c0100  2000000 
> >    magic = BTBA
> >    level = 0
> >    numrecs = 4
> >    leftsib = NULLFSBLOCK
> >    rightsib = NULLFSBLOCK
> >    rec[0] = 0x162cb, 1 (90827,1)
> >    rec[1] = 0x17cfc, 2 (97532,1)
> >  8 47900100 67360000 fcc60100 8ab51f00 71ff3100  5000000 71ff3100  5000000 
> >    rec[2] = 0x19047, 0x3667 (102471,13927)
> >    rec[3] = 0x1c6fc, 0x1fb58a (116476,2078090)
> > 
> > so, from the pre-recovery case above, we've got two new freespaces
> > in rec[0-1], rec[2] has 5 blocks removed from the left edge, and
> > rec[3] is unchanged.
> > 
> > Confirming the ABTC buffer contains the same extents:
> > 
> > BUF: cnt:2 total:2 a:0x669570 len:24 a:0x6695f0 len:128 
> >         BUF:  #regs:2   start blkno:0x15dff8a0   len:8   bmap size:1   flags:0x2000
> >         BUF DATA
> >  0 43544241  4000000 ffffffff ffffffff cb620100  1000000 fc7c0100  2000000 
> >    magic = CTBA
> >    level = 0
> >    numrecs = 4
> >    leftsib = NULLFSBLOCK
> >    rightsib = NULLFSBLOCK
> >    rec[0] = 0x162cb, 1 (90827,1)
> >    rec[1] = 0x17cfc, 2 (97532,1)
> >  8 47900100 67360000 fcc60100 8ab51f00 71ff3100  5000000 71ff3100  5000000 
> >    rec[2] = 0x19047, 0x3667 (102471,13927)
> >    rec[3] = 0x1c6fc, 0x1fb58a (116476,2078090)
> > 10  8ca0100  8000000 71ff3100  5000000 71ff3100  5000000 71ff3100  5000000 
> > 18 71ff3100  5000000 71ff3100  5000000 71ff3100  5000000 71ff3100  5000000 
> > 
> > It does. So the btrees contain consistent information, and so it's
> > unlikely that we have a free space btree corruption in the log. So
> > let's look at what was freed:
> > 
> > The EFI/EFDs in the log are:
> > 
> > EFI: cnt:1 total:1 a:0x668670 len:32 
> >         EFI:  #regs:1    num_extents:1  id:0xffff881496024af0
> >         (s: 0x38162cb, l: 1) 
> > EFD: cnt:1 total:1 a:0x6684d0 len:32 
> >         EFD:  #regs: 1    num_extents: 1  id: 0xffff881496024af0
> > ....
> > EFI: cnt:1 total:1 a:0x667da0 len:32 
> >         EFI:  #regs:1    num_extents:1  id:0xffff8814960244b0
> >         (s: 0x3817cfc, l: 1) 
> > EFD: cnt:1 total:1 a:0x65fbd0 len:32 
> >         EFD:  #regs: 1    num_extents: 1  id: 0xffff8814960244b0
> > ....
> > EFI: cnt:1 total:1 a:0x669250 len:32 
> >         EFI:  #regs:1    num_extents:1  id:0xffff881496024000
> >         (s: 0x3817cfd, l: 1) 
> > EFD: cnt:1 total:1 a:0x6692d0 len:32 
> >         EFD:  #regs: 1    num_extents: 1  id: 0xffff881496024000
> > 
> > These are all in ag#14, and have agbnos of 0x162cb, 0x17cfc and
> > 0x17cfd. This corresponds exactly to the two new records in the AG
> > btree. The one remaining EFI doesn't have an EFD in th elog, so this
> > is what is being replayed:
> > 
> > EFI: cnt:1 total:1 a:0x669f40 len:32 
> >         EFI:  #regs:1    num_extents:1  id:0xffff881496024640
> > 	(s: 0x3869ff9, l: 1) 
> > 
> > Which is at agbno 0x69ff9 (434169). That's off to the right of the
> > start of the last freespace range in rec[3]. rec[3] starts at
> > 0x1c6fc and ends at 0x1fb58a. That means this efi clearly lands
> > inside that freespace range - it's not an edge case, it's deep in
> > the interior of the freespace range.
> > 
> > The inode logged just before the EFI - likely it's owner:
> > 
> > INO: cnt:2 total:2 a:0x668040 len:56 a:0x667fb0 len:96 
> >         INODE: #regs:2   ino:0x3862d698  flags:0x1   dsize:0
> >         CORE inode:
> >             magic:IN  mode:0x81b0  ver:2  format:2  onlink:0
> >             uid:1001  gid:1001  nlink:0 projid:0
> >             atime:1394495104  mtime:1394495104  ctime:1394554526
> >             flushiter:1
> >             size:0x0  nblks:0x0  exsize:0  nextents:0  anextents:0
> >             forkoff:13  dmevmask:0x0  dmstate:0  flags:0x0  gen:-121998876
> > 
> > Is an unlinked inode that has had all it's block removed. Yup - it's
> > on the unlinked list:
> > 
> > agi unlinked bucket 24 is 6477464 in ag 14 (inode=946001560)
> > 
> > So, prior to recovery, what did it contain? it's got 287 bytes of
> > date, and a single extent:
> > 
> > u.bmx[0] = [startoff,startblock,blockcount,extentflag] 0:[0,59154425,1,0]
> > 
> > xfs_db> convert fsb 59154425 agno
> > 0xe (14)
> > xfs_db> convert fsb 59154425 agbno
> > 0x69ff9 (434169)
> > 
> > Ok, so the corruption, whatever it was, happened a long time ago,
> > and it's only when removing the file that it was tripped over.
> > There's nothing more I can really get from this - the root cause of
> > the corruption is long gone.
> > 
> > Cheers,
> > 
> > Dave.
> > -- 
> > Dave Chinner
> > david@fromorbit.com
> 
> Thanks Dave.
> 
> Upon restarting my testing I immediately hit this error again (or a very
> similar one in any case).  I suspect that the corruption you've noted was
> not properly repaired by xfs_repair.

There are some kinds of corruption that xfs_repair was finding but not
repairing until commit ea4a8de1e1.  I suggest you upgrade if you don't have
this commit.  How long ago did you make this filesystem?

Thanks,
	Ben

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs