xfs
[Top] [All Lists]

FYI: xfstests generic/019 result panic. 4.0.0-rc5

To: xfs@xxxxxxxxxxx, Dave Chinner <david@xxxxxxxxxxxxx>
Subject: FYI: xfstests generic/019 result panic. 4.0.0-rc5
From: Dmitry Monakhov <dmonakhov@xxxxxxxxxx>
Date: Thu, 02 Apr 2015 14:40:26 +0300
Delivered-to: xfs@xxxxxxxxxxx
Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=sender:from:to:subject:user-agent:date:message-id:mime-version :content-type; bh=3xCC0WgG9OWGmdq+F3AFJjW9XezfT7GJeR5xxoDvUQ8=; b=dq2uZ/YjyoDetQBz1p09dMtz964WDFg0qLYjVNXPyVDxtLWM9yyLNbvZXT7I9CT1nr pEkj81oumMiiBOKR6dNGEOE3j4wS0FLhbOy//W/Ai7BO21CysQ/y+uF1hO8LFEPcYrFZ SU/Muj/9gXQwJZJh7K9zQxMn1TpUoN6lXpjhnlwXdl5NjINQ6viY4EM9IGZ1MrT3FF4j C6XqFR45WSgUC148T4iSfCtMT6jWo2KBzW8k1n5WI/3e7OI0egE3mfHuCeTXubIwWhay c4oHKMUfBMTTzxgnQSDZeKkcLUda/xaPnifUDkhZIZ4acO8wqPtT4I52TBc4JCEvjOpC NHAA==
Sender: Dmitry Monakhov <rjevskiy@xxxxxxxxx>
User-agent: Notmuch/0.18.1 (http://notmuchmail.org) Emacs/24.4.1 (x86_64-pc-linux-gnu)
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

Attachment: signature.asc
Description: PGP signature

/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      0
BEGIN 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 SOMETHING
Second 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
<Prev in Thread] Current Thread [Next in Thread>