FYI: xfstests generic/019 result panic. 4.0.0-rc5
Hi I've played with recent kernel 4.0.0-rc5 (AlViro's tree vfs.git/for-next)
And have found two issues (I do not know whenever it was fixed in xfs.git already, so I just want to let you know)
First one is Panic caused by xfstest generic/019 (disk failure simulation test) see attachment
/dev/vdb: 68/327680 files (5.9% non-contiguous), 59205/1310720 blocks
FSTESTVER: fio fio-2.2.5-2-g64666f8-dirty (Thu, 22 Jan 2015 00:57:00 +0100)
FSTESTVER: quota 52f4e0a (Mon, 5 Jan 2015 17:13:22 +0100)
FSTESTVER: xfsprogs v3.2.2 (Thu, 4 Dec 2014 07:56:44 +1100)
FSTESTVER: xfstests-bld 5a41f87 (Thu, 22 Jan 2015 17:26:16 +0300)
FSTESTVER: xfstests linux-v3.8-571-gad5c393 (Tue, 20 Jan 2015 15:37:19 +0400)
FSTESTVER: kernel 4.0.0-rc5-196354-gcf5ffe9 #18 SMP Tue Mar 31 17:23:06 MSK 2015 x86_64
FSTESTCFG: "xfs"
FSTESTSET: "generic/019"
FSTESTEXC: ""
FSTESTOPT: "aex"
MNTOPTS: ""
meta-data=/dev/vdd isize=256 agcount=4, agsize=327680 blks
= sectsz=512 attr=2, projid32bit=1
= crc=0 finobt=0
data = bsize=4096 blocks=1310720, imaxpct=25
= sunit=0 swidth=0 blks
naming =version 2 bsize=4096 ascii-ci=0 ftype=0
log =internal log bsize=4096 blocks=2560, version=2
= sectsz=512 sunit=0 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0
total used free shared buffers cached
Mem: 1974 69 1905 9 0 17
-/+ buffers/cache: 51 1923
Swap: 0 0 0
xfs_dqtrx 0 0 576 14 2 : tunables 0 0 0 : slabdata 0 0 0
xfs_dquot 0 0 720 22 4 : tunables 0 0 0 : slabdata 0 0 0
xfs_icr 0 0 144 28 1 : tunables 0 0 0 : slabdata 0 0 0
xfs_inode 0 0 1792 18 8 : tunables 0 0 0 : slabdata 0 0 0
xfs_efd_item 0 0 400 20 2 : tunables 0 0 0 : slabdata 0 0 0
xfs_buf_item 34 34 232 17 1 : tunables 0 0 0 : slabdata 2 2 0
xfs_da_state 0 0 480 17 2 : tunables 0 0 0 : slabdata 0 0 0
xfs_btree_cur 0 0 208 19 1 : tunables 0 0 0 : slabdata 0 0 0
xfs_log_ticket 0 0 184 22 1 : tunables 0 0 0 : slabdata 0 0 0
xfs_ioend 52 52 152 26 1 : tunables 0 0 0 : slabdata 2 2 0BEGIN TEST: XFS Tue Mar 31 13:30:30 UTC 2015
Device: /dev/vdd
mk2fs options:
mount options: -o block_validity
FSTYP -- xfs (debug) PLATFORM -- Linux/x86_64 kvm-xfstests 4.0.0-rc5-196354-gcf5ffe9 MKFS_OPTIONS -- -f -bsize=4096 /dev/vdc
MOUNT_OPTIONS -- /dev/vdc /vdc
generic/019 [13:30:32][ 17.619593] XFS (vdc): xlog_verify_grant_tail: space > BBTOB(tail_blocks)
[ 41.914283] XFS (vdc): metadata I/O error: block 0x503d1f ("xlog_iodone") error 5 numblks 64
[ 41.917326] XFS (vdc): xfs_bmap_check_leaf_extents: BAD after btree leaves for 6623 extents
[ 41.917376] XFS (vdc): Log I/O Error Detected. Shutting down filesystem
[ 41.917378] XFS (vdc): Please umount the filesystem and rectify the problem(s)
[ 41.918098] fsstress (3180) used greatest stack depth: 11392 bytes left
[ 41.918876] XFS (vdc): metadata I/O error: block 0x503d5f ("xlog_iodone") error 5 numblks 64
[ 41.918966] XFS (vdc): xfs_log_force: error -5 returned.
[ 41.930237] Kernel panic - not syncing: xfs_bmap_check_leaf_extents: CORRUPTED BTREE OR SOMETHING
[ 41.932793] CPU: 0 PID: 3214 Comm: fio Not tainted 4.0.0-rc5-196354-gcf5ffe9 #18
[ 41.933500] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
[ 41.933500] 00000000000019df ffff880072b4f508 ffffffff816effa5 000000000000001e
[ 41.933500] ffffffff81ac0665 ffff880072b4f588 ffffffff816efc10 ffff880000000010
[ 41.933500] ffff880072b4f598 ffff880072b4f538 ffff880072b4f598 ffff880072b4f558
[ 41.933500] Call Trace:
[ 41.933500] [<ffffffff816effa5>] dump_stack+0x48/0x5b
[ 41.933500] [<ffffffff816efc10>] panic+0xd4/0x21c
[ 41.933500] [<ffffffff8128cc45>] xfs_bmap_check_leaf_extents+0x495/0x506
[ 41.933500] [<ffffffff812906b4>] xfs_bmap_add_extent_hole_real+0x786/0x7ae
[ 41.933500] [<ffffffff812940d9>] xfs_bmapi_write+0x6da/0xbb9
[ 41.933500] [<ffffffff812cc8ed>] xfs_iomap_write_direct+0x26d/0x321
[ 41.933500] [<ffffffff812b9c0f>] __xfs_get_blocks+0x1cb/0x4a1
[ 41.933500] [<ffffffff810c3c63>] ? trace_hardirqs_on_caller+0x164/0x19b
[ 41.933500] [<ffffffff812b9ef9>] xfs_get_blocks_direct+0x14/0x16
[ 41.933500] [<ffffffff811b9627>] do_blockdev_direct_IO+0x64a/0xb83
[ 41.933500] [<ffffffff810b15a4>] ? local_clock+0x1a/0x23
[ 41.933500] [<ffffffff812b9ee5>] ? __xfs_get_blocks+0x4a1/0x4a1
[ 41.933500] [<ffffffff811b9bac>] __blockdev_direct_IO+0x4c/0x4e
[ 41.933500] [<ffffffff812b9ee5>] ? __xfs_get_blocks+0x4a1/0x4a1
[ 41.933500] [<ffffffff812ba93f>] ? xfs_setfilesize+0xf3/0xf3
[ 41.933500] [<ffffffff812b8c6a>] xfs_vm_direct_IO+0x8a/0x8c
[ 41.933500] [<ffffffff812b9ee5>] ? __xfs_get_blocks+0x4a1/0x4a1
[ 41.933500] [<ffffffff812ba93f>] ? xfs_setfilesize+0xf3/0xf3
[ 41.933500] [<ffffffff81149bb8>] generic_file_direct_write+0xc1/0x150
[ 41.933500] [<ffffffff812c49d6>] xfs_file_dio_aio_write+0x21c/0x265
[ 41.933500] [<ffffffff811c3423>] ? aio_run_iocb+0x163/0x28d
[ 41.933500] [<ffffffff8107b40b>] ? kvm_clock_read+0x1e/0x20
[ 41.933500] [<ffffffff812c57e9>] ? xfs_file_buffered_aio_write+0x1e8/0x1e8
[ 41.933500] [<ffffffff812c5865>] xfs_file_write_iter+0x7c/0x107
[ 41.933500] [<ffffffff811c3432>] aio_run_iocb+0x172/0x28d
[ 41.933500] [<ffffffff81166c39>] ? might_fault+0x42/0x92
[ 41.933500] [<ffffffff81166c39>] ? might_fault+0x42/0x92
[ 41.933500] [<ffffffff811c3899>] do_io_submit+0x34c/0x3e3
[ 41.933500] [<ffffffff811c3940>] SyS_io_submit+0x10/0x12
[ 41.933500] [<ffffffff816f5f49>] system_call_fastpath+0x12/0x17
[ 41.933500] Kernel Offset: 0x0 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffff9fffffff)
[ 41.933500] ---[ end Kernel panic - not syncing: xfs_bmap_check_leaf_extents: CORRUPTED BTREE OR SOMETHINGSecond one is lockdep's complain from splice, It looks like a false-positive one, but still.
[ 468.667585] ======================================================
[ 468.669774] [ INFO: possible circular locking dependency detected ]
[ 468.669983] 4.0.0-rc5-196355-gd50b8fe-dirty #19 Not tainted
[ 468.669983] -------------------------------------------------------
[ 468.669983] splice-fcntl/2950 is trying to acquire lock:
[ 468.669983] (&sb->s_type->i_mutex_key#11){+.+.+.}, at: [<ffffffff812c3f60>] xfs_rw_ilock+0x21/0x31
[ 468.669983]
but task is already holding lock:
[ 468.669983] (&pipe->mutex/1){+.+.+.}, at: [<ffffffff8118f93e>] pipe_lock+0x1c/0x1e
[ 468.669983]which lock already depends on the new lock.
[ 468.669983]
the existing dependency chain (in reverse order) is:
[ 468.669983]
-> #2 (&pipe->mutex/1){+.+.+.}:
[ 468.669983] [<ffffffff810c4f5c>] lock_acquire+0xd7/0x112
[ 468.669983] [<ffffffff816f1f88>] mutex_lock_nested+0x63/0x5ab
[ 468.669983] [<ffffffff8118f93e>] pipe_lock+0x1c/0x1e
[ 468.669983] [<ffffffff811aff79>] splice_to_pipe+0x2d/0x203
[ 468.669983] [<ffffffff811b0f82>] __generic_file_splice_read+0x41f/0x440
[ 468.669983] [<ffffffff811b0fec>] generic_file_splice_read+0x49/0x73
[ 468.669983] [<ffffffff812c50ac>] xfs_file_splice_read+0xfb/0x144
[ 468.669983] [<ffffffff811af6a4>] do_splice_to+0x74/0x81
[ 468.669983] [<ffffffff811b0751>] SyS_splice+0x4b6/0x55e
[ 468.669983] [<ffffffff816f5f09>] system_call_fastpath+0x12/0x17
[ 468.669983]
-> #1 (&(&ip->i_iolock)->mr_lock){++++++}:
[ 468.669983] [<ffffffff810c4f5c>] lock_acquire+0xd7/0x112
[ 468.669983] [<ffffffff810bf5d0>] down_write_nested+0x4b/0xad
[ 468.669983] [<ffffffff812d1c5f>] xfs_ilock+0xdb/0x14b
[ 468.669983] [<ffffffff812c3f6b>] xfs_rw_ilock+0x2c/0x31
[ 468.669983] [<ffffffff812c561e>] xfs_file_buffered_aio_write+0x59/0x1e8
[ 468.669983] [<ffffffff812c5830>] xfs_file_write_iter+0x83/0x107
[ 468.669983] [<ffffffff811882e7>] new_sync_write+0x64/0x82
[ 468.669983] [<ffffffff8118956b>] vfs_write+0xb5/0x14d
[ 468.669983] [<ffffffff811896eb>] SyS_write+0x5c/0x8c
[ 468.669983] [<ffffffff816f5f09>] system_call_fastpath+0x12/0x17
[ 468.669983]
-> #0 (&sb->s_type->i_mutex_key#11){+.+.+.}:
[ 468.669983] [<ffffffff810c4b60>] __lock_acquire+0xbd6/0xefb
[ 468.669983] [<ffffffff810c4f5c>] lock_acquire+0xd7/0x112
[ 468.669983] [<ffffffff816f1f88>] mutex_lock_nested+0x63/0x5ab
[ 468.669983] [<ffffffff812c3f60>] xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff812c561e>] xfs_file_buffered_aio_write+0x59/0x1e8
[ 468.669983] [<ffffffff812c5830>] xfs_file_write_iter+0x83/0x107
[ 468.669983] [<ffffffff81187e4c>] vfs_iter_write+0x4c/0x6b
[ 468.669983] [<ffffffff811afdfb>] iter_file_splice_write+0x230/0x33a
[ 468.669983] [<ffffffff811b06a4>] SyS_splice+0x409/0x55e
[ 468.669983] [<ffffffff816f5f09>] system_call_fastpath+0x12/0x17
[ 468.669983]other info that might help us debug this[ 604.889687] serial8250: too much work for irq4 :
[ 468.669983] Chain exists of: &sb->s_type->i_mutex_key#11 --> &(&ip->i_iolock)->mr_lock --> &pipe->mutex/1
[ 468.669983] Possible unsafe locking scenario:
[ 468.669983] CPU0 CPU1 [ 468.669983] ---- ---- [ 468.669983] lock(&pipe->mutex/1); [ 468.669983] lock(&(&ip->i_iolock)->mr_lock); [ 468.669983] lock(&pipe->mutex/1); [ 468.669983] lock(&sb->s_type->i_mutex_key#11); [ 468.669983] *** DEADLOCK ***
[ 468.669983] 2 locks held by splice-fcntl/2950:
[ 468.669983] #0: (sb_writers#9){.+.+.+}, at: [<ffffffff811b0671>] SyS_splice+0x3d6/0x55e
[ 468.669983] #1: (&pipe->mutex/1){+.+.+.}, at: [<ffffffff8118f93e>] pipe_lock+0x1c/0x1e
[ 468.669983]
stack backtrace:
[ 468.669983] CPU: 1 PID: 2950 Comm: splice-fcntl Not tainted 4.0.0-rc5-196355-gd50b8fe-dirty #19
[ 468.669983] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5-0-ge51488c-20140602_164612-nilsson.home.kraxel.org 04/01/2014
[ 468.669983] ffffffff8247a700 ffff88006b03fa18 ffffffff816eff65 0000000000000001
[ 468.669983] ffffffff824924b0 ffff88006b03fa68 ffffffff810c2fae ffff88006b03fa68
[ 468.669983] ffffffff822781f0 ffff88007c062de0 ffff88007c0624b0 ffff88007c062de0
[ 468.669983] Call Trace:
[ 468.669983] [<ffffffff816eff65>] dump_stack+0x48/0x5b
[ 468.669983] [<ffffffff810c2fae>] print_circular_bug+0x1f8/0x209
[ 468.669983] [<ffffffff810c4b60>] __lock_acquire+0xbd6/0xefb
[ 468.669983] [<ffffffff812c3f60>] ? xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff810c4f5c>] lock_acquire+0xd7/0x112
[ 468.669983] [<ffffffff812c3f60>] ? xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff816f1f88>] mutex_lock_nested+0x63/0x5ab
[ 468.669983] [<ffffffff812c3f60>] ? xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff812c3f60>] ? xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff810c3909>] ? mark_held_locks+0x59/0x77
[ 468.669983] [<ffffffff81183919>] ? slab_free_hook+0x7a/0x9a
[ 468.669983] [<ffffffff8107b40b>] ? kvm_clock_read+0x1e/0x20
[ 468.669983] [<ffffffff812c3f60>] xfs_rw_ilock+0x21/0x31
[ 468.669983] [<ffffffff812c561e>] xfs_file_buffered_aio_write+0x59/0x1e8
[ 468.669983] [<ffffffff810c3c63>] ? trace_hardirqs_on_caller+0x164/0x19b
[ 468.669983] [<ffffffff810c3ca7>] ? trace_hardirqs_on+0xd/0xf
[ 468.669983] [<ffffffff8118f93e>] ? pipe_lock+0x1c/0x1e
[ 468.669983] [<ffffffff812c5830>] xfs_file_write_iter+0x83/0x107
[ 468.669983] [<ffffffff81187e4c>] vfs_iter_write+0x4c/0x6b
[ 468.669983] [<ffffffff811afdfb>] iter_file_splice_write+0x230/0x33a
[ 468.669983] [<ffffffff811b06a4>] SyS_splice+0x409/0x55e
[ 468.669983] [<ffffffff811a1167>] ? __fd_install+0x9f/0xab
[ 468.669983] [<ffffffff810c3c63>] ? trace_hardirqs_on_caller+0x164/0x19b
[ 468.669983] [<ffffffff816f5f09>] system_call_fastpath+0x12/0x17_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 7 lines · Dmitry Monakhov
Hi I've played with recent kernel 4.0.0-rc5 (AlViro's tree vfs.git/for-next)
And have found two issues (I do not know whenever it was fixed in xfs.git already, so I just want to let you know)
First one is Panic caused by xfstest generic/019 (disk failure simulation test) see attachment
.....
Quoted 3 lines
generic/019 [13:30:32][ 17.619593] XFS (vdc):
xlog_verify_grant_tail: space >BBTOB(tail_blocks)[ 41.914283] XFS (vdc): metadata I/O error: block 0x503d1f ("xlog_iodone") error 5 numblks 64
So the test has shut down the filesystem via device pull...
Quoted 1 line
[ 41.917326] XFS (vdc): xfs_bmap_check_leaf_extents: BAD after btree leaves for 6623 extents
in the middle of a bmbt update operation, which aborted in an inconsistent state in memory due to shutdown...
Quoted 6 lines
[ 41.917376] XFS (vdc): Log I/O Error Detected. Shutting down filesystem
[ 41.917378] XFS (vdc): Please umount the filesystem and rectify the problem(s)
[ 41.918098] fsstress (3180) used greatest stack depth: 11392 bytes left
[ 41.918876] XFS (vdc): metadata I/O error: block 0x503d5f ("xlog_iodone") error 5 numblks 64
[ 41.918966] XFS (vdc): xfs_log_force: error -5 returned.
[ 41.930237] Kernel panic - not syncing: xfs_bmap_check_leaf_extents: CORRUPTED BTREE OR SOMETHINGAnd debug code detected that inconsistent in-memory state, and threw out the panic. Production machines won't run this code (it's CONFIG_XFS_DEBUG=y specific) so they'll just shut down normally.
Quoted 1 line
Second one is lockdep's complain from splice, It looks like a false-positive one, but still.
No, that's a real one. splice has inverted locks and we've been able to deadlock it since, well, forever. The recent rework that Al Viro did removed the old lock inversion problem, and created a new one w.r.t. to the pipe_lock and filesystem locks. I've reported this to him previously, but I've never got any response about it...
Thanks for the reports, though, Dmitry.
Cheers,
Dave.
Signature · 7 lines
Dave Chinner [email protected] _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs