From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mo-p00-ob.rzone.de ([81.169.146.161]:21614 "EHLO mo-p00-ob.rzone.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752872Ab2LLPMV (ORCPT ); Wed, 12 Dec 2012 10:12:21 -0500 Received: from [172.24.1.80] (yian-ho01.nir.cronon.net [192.166.201.94]) by smtp.strato.de (josoe mo15) (RZmta 31.9 AUTH) with ESMTPA id U05d7eoBCF7qEf for ; Wed, 12 Dec 2012 16:12:18 +0100 (CET) Message-ID: <50C89ED2.1020101@giantdisaster.de> Date: Wed, 12 Dec 2012 16:12:18 +0100 From: Stefan Behrens MIME-Version: 1.0 To: Linux Btrfs List Subject: [BUG] btrfs-next issues detected with xfstest, part #1 Content-Type: text/plain; charset=ISO-8859-1 Sender: linux-btrfs-owner@vger.kernel.org List-ID: Make sure you have a wide terminal to read the following logs. The current btrfs-next was taken to run the xfstest suite. export TEST_DEV=/dev/sdg export TEST_DIR=/mnt3 export SCRATCH_DEV=/dev/sdi export SCRATCH_MNT=/mnt2 cd ~/git/xfs/cmds/xfstests grep check_int common.rc gives this result: export MOUNT_OPTIONS="-o check_int,compress=lzo,autodefrag,space_cache" ./check 001-299 [010] Dec 12 11:41:04 qvarne root: run xfstest 010 ========================================================= [ INFO: possible irq lock inversion dependency detected ] 3.7.0+ #106 Not tainted --------------------------------------------------------- dbtest/8502 just changed the state of lock: (&(&root->log_extents_lock[1])->rlock){+.+...}, at: [] log_one_extent.isra.25+0x34e/0x710 [btrfs] but this lock was taken by another, SOFTIRQ-safe lock in the past: (&(&t->lock)->rlock){..-...} and interrupts could create inverse lock ordering between them. other info that might help us debug this: Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&(&root->log_extents_lock[1])->rlock); local_irq_disable(); lock(&(&t->lock)->rlock); lock(&(&root->log_extents_lock[1])->rlock); lock(&(&t->lock)->rlock); *** DEADLOCK *** 3 locks held by dbtest/8502: #0: (&sb->s_type->i_mutex_key#11){+.+.+.}, at: [] btrfs_sync_file+0xad/0x2c0 [btrfs] #1: (sb_internal){.+.+..}, at: [] start_transaction+0x2a6/0x470 [btrfs] #2: (&ei->log_mutex){+.+...}, at: [] btrfs_log_inode+0x116/0x8e0 [btrfs] the shortest dependencies between 2nd lock and 1st lock: -> (&(&t->lock)->rlock){..-...} ops: 90123 { IN-SOFTIRQ-W at: [] __lock_acquire+0x5f5/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock_irqsave+0x52/0x90 [] btrfs_dec_test_ordered_pending+0x3d/0x1c0 [btrfs] [] btrfs_writepage_end_io_hook+0x72/0x1a0 [btrfs] [] end_extent_writepage+0x42/0x70 [btrfs] [] end_bio_extent_writepage+0x3b/0xa0 [btrfs] [] bio_endio+0x18/0x30 [] btrfs_end_bio+0xfd/0x190 [btrfs] [] bio_endio+0x18/0x30 [] req_bio_endio.isra.52+0x83/0xc0 [] blk_update_request+0x111/0x540 [] blk_update_bidi_request+0x2c/0x90 [] blk_end_bidi_request+0x27/0x70 [] blk_end_request+0xb/0x10 [] scsi_io_completion+0xaa/0x680 [] scsi_finish_command+0xbc/0x110 [] scsi_softirq_done+0x12f/0x150 [] blk_done_softirq+0x73/0x90 [] __do_softirq+0xcd/0x290 [] call_softirq+0x1c/0x30 [] do_softirq+0x85/0xc0 [] irq_exit+0x9e/0xc0 [] do_IRQ+0x5e/0xd0 [] ret_from_intr+0x0/0x13 [] cpuidle_enter+0x1a/0x20 [] cpuidle_idle_call+0xbe/0x320 [] cpu_idle+0x85/0xd0 [] start_secondary+0x220/0x222 INITIAL USE at: [] __lock_acquire+0x31a/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock_irq+0x46/0x80 [] btrfs_lookup_ordered_extent+0x2d/0xe0 [btrfs] [] __extent_read_full_page+0xcf/0x660 [btrfs] [] read_extent_buffer_pages+0x263/0x360 [btrfs] [] btree_read_extent_buffer_pages.constprop.119+0xb1/0x110 [btrfs] [] read_tree_block+0x35/0x50 [btrfs] [] open_ctree+0x1292/0x1ee0 [btrfs] [] btrfs_mount+0x5a6/0x680 [btrfs] [] mount_fs+0x3e/0x1b0 [] vfs_kern_mount+0x63/0x100 [] do_kern_mount+0x4f/0x100 [] do_mount+0x19c/0x880 [] sys_mount+0x8b/0xe0 [] system_call_fastpath+0x16/0x1b } ... key at: [] __key.35139+0x0/0xfffffffffffea68e [btrfs] ... acquired at: [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_log_inode+0x125/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b -> (&(&root->log_extents_lock[1])->rlock){+.+...} ops: 6 { HARDIRQ-ON-W at: [] __lock_acquire+0x623/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] log_one_extent.isra.25+0x34e/0x710 [btrfs] [] btrfs_log_inode+0x7ee/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b SOFTIRQ-ON-W at: [] __lock_acquire+0x652/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] log_one_extent.isra.25+0x34e/0x710 [btrfs] [] btrfs_log_inode+0x7ee/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b INITIAL USE at: [] __lock_acquire+0x31a/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_log_inode+0x125/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b } ... key at: [] __key.37236+0x0/0xfffffffffffea896 [btrfs] ... acquired at: [] check_usage_backwards+0x110/0x150 [] mark_lock+0x198/0x2f0 [] __lock_acquire+0x652/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] log_one_extent.isra.25+0x34e/0x710 [btrfs] [] btrfs_log_inode+0x7ee/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b stack backtrace: Pid: 8502, comm: dbtest Not tainted 3.7.0+ #106 Call Trace: [] print_irq_inversion_bug.part.40+0x1e8/0x1f0 [] check_usage_backwards+0x110/0x150 [] mark_lock+0x198/0x2f0 [] ? check_usage_forwards+0x150/0x150 [] __lock_acquire+0x652/0x1c00 [] ? sched_clock_cpu+0xc5/0x120 [] ? local_clock+0x4b/0x60 [] ? lock_release_holdtime.part.25+0x15/0x190 [] ? release_extent_buffer.isra.25+0xb1/0xe0 [btrfs] [] ? log_one_extent.isra.25+0x34e/0x710 [btrfs] [] lock_acquire+0x95/0x150 [] ? log_one_extent.isra.25+0x34e/0x710 [btrfs] [] ? _raw_spin_unlock+0x26/0x40 [] ? release_extent_buffer.isra.25+0xb1/0xe0 [btrfs] [] _raw_spin_lock+0x40/0x80 [] ? log_one_extent.isra.25+0x34e/0x710 [btrfs] [] log_one_extent.isra.25+0x34e/0x710 [btrfs] [] ? trace_hardirqs_off+0xd/0x10 [] ? lock_release_holdtime.part.25+0x15/0x190 [] ? btrfs_log_inode+0x7d0/0x8e0 [btrfs] [] btrfs_log_inode+0x7ee/0x8e0 [btrfs] [] ? mark_held_locks+0x7e/0x140 [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] ? sysret_check+0x1b/0x56 [] do_fsync+0x58/0x80 [] ? trace_hardirqs_on_thunk+0x3a/0x3f [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b [013, 068, 071, 091, 218...] WARNING: at fs/btrfs/inode.c:7755 btrfs_destroy_inode+0x236/0x2d0 [btrfs]() WARNING: at fs/btrfs/inode.c:7756 btrfs_destroy_inode+0x2be/0x2d0 [btrfs]() WARNING: at fs/btrfs/inode.c:7758 btrfs_destroy_inode+0x292/0x2d0 [btrfs]() [071] Dec 12 11:56:55 qvarne root: run xfstest 071 ------------[ cut here ]------------ WARNING: at fs/btrfs/inode.c:7755 btrfs_destroy_inode+0x236/0x2d0 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_destroy_inode+0x236/0x2d0 [btrfs] [] destroy_inode+0x37/0x60 [] evict+0x11d/0x1b0 [] iput+0x105/0x190 [] btrfs_run_delayed_iputs+0xd2/0x100 [btrfs] [] btrfs_commit_super+0x27/0x100 [btrfs] [] close_ctree+0x2f0/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7af ]--- ------------[ cut here ]------------ WARNING: at fs/btrfs/inode.c:7756 btrfs_destroy_inode+0x2be/0x2d0 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_destroy_inode+0x2be/0x2d0 [btrfs] [] destroy_inode+0x37/0x60 [] evict+0x11d/0x1b0 [] iput+0x105/0x190 [] btrfs_run_delayed_iputs+0xd2/0x100 [btrfs] [] btrfs_commit_super+0x27/0x100 [btrfs] [] close_ctree+0x2f0/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b0 ]--- ------------[ cut here ]------------ WARNING: at fs/btrfs/inode.c:7758 btrfs_destroy_inode+0x292/0x2d0 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_destroy_inode+0x292/0x2d0 [btrfs] [] destroy_inode+0x37/0x60 [] evict+0x11d/0x1b0 [] iput+0x105/0x190 [] btrfs_run_delayed_iputs+0xd2/0x100 [btrfs] [] btrfs_commit_super+0x27/0x100 [btrfs] [] close_ctree+0x2f0/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b1 ]--- ------------[ cut here ]------------ WARNING: at fs/btrfs/extent-tree.c:4351 btrfs_free_block_groups+0x2b5/0x360 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_free_block_groups+0x2b5/0x360 [btrfs] [] close_ctree+0x1bf/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b2 ]--- ------------[ cut here ]------------ WARNING: at fs/btrfs/extent-tree.c:4352 btrfs_free_block_groups+0x34f/0x360 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_free_block_groups+0x34f/0x360 [btrfs] [] close_ctree+0x1bf/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b3 ]--- ------------[ cut here ]------------ WARNING: at fs/btrfs/extent-tree.c:7650 btrfs_free_block_groups+0x246/0x360 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_free_block_groups+0x246/0x360 [btrfs] [] close_ctree+0x1bf/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b4 ]--- space_info 1 has 1071878144 free, is not full space_info total=1082130432, used=10252288, pinned=0, reserved=0, may_use=524288, readonly=0 ------------[ cut here ]------------ WARNING: at fs/btrfs/extent-tree.c:7650 btrfs_free_block_groups+0x246/0x360 [btrfs]() Hardware name: X8SIL Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class Pid: 20909, comm: umount Tainted: G W 3.7.0+ #106 Call Trace: [] warn_slowpath_common+0x7a/0xb0 [] warn_slowpath_null+0x15/0x20 [] btrfs_free_block_groups+0x246/0x360 [btrfs] [] close_ctree+0x1bf/0x330 [btrfs] [] ? evict_inodes+0x10c/0x120 [] btrfs_put_super+0x14/0x20 [btrfs] [] generic_shutdown_super+0x5d/0xf0 [] kill_anon_super+0x11/0x20 [] btrfs_kill_super+0x15/0x90 [btrfs] [] ? deactivate_super+0x41/0x70 [] deactivate_locked_super+0x3d/0x70 [] deactivate_super+0x49/0x70 [] mntput_no_expire+0x101/0x160 [] sys_umount+0x69/0x3a0 [] system_call_fastpath+0x16/0x1b ---[ end trace 49e8450e20d1e7b5 ]--- space_info 4 has 1073610752 free, is not full space_info total=1082130432, used=65536, pinned=0, reserved=0, may_use=393216, readonly=8454144 [075] Dec 12 11:59:50 qvarne root: run xfstest 075 device fsid 791bdd4f-0db8-43ee-af10-29e62fc1b27c devid 1 transid 1772 /dev/sdg btrfs: enabling check integrity btrfs: use lzo compression btrfs: enabling auto defrag btrfs: disk space caching is enabled BUG: soft lockup - CPU#3 stuck for 23s! [fsx:21976] Modules linked in: btrfs raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 mpt2sas scsi_transport_sas raid_class irq event stamp: 0 hardirqs last enabled at (0): [< (null)>] (null) hardirqs last disabled at (0): [] copy_process+0x5ce/0x16b0 softirqs last enabled at (0): [] copy_process+0x5ce/0x16b0 softirqs last disabled at (0): [< (null)>] (null) CPU 3 Pid: 21976, comm: fsx Tainted: G W 3.7.0+ #106 Supermicro X8SIL/X8SIL RIP: 0010:[] [] eb_cmp+0x10/0x30 [btrfs] RSP: 0018:ffff88023483dc80 EFLAGS: 00000246 RAX: 0000000001c96000 RBX: 0000000000000000 RCX: 0000000000000000 RDX: ffff880230fd9128 RSI: ffff880230fd9128 RDI: 0000000000000000 RBP: ffff88023483dda8 R08: ffff880212b931f0 R09: ffff88023483de58 R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff8195ed1c R13: ffffffff81120aa0 R14: ffff88023483dbe8 R15: 0000000000000000 FS: 00007fa32e3a3700(0000) GS:ffff880236c00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 00007fa32e31f000 CR3: 0000000233dd1000 CR4: 00000000000007e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process fsx (pid: 21976, threadinfo ffff88023483c000, task ffff88020ea5c4e0) Stack: ffffffff81445f7d ffff88023483dcc8 ffff88023483de58 0000000100000282 0000000000000000 ffff88023483dcc8 ffff88023483dcc0 0000000000000000 0000000000000000 ffff880230fd9128 0000000000000000 0000000000000000 Call Trace: [] ? list_sort+0x1bd/0x370 [] ? mutex_lock_nested+0x299/0x360 [] btrfs_sync_eb_list+0x5b/0x120 [btrfs] [] btrfs_sync_log+0x41c/0x6c0 [btrfs] [] btrfs_sync_file+0x226/0x2c0 [btrfs] [] vfs_fsync+0x26/0x30 [] sys_msync+0x13c/0x1c0 [] system_call_fastpath+0x16/0x1b Code: 89 9c 24 90 00 00 00 48 8b 5d e8 4c 8b 65 f0 c9 c3 66 2e 0f 1f 84 00 00 00 00 00 48 8b 82 58 ff ff ff 31 c9 48 39 86 58 ff ff ff <55> b8 ff ff ff ff 48 89 e5 0f 97 c1 0f 43 c1 5d c3 66 66 66 66 BUG: soft lockup - CPU#3 stuck for 23s! [fsx:21976] At this point the box needed an 'impitool power reset' from remote to go on. ./check 076-299 [076] device fsid 8f255b0b-d145-4a20-8fb0-812ee4b31e87 devid 1 transid 4 /dev/sdi btrfs: enabling check integrity btrfs: use lzo compression btrfs: enabling auto defrag btrfs: disk space caching is enabled Btrfs detected SSD devices, enabling SSD mode ====================================================== [ INFO: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected ] 3.7.0+ #106 Not tainted ------------------------------------------------------ fsstress/4820 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: (&(&root->log_extents_lock[0])->rlock){+.+...}, at: [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] and this task is already holding: (&(&t->lock)->rlock){..-...}, at: [] btrfs_get_logged_extents+0x24/0xd0 [btrfs] which would create a new lock dependency: (&(&t->lock)->rlock){..-...} -> (&(&root->log_extents_lock[0])->rlock){+.+...} but this new dependency connects a SOFTIRQ-irq-safe lock: (&(&t->lock)->rlock){..-...} ... which became SOFTIRQ-irq-safe at: [] __lock_acquire+0x5f5/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock_irqsave+0x52/0x90 [] btrfs_dec_test_ordered_pending+0x3d/0x1c0 [btrfs] [] btrfs_writepage_end_io_hook+0x72/0x1a0 [btrfs] [] end_extent_writepage+0x42/0x70 [btrfs] [] end_bio_extent_writepage+0x3b/0xa0 [btrfs] [] bio_endio+0x18/0x30 [] btrfs_end_bio+0xfd/0x190 [btrfs] [] bio_endio+0x18/0x30 [] req_bio_endio.isra.52+0x83/0xc0 [] blk_update_request+0x111/0x540 [] blk_update_bidi_request+0x2c/0x90 [] blk_end_bidi_request+0x27/0x70 [] blk_end_request+0xb/0x10 [] scsi_io_completion+0xaa/0x680 [] scsi_finish_command+0xbc/0x110 [] scsi_softirq_done+0x12f/0x150 [] blk_done_softirq+0x73/0x90 [] __do_softirq+0xcd/0x290 [] call_softirq+0x1c/0x30 [] do_softirq+0x85/0xc0 [] irq_exit+0x9e/0xc0 [] do_IRQ+0x5e/0xd0 [] ret_from_intr+0x0/0x13 [] cpuidle_enter+0x1a/0x20 [] cpuidle_idle_call+0xbe/0x320 [] cpu_idle+0x85/0xd0 [] start_secondary+0x220/0x222 to a SOFTIRQ-irq-unsafe lock: (&(&root->log_extents_lock[0])->rlock){+.+...} ... which became SOFTIRQ-irq-unsafe at: ... [] __lock_acquire+0x652/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_wait_logged_extents+0x4a/0x130 [btrfs] [] btrfs_sync_log+0x5c4/0x6c0 [btrfs] [] btrfs_sync_file+0x226/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b other info that might help us debug this: Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&(&root->log_extents_lock[0])->rlock); local_irq_disable(); lock(&(&t->lock)->rlock); lock(&(&root->log_extents_lock[0])->rlock); lock(&(&t->lock)->rlock); *** DEADLOCK *** 4 locks held by fsstress/4820: #0: (&sb->s_type->i_mutex_key#11){+.+.+.}, at: [] btrfs_sync_file+0xad/0x2c0 [btrfs] #1: (sb_internal){.+.+..}, at: [] start_transaction+0x2a6/0x470 [btrfs] #2: (&ei->log_mutex){+.+...}, at: [] btrfs_log_inode+0x116/0x8e0 [btrfs] #3: (&(&t->lock)->rlock){..-...}, at: [] btrfs_get_logged_extents+0x24/0xd0 [btrfs] the dependencies between SOFTIRQ-irq-safe lock and the holding lock: -> (&(&t->lock)->rlock){..-...} ops: 3800 { IN-SOFTIRQ-W at: [] __lock_acquire+0x5f5/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock_irqsave+0x52/0x90 [] btrfs_dec_test_ordered_pending+0x3d/0x1c0 [btrfs] [] btrfs_writepage_end_io_hook+0x72/0x1a0 [btrfs] [] end_extent_writepage+0x42/0x70 [btrfs] [] end_bio_extent_writepage+0x3b/0xa0 [btrfs] [] bio_endio+0x18/0x30 [] btrfs_end_bio+0xfd/0x190 [btrfs] [] bio_endio+0x18/0x30 [] req_bio_endio.isra.52+0x83/0xc0 [] blk_update_request+0x111/0x540 [] blk_update_bidi_request+0x2c/0x90 [] blk_end_bidi_request+0x27/0x70 [] blk_end_request+0xb/0x10 [] scsi_io_completion+0xaa/0x680 [] scsi_finish_command+0xbc/0x110 [] scsi_softirq_done+0x12f/0x150 [] blk_done_softirq+0x73/0x90 [] __do_softirq+0xcd/0x290 [] call_softirq+0x1c/0x30 [] do_softirq+0x85/0xc0 [] irq_exit+0x9e/0xc0 [] do_IRQ+0x5e/0xd0 [] ret_from_intr+0x0/0x13 [] cpuidle_enter+0x1a/0x20 [] cpuidle_idle_call+0xbe/0x320 [] cpu_idle+0x85/0xd0 [] start_secondary+0x220/0x222 INITIAL USE at: [] __lock_acquire+0x31a/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock_irq+0x46/0x80 [] btrfs_lookup_ordered_extent+0x2d/0xe0 [btrfs] [] __extent_read_full_page+0xcf/0x660 [btrfs] [] read_extent_buffer_pages+0x263/0x360 [btrfs] [] btree_read_extent_buffer_pages.constprop.119+0xb1/0x110 [btrfs] [] read_tree_block+0x35/0x50 [btrfs] [] open_ctree+0x1292/0x1ee0 [btrfs] [] btrfs_mount+0x5a6/0x680 [btrfs] [] mount_fs+0x3e/0x1b0 [] vfs_kern_mount+0x63/0x100 [] do_kern_mount+0x4f/0x100 [] do_mount+0x19c/0x880 [] sys_mount+0x8b/0xe0 [] system_call_fastpath+0x16/0x1b } ... key at: [] __key.35139+0x0/0xfffffffffffea68e [btrfs] ... acquired at: [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0x106b/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_log_inode+0x125/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fdatasync+0xe/0x20 [] system_call_fastpath+0x16/0x1b the dependencies between the lock to be acquired and SOFTIRQ-irq-unsafe lock: -> (&(&root->log_extents_lock[0])->rlock){+.+...} ops: 3 { HARDIRQ-ON-W at: [] __lock_acquire+0x623/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_wait_logged_extents+0x4a/0x130 [btrfs] [] btrfs_sync_log+0x5c4/0x6c0 [btrfs] [] btrfs_sync_file+0x226/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b SOFTIRQ-ON-W at: [] __lock_acquire+0x652/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_wait_logged_extents+0x4a/0x130 [btrfs] [] btrfs_sync_log+0x5c4/0x6c0 [btrfs] [] btrfs_sync_file+0x226/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b INITIAL USE at: [] __lock_acquire+0x31a/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_wait_logged_extents+0x4a/0x130 [btrfs] [] btrfs_sync_log+0x5c4/0x6c0 [btrfs] [] btrfs_sync_file+0x226/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fsync+0xb/0x10 [] system_call_fastpath+0x16/0x1b } ... key at: [] __key.37235+0x0/0xfffffffffffea89e [btrfs] ... acquired at: [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0x106b/0x1c00 [] lock_acquire+0x95/0x150 [] _raw_spin_lock+0x40/0x80 [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_log_inode+0x125/0x8e0 [btrfs] [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] do_fsync+0x58/0x80 [] sys_fdatasync+0xe/0x20 [] system_call_fastpath+0x16/0x1b stack backtrace: Pid: 4820, comm: fsstress Not tainted 3.7.0+ #106 Call Trace: [] check_usage+0x4c2/0x4d0 [] ? trace_hardirqs_off+0xd/0x10 [] ? sched_clock_cpu+0xc5/0x120 [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0x106b/0x1c00 [] ? trace_hardirqs_off+0xd/0x10 [] ? mark_held_locks+0x7e/0x140 [] ? _raw_write_unlock_irqrestore+0x3a/0x70 [] ? btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] lock_acquire+0x95/0x150 [] ? btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] ? btrfs_log_inode+0x116/0x8e0 [btrfs] [] _raw_spin_lock+0x40/0x80 [] ? btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_get_logged_extents+0x80/0xd0 [btrfs] [] btrfs_log_inode+0x125/0x8e0 [btrfs] [] ? mark_held_locks+0x7e/0x140 [] ? trace_hardirqs_on+0xd/0x10 [] btrfs_log_inode_parent+0x18a/0x450 [btrfs] [] btrfs_log_dentry_safe+0x3f/0x60 [btrfs] [] btrfs_sync_file+0x147/0x2c0 [btrfs] [] ? sysret_check+0x1b/0x56 [] do_fsync+0x58/0x80 [] ? trace_hardirqs_on_thunk+0x3a/0x3f [] sys_fdatasync+0xe/0x20 [] system_call_fastpath+0x16/0x1b [tty output of 076 and 077] 076 50s ... [failed, exit status 1] - output mismatch (see 076.out.bad) --- 076.out 2011-12-05 16:26:15.000000000 +0100 +++ 076.out.bad 2012-12-12 12:47:54.000000000 +0100 @@ -1,5 +1,5 @@ QA output created by 076 *** init fs *** test concurrent block/fs access -*** done +_check_btrfs_filesystem: filesystem on /dev/sdi is inconsistent (see 076.full) *** unmount 077 15s ... [failed, exit status 1] - output mismatch (see 077.out.bad) --- 077.out 2011-12-05 16:26:15.000000000 +0100 +++ 077.out.bad 2012-12-12 12:48:00.000000000 +0100 @@ -3,5 +3,5 @@ *** set default ACL *** populate filesystem, pass #1 *** populate filesystem, pass #2 -*** all done +_check_btrfs_filesystem: filesystem on /dev/sdi is inconsistent (see 077.full) *** unmount root@qvarne:~/git/xfs/cmds/xfstests# less 076.full *** MKFS *** seed = 1355780049 _check_btrfs_filesystem: filesystem on /dev/sdi is inconsistent *** fsck.btrfs output *** Check tree block failed, want=20975616, have=8947527917593559565 Check tree block failed, want=20975616, have=8947527917593559565 Check tree block failed, want=20975616, have=8947527917593559565 read block failed check_tree_block Couldn't read chunk root *** end fsck.btrfs output root@qvarne:~/git/xfs/cmds/xfstests# less 077.full cp: cannot create regular file `/mnt2/subdir/modules/3.6.5+/modules.alias.bin': No space left on device cp: cannot create regular file `/mnt2/subdir/modules/3.6.5+/modules.builtin.bin': No space left on device cp: cannot create symbolic link `/mnt2/subdir/modules/3.6.5+/source': No space left on device ... _check_btrfs_filesystem: filesystem on /dev/sdi is inconsistent *** fsck.btrfs output *** parent transid verify failed on 131072 wanted 5 found 2 parent transid verify failed on 131072 wanted 5 found 2 Ignoring transid failure Couldn't map the block 39190528 Couldn't read tree root Critical roots corrupted, unable to fsck the FS *** end fsck.btrfs output