From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from magic.merlins.org ([209.81.13.136]:33183 "EHLO mail1.merlins.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751612AbaJEU3p (ORCPT ); Sun, 5 Oct 2014 16:29:45 -0400 Received: from svh-gw.merlins.org ([173.11.111.145]:52397 helo=legolas.merlins.org) by mail1.merlins.org with esmtpsa (Cipher TLS1.2:DHE_RSA_AES_128_CBC_SHA1:128) (Exim 4.80 #2) id 1XasQw-0005bV-Qg by authid with srv_auth_plain for ; Sun, 05 Oct 2014 13:29:44 -0700 Received: from merlin by legolas.merlins.org with local (Exim 4.80) (envelope-from ) id 1XasQz-00084g-R7 for linux-btrfs@vger.kernel.org; Sun, 05 Oct 2014 13:29:37 -0700 Date: Sun, 5 Oct 2014 13:29:37 -0700 From: Marc MERLIN To: linux-btrfs@vger.kernel.org Message-ID: <20141005202937.GK10696@merlins.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Subject: 3.16.2 btrfs deadlock Sender: linux-btrfs-owner@vger.kernel.org List-ID: Deadlocks have been less frequent (good), but here is one. An rsync from 5 days ago got stuck on btrfs it seems, and things just started piling up on top until the system deadlocked I see btrfs-transaction saying wait on page, but if it's RAM, I had plenty left: total used free shared buffers cached Mem: 7894580 6950108 944472 0 40 4816148 -/+ buffers/cache: 2133920 5760660 Swap: 15616764 767004 14849760 Here's the trace: SysRq : Show Blocked State task PC stack pid father md8_raid5 D ffff88017028cb80 0 675 2 0x00000000 ffff88020fd67aa8 0000000000000046 ffffffff812f1799 ffff88020fd67fd8 ffff880037228410 00000000000140c0 ffff88021e3940c0 ffff880037228410 ffff8801f5579bf0 0000000000000004 ffff880211ad07c8 ffff88020fd67ab8 Call Trace: [] ? blk_flush_plug_list+0x1bc/0x1cb [] schedule+0x6e/0x70 [] io_schedule+0x60/0x7a [] get_request+0x4b8/0x56a [] ? cfq_merge+0x49/0x9e [] ? finish_wait+0x65/0x65 [] blk_queue_bio+0x179/0x262 [] generic_make_request+0x9c/0xdb [] handle_stripe+0x1e41/0x2166 [raid456] [] ? ___preempt_schedule+0x56/0xa8 [] ? _raw_spin_unlock_irqrestore+0x1f/0x32 [] handle_active_stripes.isra.22+0x2e3/0x359 [raid456] [] ? md_wakeup_thread+0x55/0x58 [] raid5d+0x330/0x428 [raid456] [] ? get_parent_ip+0xd/0x3c [] md_thread+0x11c/0x13a [] ? finish_wait+0x65/0x65 [] ? bb_store+0x55/0x55 [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 btrfs-transacti D 0000000000000002 0 781 2 0x00000000 ffff88020fd6b8c0 0000000000000046 ffff88020fd6b890 ffff88020fd6bfd8 ffff88021150e3d0 00000000000140c0 ffff88021e3140c0 ffff88021150e3d0 ffff88020fd6b960 ffffffff81106441 0000000000000002 ffff88020fd6b8d0 Call Trace: [] ? wait_on_page_read+0x3c/0x3c [] schedule+0x6e/0x70 [] io_schedule+0x60/0x7a [] sleep_on_page+0xe/0x12 [] __wait_on_bit+0x48/0x7a [] wait_on_page_bit+0x7a/0x7c [] ? autoremove_wake_function+0x34/0x34 [] read_extent_buffer_pages+0x1bf/0x204 [] ? free_root_pointers+0x5b/0x5b [] btree_read_extent_buffer_pages.constprop.44+0x66/0x100 [] read_tree_block+0x2f/0x47 [] read_node_slot+0x85/0xb2 [] push_leaf_right+0x76/0x16b [] split_leaf+0xc5/0x567 [] ? leaf_space_used+0xa9/0xd8 [] ? _raw_write_unlock+0x16/0x29 [] ? btrfs_set_lock_blocking_rw+0x70/0xb5 [] btrfs_search_slot+0x654/0x6ef [] btrfs_insert_empty_items+0x5d/0xa8 [] __btrfs_run_delayed_refs+0x706/0xc49 [] btrfs_run_delayed_refs+0x71/0x197 [] btrfs_commit_transaction+0x3d/0x87f [] transaction_kthread+0xf8/0x1ab [] ? btrfs_cleanup_transaction+0x436/0x436 [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 btrfs-transacti D 0000000000000002 0 3349 2 0x00000000 ffff8802085b3a60 0000000000000046 ffff8802085b3a30 ffff8802085b3fd8 ffff8800c6836350 00000000000140c0 ffff88021e3140c0 ffff8800c6836350 ffff8802085b3b00 ffffffff81106441 0000000000000002 ffff8802085b3a70 Call Trace: [] ? wait_on_page_read+0x3c/0x3c [] schedule+0x6e/0x70 [] io_schedule+0x60/0x7a [] sleep_on_page+0xe/0x12 [] __wait_on_bit+0x48/0x7a [] wait_on_page_bit+0x7a/0x7c [] ? autoremove_wake_function+0x34/0x34 [] filemap_fdatawait_range+0x7e/0x126 [] btrfs_wait_ordered_range+0x6a/0x11a [] __btrfs_write_out_cache+0x29b/0x387 [] btrfs_write_out_cache+0xab/0xe3 [] btrfs_write_dirty_block_groups+0x543/0x561 [] commit_cowonly_roots+0x14d/0x219 [] btrfs_commit_transaction+0x41d/0x87f [] transaction_kthread+0xf8/0x1ab [] ? btrfs_cleanup_transaction+0x436/0x436 [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 md8_resync D 0000000000000002 0 20574 2 0x00000080 ffff88006666fbd0 0000000000000046 ffff88021149f618 ffff88006666ffd8 ffff880015f20510 00000000000140c0 ffff88021149f400 ffff88021149f424 0000000000000000 ffff88021149f5f8 ffff88006666fc28 ffff88006666fbe0 Call Trace: [] schedule+0x6e/0x70 [] get_active_stripe+0x225/0x575 [raid456] [] ? finish_wait+0x65/0x65 [] sync_request+0x25d/0x2d0 [raid456] [] md_do_sync+0x7fb/0xc2f [] ? finish_wait+0x65/0x65 [] md_thread+0x11c/0x13a [] ? bb_store+0x55/0x55 [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 kworker/0:2 D ffff88010e4bf440 0 28539 2 0x00000080 Workqueue: events do_sync_work ffff880075083b60 0000000000000046 ffff880075083b30 ffff880075083fd8 ffff880017c3a210 00000000000140c0 ffff88021e2140c0 ffff880017c3a210 ffff880075083c00 ffffffff81106441 0000000000000002 ffff880075083b70 Call Trace: [] ? wait_on_page_read+0x3c/0x3c [] schedule+0x6e/0x70 [] io_schedule+0x60/0x7a [] sleep_on_page+0xe/0x12 [] __wait_on_bit+0x48/0x7a [] wait_on_page_bit+0x7a/0x7c [] ? autoremove_wake_function+0x34/0x34 [] ? pagevec_lookup_tag+0x21/0x29 [] filemap_fdatawait_range+0x7e/0x126 [] filemap_fdatawait+0x21/0x23 [] sync_inodes_sb+0x14e/0x1a0 [] ? vfs_fsync+0x1e/0x1e [] sync_inodes_one_sb+0x14/0x16 [] iterate_supers+0x6e/0xc2 [] do_sync_work+0x25/0x8b [] process_one_work+0x195/0x2d2 [] worker_thread+0x275/0x352 [] ? process_scheduled_works+0x2f/0x2f [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 kworker/u8:10 D 0000000000000000 0 20493 2 0x00000080 Workqueue: btrfs-extent-refs btrfs_extent_refs_helper ffff88007d427cd8 0000000000000046 ffff8800c96aa270 ffff88007d427fd8 ffff88003c7e62d0 00000000000140c0 ffff880110e8e1e0 ffff8802115c11f0 ffff8802115c1000 ffff88010b2a0e80 00000000fffffff0 ffff88007d427ce8 Call Trace: [] schedule+0x6e/0x70 [] wait_current_trans.isra.15+0x98/0xf4 [] ? finish_wait+0x65/0x65 [] start_transaction+0x224/0x50f [] btrfs_join_transaction+0x17/0x19 [] delayed_ref_async_start+0x18/0x7b [] normal_work_helper+0xf1/0x233 [] btrfs_extent_refs_helper+0x12/0x14 [] process_one_work+0x195/0x2d2 [] worker_thread+0x275/0x352 [] ? process_scheduled_works+0x2f/0x2f [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 kworker/0:4 D ffff88017028cb80 0 22618 2 0x00000080 Workqueue: kcryptd kcryptd_crypt [dm_crypt] ffff88006c577b88 0000000000000046 ffff88021149f618 ffff88006c577fd8 ffff8800017d41d0 00000000000140c0 ffff88021149f400 ffff88021149f418 0000000000000000 ffff88021149f5c8 ffff88006c577be0 ffff88006c577b98 Call Trace: [] schedule+0x6e/0x70 [] get_active_stripe+0x225/0x575 [raid456] [] ? preempt_count_add+0x7a/0x8d [] ? finish_wait+0x65/0x65 [] make_request+0x790/0xa04 [raid456] [] ? finish_wait+0x65/0x65 [] md_make_request+0x105/0x213 [] generic_make_request+0x9c/0xdb [] kcryptd_crypt_write_io_submit+0x9d/0xa2 [dm_crypt] [] kcryptd_crypt+0x261/0x411 [dm_crypt] [] process_one_work+0x195/0x2d2 [] worker_thread+0x275/0x352 [] ? process_scheduled_works+0x2f/0x2f [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 rsync D ffff880129726080 0 28673 9798 0x20020080 ffff8800484d7c30 0000000000000082 ffff88013f4976d8 ffff8800484d7fd8 ffff88007cfe61d0 00000000000140c0 ffff880150dce660 ffff880150dce664 ffff88007cfe61d0 ffff880150dce668 00000000ffffffff ffff8800484d7c40 Call Trace: [] schedule+0x6e/0x70 [] schedule_preempt_disabled+0x18/0x24 [] __mutex_lock_slowpath+0x160/0x1d7 [] ? lookup_fast+0x15f/0x228 [] mutex_lock+0x17/0x27 [] walk_component+0x69/0x180 [] lookup_last+0x2e/0x30 [] path_lookupat+0x90/0x2d7 [] ? kmemleak_alloc_recursive.constprop.44+0x16/0x18 [] ? kmem_cache_alloc+0xff/0x17e [] filename_lookup+0x29/0x7f [] user_path_at_empty+0x59/0x8c [] ? _raw_spin_unlock+0x17/0x2a [] ? list_lru_add+0xc4/0xdb [] ? mntput_no_expire+0x33/0x12b [] user_path_at+0x11/0x13 [] vfs_fstatat+0x49/0x96 [] ? from_kgid_munged+0x12/0x1e [] vfs_lstat+0x1e/0x20 [] sys32_lstat64+0x1a/0x33 [] ? path_put+0x1e/0x21 [] ? current_kernel_time+0xe/0x32 [] ? __audit_syscall_entry+0xa6/0xc8 [] sysenter_dispatch+0x7/0x21 kworker/3:2 D 0000000000000000 0 29416 2 0x00000080 Workqueue: kcryptd kcryptd_crypt [dm_crypt] ffff88000549bbe0 0000000000000046 ffff880211117298 ffff88000549bfd8 ffff88002c84a150 00000000000140c0 ffff880211117000 ffff880211117298 ffff880211117290 0000000000000001 ffff8800c878d700 ffff88000549bbf0 Call Trace: [] schedule+0x6e/0x70 [] md_write_start+0x11e/0x137 [] ? finish_wait+0x65/0x65 [] make_request+0x3f/0xa96 [] ? crypto_aes_set_key+0x2c/0x2c [] ? crypto_aes_set_key+0x2c/0x2c [] md_make_request+0x105/0x213 [] generic_make_request+0x9c/0xdb [] kcryptd_crypt_write_io_submit+0x9d/0xa2 [dm_crypt] [] kcryptd_crypt+0x261/0x411 [dm_crypt] [] process_one_work+0x195/0x2d2 [] worker_thread+0x275/0x352 [] ? process_scheduled_works+0x2f/0x2f [] kthread+0xae/0xb6 [] ? __kthread_parkme+0x61/0x61 [] ret_from_fork+0x7c/0xb0 [] ? __kthread_parkme+0x61/0x61 rsync D ffff88018351f040 0 30350 28673 0x20020080 ffff88002e6fbbb0 0000000000000086 ffff8800c96aa270 ffff88002e6fbfd8 ffff8800824be510 00000000000140c0 ffff880110e8e1e0 ffff8800c96a19f0 ffff8800c96a1800 ffff880209e9f980 0000000000000000 ffff88002e6fbbc0 Call Trace: [] schedule+0x6e/0x70 [] wait_current_trans.isra.15+0x98/0xf4 [] ? finish_wait+0x65/0x65 [] start_transaction+0x49f/0x50f [] btrfs_start_transaction+0x1b/0x1d [] btrfs_create+0x3c/0x1ce [] ? security_inode_permission+0x1c/0x23 [] ? __inode_permission+0x79/0xa4 [] vfs_create+0x66/0x8c [] do_last+0x5af/0xa23 [] path_openat+0x237/0x4de [] do_filp_open+0x3a/0x7f [] ? get_parent_ip+0xd/0x3c [] ? _raw_spin_unlock+0x17/0x2a [] ? __alloc_fd+0xea/0xf9 [] do_sys_open+0x70/0xff [] compat_SyS_open+0x1b/0x1d [] sysenter_dispatch+0x7/0x21 exim D 0000000000000001 0 9533 4717 0x20020080 ffff8800016bfc30 0000000000000082 ffff8800016bfc00 ffff8800016bffd8 ffff8800b9fac410 00000000000140c0 ffff88021e2940c0 ffff8800b9fac410 ffff8800016bfcd0 ffffffff81106441 0000000000000002 ffff8800016bfc40 Call Trace: [] ? wait_on_page_read+0x3c/0x3c [] schedule+0x6e/0x70 [] io_schedule+0x60/0x7a [] sleep_on_page+0xe/0x12 [] __wait_on_bit+0x48/0x7a [] wait_on_page_bit+0x7a/0x7c [] ? autoremove_wake_function+0x34/0x34 [] wait_on_page_writeback+0x16/0x18 [] extent_write_cache_pages.isra.16.constprop.31+0x15b/0x2c3 [] ? mutex_unlock+0x16/0x18 [] ? btrfs_file_write_iter+0x34e/0x41c [] extent_writepages+0x4b/0x5c [] ? btrfs_submit_direct+0x3f9/0x3f9 [] btrfs_writepages+0x28/0x2a [] do_writepages+0x1e/0x2c [] __filemap_fdatawrite_range+0x55/0x57 [] filemap_fdatawrite_range+0x13/0x15 [] btrfs_sync_file+0xaa/0x2cc [] ? __sb_end_write+0x2d/0x5b [] vfs_fsync_range+0x1b/0x25 [] vfs_fsync+0x1c/0x1e [] do_fsync+0x2c/0x4c [] SyS_fdatasync+0x13/0x17 [] sysenter_dispatch+0x7/0x21 Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 3 CPU: 3 PID: 9583 Comm: sadc Not tainted 3.16.2-amd64-i915-preempt-20140714 #1 Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 3806 08/20/2012 0000000000000000 ffff88021e386c20 ffffffff816369d6 ffffffff81aa16ef ffff88021e386c98 ffffffff81632988 0000000000000010 ffff88021e386ca8 ffff88021e386c48 0000000000000000 0000000000000003 ffff88021e386ef8 Call Trace: [] dump_stack+0x4e/0x7a [] panic+0xcb/0x1fe [] watchdog_overflow_callback+0xbb/0x110 [] __perf_event_overflow+0x155/0x1e3 [] ? x86_perf_event_set_period+0x103/0x113 [] perf_event_overflow+0x14/0x16 [] intel_pmu_handle_irq+0x2d7/0x364 [] perf_event_nmi_handler+0x25/0x3e [] nmi_handle+0x60/0x11c [] ? cpumask_clear_cpu.constprop.3+0x11/0x11 [] default_do_nmi+0x74/0x157 [] do_nmi+0x62/0xa2 [] end_repeat_nmi+0x1e/0x2e [] ? do_raw_spin_lock+0x19/0x27 [] ? do_raw_spin_lock+0x19/0x27 [] ? do_raw_spin_lock+0x19/0x27 <> [] _raw_spin_lock_irq+0x24/0x27 [] uart_proc_show+0x134/0x331 [] seq_read+0x150/0x302 [] ? fsnotify_perm+0x60/0x6b [] proc_reg_read+0x5a/0x7c [] vfs_read+0x88/0xfa [] SyS_read+0x46/0x79 [] sysenter_dispatch+0x7/0x21 131.048038 0.016424 0.007621 / kworker/2:1H 347 4825481473.873853 32768954 100 4825481473.873853 1024031.415751 2431265490.458642 / bioset 656 7340.438018 2 100 7340.438018 0.079953 0.032596 / bioset 674 7428.235256 2 100 7428.235256 0.011555 0.006256 / btrfs-worker 761 8129.795955 2 100 8129.795955 0.096081 0.046142 / btrfs-worker-hi 763 3243544430.862921 4 100 3243544430.862921 0.119452 1603390139.421423 / btrfs-flush_del 765 4740941088.983912 4 100 4740941088.983912 0.105922 2389612400.423491 / btrfs-fixup 768 8175.005182 2 100 8175.005182 0.009229 0.006478 / btrfs-endio 769 4805566466.196436 64 100 4805566466.196436 9.582823 2423209769.669892 / btrfs-endio-met 771 8202.024157 2 100 8202.024157 0.007683 0.003995 / btrfs-endio-rai 772 8211.030439 2 100 8211.030439 0.007657 0.003322 / btrfs-rmw 773 8220.036746 2 100 8220.036746 0.007690 0.003264 / btrfs-freespace 775 4731100793.494699 131 100 4731100793.494699 3.131112 2383851399.473326 / btrfs-delayed-m 776 65137379.868524 3 100 65137379.868524 0.113543 26290219.856218 / btrfs-readahead 777 8 -- "A mouse is a device used to point at the xterm you want to type in" - A.S.R. Microsoft is to operating systems .... .... what McDonalds is to gourmet cooking Home page: http://marc.merlins.org/ | PGP 1024R/763BE901