Hi Brian, These traces, and the stack trace presented, looks quite similar with the one we were discussing a few days ago, using a dm-thin snapshot. Looks like with the same bug I've been hunting and Shyam confirmed my hypothesis of this bug be able to be reproduced with a regular device. If it's the same bug, yes, I reproduced it using upstream kernel. The difference between both (this bug and the one I've been working on) is how xfs actually behaves when async metadata writes fail. Other than that, it pretty much looks the same. Trying to unmount the filesystem hungs in xfs_log_force(), well, basically the reason I submitted the patch to include the caller into xfs_log_force trace. I'd like to see ftrace traces from this system with that patch if possible. I didn't have time to keep working on this for the past few days, but looks like it's time to come back to it. Shyam, after you reconnected the disks, the messages about failed async metadata writes stops to be logged? Any chance you can reliably reproduce it? I'm not a xfs journal expert, but it looks like the writeback of items in AIL got stuck due the IO errors, and were never completed, but I don't know what I should expect after the disk is reconnected. In my case though, with upstream kernel, I didn't get a XFS_SHUTDOWN until I tried to unmount the filesystem, which differs from this case, where xfs looks to have shutdown the filesystem after a few tries to writeback the metadata. Anyway, I can dig more into it this week, if nobody knows what is going on before I do it :) On Tue, Mar 22, 2016 at 10:03:46AM -0400, Brian Foster wrote: > On Tue, Mar 22, 2016 at 06:31:48PM +0530, Shyam Kaushik wrote: > > Hi Brian, > > > > Thanks for your quick reply. I repeated the test & trace-pipe is > > constantly filled with this: > > > > xfsaild/dm-10-3335 [003] ...2 24890.546491: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.546492: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.546493: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.596491: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.596492: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.596494: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.646497: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.646498: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.646500: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.696467: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.696468: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.696468: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.746548: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.746550: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.746550: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.796479: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.796480: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.796480: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 24890.846467: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 24890.846468: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > > > So xfsaild is spinning on this inode. It was presumably modified, logged > and flushed to the log, hence it's sitting in the AIL waiting to be > flushed to disk. xfsaild wants to push it to get it flushed to disk and > off the AIL, but it sees it is already in the flushing state as the > flush lock is held. > > It's not clear to me why the inode is not removed from the AIL, or > whether that I/O was actually submitted or aborted with an error. The > shutdown involved here most likely affects this one way or the other. > IIUC, the I/O completion should eventually release the flush lock and > remove the inode from the AIL. A complete trace log of the entire > reproducer might shed more light as to what's going on. > > Also, it sounds like you have a reliable reproducer. Does this reproduce > on a recent kernel? > > Brian > > > > > while regular activity seems to happen on other inodes/kworker threads > > > > kworker/u8:4-27691 [001] ...1 24895.811474: xfs_writepage: dev 253:10 > > ino 0x1801061 pgoff 0x29000 size 0x1aebbc offset 0 length 0 delalloc 1 > > unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811477: xfs_invalidatepage: dev > > 253:10 ino 0x1801061 pgoff 0x29000 size 0x1aebbc offset 0 length 1000 > > delalloc 1 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811478: xfs_releasepage: dev > > 253:10 ino 0x1801061 pgoff 0x29000 size 0x1aebbc offset 0 length 0 > > delalloc 0 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811482: xfs_writepage: dev 253:10 > > ino 0x4017bdf pgoff 0x29000 size 0x1aebbc offset 0 length 0 delalloc 1 > > unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811482: xfs_invalidatepage: dev > > 253:10 ino 0x4017bdf pgoff 0x29000 size 0x1aebbc offset 0 length 1000 > > delalloc 1 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811483: xfs_releasepage: dev > > 253:10 ino 0x4017bdf pgoff 0x29000 size 0x1aebbc offset 0 length 0 > > delalloc 0 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811485: xfs_writepage: dev 253:10 > > ino 0x68048c3 pgoff 0x29000 size 0x1aebbc offset 0 length 0 delalloc 1 > > unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811486: xfs_invalidatepage: dev > > 253:10 ino 0x68048c3 pgoff 0x29000 size 0x1aebbc offset 0 length 1000 > > delalloc 1 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.811486: xfs_releasepage: dev > > 253:10 ino 0x68048c3 pgoff 0x29000 size 0x1aebbc offset 0 length 0 > > delalloc 0 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.812381: xfs_writepage: dev 253:10 > > ino 0x1805e37 pgoff 0x29000 size 0x68470 offset 0 length 0 delalloc 1 > > unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.812382: xfs_invalidatepage: dev > > 253:10 ino 0x1805e37 pgoff 0x29000 size 0x68470 offset 0 length 1000 > > delalloc 1 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.812382: xfs_releasepage: dev > > 253:10 ino 0x1805e37 pgoff 0x29000 size 0x68470 offset 0 length 0 delalloc > > 0 unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.812385: xfs_writepage: dev 253:10 > > ino 0x4019c95 pgoff 0x29000 size 0x68470 offset 0 length 0 delalloc 1 > > unwritten 0 > > kworker/u8:4-27691 [001] ...1 24895.812385: xfs_invalidatepage: dev > > 253:10 ino 0x4019c95 pgoff 0x29000 size 0x68470 offset 0 length 1000 > > delalloc 1 unwritten 0 > > > > > > looks like xfsaild is not able to take lock until hung-task timeout kicks > > in > > > > xfsaild/dm-10-3335 [003] ...2 25247.649468: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.649469: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.649469: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 25247.699478: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.699516: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.699517: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > xfsaild/dm-10-3335 [003] ...2 25247.749471: xfs_ilock_nowait: dev > > 253:10 ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.749478: xfs_iunlock: dev 253:10 > > ino 0xc0 flags ILOCK_SHARED caller xfs_inode_item_push [xfs] > > xfsaild/dm-10-3335 [003] ...2 25247.749479: xfs_ail_flushing: dev > > 253:10 lip 0xffff8800a9f437b8 lsn 1/38624 type XFS_LI_INODE flags IN_AIL > > > > Please let me know how to debug this further. Thanks. > > > > --Shyam > > -----Original Message----- > > From: Brian Foster [mailto:bfoster@xxxxxxxxxx] > > Sent: 22 March 2016 17:49 > > To: Shyam Kaushik > > Cc: xfs@xxxxxxxxxxx; Alex Lyakas > > Subject: Re: XFS hung task in xfs_ail_push_all_sync() when unmounting FS > > after disk failure/recovery > > > > On Tue, Mar 22, 2016 at 04:51:39PM +0530, Shyam Kaushik wrote: > > > Hi XFS developers, > > > > > > We are seeing the following issue with XFS on kernel 3.18.19. > > > > > > We have XFS mounted over a raw disk. Disk was pulled out manually. There > > > were async writes on files that were errored like this > > > > > ... > > > > > > And XFS hit metadata & Log IO errors that it decides to shutdown: > > > > > > Mar 16 16:03:22 host0 kernel: [ 4637.351841] XFS (dm-29): metadata I/O > > > error: block 0x3a27fbd0 ("xlog_iodone") error 5 numblks 64 > > > Mar 16 16:03:22 host0 kernel: [ 4637.352820] XFS(dm-29): SHUTDOWN!!! > > > old_flags=0x0 new_flags=0x2 > > > Mar 16 16:03:22 host0 kernel: [ 4637.353187] XFS (dm-29): Log I/O Error > > > Detected. Shutting down filesystem > > ... > > > Later the drive was re-inserted back. After the drive was re-inserted, > > XFS > > > was attempted to be unmounted > > > > > > Mar 16 16:16:53 host0 controld: [2557] [ ] umount[202] > > > : umount(/sdisk/vol5b0, xfs) > > > > > > But nothing happens except for the 30-secs xfs_log_force errors that > > keeps > > > repeating > > > > > ... > > > > > > This problem doesn't happen consistently, but happens periodically with > > a > > > drive failure/recovery followed by XFS unmount. I couldn't find this > > issue > > > fixed in later kernels. Can you please suggest how I can debug this > > issue > > > further? > > > > > > > Similar problems have been reproduced due to racy/incorrect EFI/EFD > > object tracking, which are internal data structures associated with > > freeing extents. > > > > What happens if you enable tracepoints while the fs is in this hung > > unmount state? > > > > # trace-cmd start -e "xfs:*" > > # cat /sys/kernel/debug/tracing/trace_pipe > > > > Brian > > > > > Thanks! > > > > > > --Shyam > > > > > > _______________________________________________ > > > xfs mailing list > > > xfs@xxxxxxxxxxx > > > http://oss.sgi.com/mailman/listinfo/xfs > > > > _______________________________________________ > > xfs mailing list > > xfs@xxxxxxxxxxx > > http://oss.sgi.com/mailman/listinfo/xfs > > _______________________________________________ > xfs mailing list > xfs@xxxxxxxxxxx > http://oss.sgi.com/mailman/listinfo/xfs -- Carlos _______________________________________________ xfs mailing list xfs@xxxxxxxxxxx http://oss.sgi.com/mailman/listinfo/xfs
