From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from sentry-two.sandia.gov ([132.175.109.14]:37604 "EHLO sentry-two.sandia.gov" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754827Ab2JCVak (ORCPT ); Wed, 3 Oct 2012 17:30:40 -0400 Message-ID: <506CAE5E.40806@sandia.gov> Date: Wed, 3 Oct 2012 15:30:06 -0600 From: "Jim Schutt" MIME-Version: 1.0 To: linux-btrfs@vger.kernel.org cc: "Josef Bacik" Subject: btrfs lockdep splat for fs_info->chunk_mutex Content-Type: text/plain; charset=utf-8; format=flowed Sender: linux-btrfs-owner@vger.kernel.org List-ID: Hi, I've been testing what I believe to be the btrfs patches being queued up for 3.7, and have been having trouble with stalled writes. (See, e.g., http://www.spinics.net/lists/linux-btrfs/msg19171.html) With CONFIG_PROVE_LOCKING=y I was able to collect the following lockdep splat, which I hope is related to my stalls. The kernel is from the master branch of Josef Bacik's btrfs-next tree, and the load is heavy writing from Ceph OSDs. Please let me know if there is anything more I can do to help resolve this. [ 1369.608721] [ 1369.610215] ============================================= [ 1369.615602] [ INFO: possible recursive locking detected ] [ 1369.620990] 3.6.0-00115-g2ff1260 #311 Not tainted [ 1369.625688] --------------------------------------------- [ 1369.631076] ceph-osd/88953 is trying to acquire lock: [ 1369.636122] (&fs_info->chunk_mutex){+.+...}, at: [] do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.645815] [ 1369.645815] but task is already holding lock: [ 1369.651636] (&fs_info->chunk_mutex){+.+...}, at: [] do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.661333] [ 1369.661333] other info that might help us debug this: [ 1369.667843] Possible unsafe locking scenario: [ 1369.667843] [ 1369.673748] CPU0 [ 1369.676202] ---- [ 1369.678646] lock(&fs_info->chunk_mutex); [ 1369.682783] lock(&fs_info->chunk_mutex); [ 1369.686917] [ 1369.686917] *** DEADLOCK *** [ 1369.686917] [ 1369.692821] May be due to missing lock nesting notation [ 1369.692821] [ 1369.699595] 4 locks held by ceph-osd/88953: [ 1369.703776] #0: (sb_writers#7){.+.+.+}, at: [] btrfs_file_aio_write+0x64/0x320 [btrfs] [ 1369.713647] #1: (&sb->s_type->i_mutex_key#9){+.+.+.}, at: [] btrfs_file_aio_write+0x6e/0x320 [btrfs] [ 1369.724666] #2: (sb_internal){.+.+..}, at: [] start_transaction+0x1c4/0x490 [btrfs] [ 1369.734186] #3: (&fs_info->chunk_mutex){+.+...}, at: [] do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.744345] [ 1369.744345] stack backtrace: [ 1369.748707] Pid: 88953, comm: ceph-osd Not tainted 3.6.0-00115-g2ff1260 #311 [ 1369.755740] Call Trace: [ 1369.758213] [] print_deadlock_bug+0xe9/0x100 [ 1369.764124] [] validate_chain+0x596/0x750 [ 1369.769778] [] ? finish_task_switch+0x3f/0x110 [ 1369.775867] [] __lock_acquire+0x3dd/0x480 [ 1369.781532] [] lock_acquire+0x129/0x190 [ 1369.787052] [] ? do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.793586] [] __mutex_lock_common+0x5d/0x3a0 [ 1369.799618] [] ? do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.806183] [] ? do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.812702] [] mutex_lock_nested+0x4a/0x60 [ 1369.818467] [] do_chunk_alloc+0x183/0x290 [btrfs] [ 1369.824853] [] find_free_extent+0xa9c/0xbc0 [btrfs] [ 1369.831394] [] ? btrfs_reduce_alloc_profile+0xa9/0x120 [btrfs] [ 1369.838920] [] btrfs_reserve_extent+0x82/0x1e0 [btrfs] [ 1369.845731] [] btrfs_alloc_free_block+0x85/0x230 [btrfs] [ 1369.852717] [] __btrfs_cow_block+0x14a/0x4b0 [btrfs] [ 1369.859354] [] ? btrfs_set_lock_blocking_rw+0xe3/0x160 [btrfs] [ 1369.866843] [] btrfs_cow_block+0x18d/0x2d0 [btrfs] [ 1369.873289] [] btrfs_search_slot+0x368/0x720 [btrfs] [ 1369.879910] [] btrfs_insert_empty_items+0x8d/0x100 [btrfs] [ 1369.887026] [] ? kmem_cache_alloc+0xd3/0x1b0 [ 1369.892965] [] btrfs_alloc_dev_extent+0xb5/0x190 [btrfs] [ 1369.899931] [] __btrfs_alloc_chunk+0x6e7/0x790 [btrfs] [ 1369.906743] [] btrfs_alloc_chunk+0x5e/0x90 [btrfs] [ 1369.913204] [] ? check_system_chunk+0x71/0x130 [btrfs] [ 1369.920022] [] do_chunk_alloc+0x21e/0x290 [btrfs] [ 1369.926409] [] btrfs_check_data_free_space+0x13c/0x2f0 [btrfs] [ 1369.933917] [] btrfs_delalloc_reserve_space+0x20/0x60 [btrfs] [ 1369.941335] [] __btrfs_buffered_write+0x15e/0x350 [btrfs] [ 1369.948408] [] btrfs_file_aio_write+0x209/0x320 [btrfs] [ 1369.955299] [] ? __btrfs_direct_write+0x130/0x130 [btrfs] [ 1369.962334] [] do_sync_readv_writev+0x94/0xe0 [ 1369.968333] [] do_readv_writev+0xe3/0x1e0 [ 1369.973983] [] ? fget_light+0x388/0x3e0 [ 1369.979459] [] vfs_writev+0x46/0x60 [ 1369.984585] [] sys_writev+0x51/0xb0 [ 1369.989715] [] system_call_fastpath+0x16/0x1b [ 1559.036678] INFO: task btrfs-endio-wri:75602 blocked for more than 120 seconds. [ 1559.043993] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1559.051872] btrfs-endio-wri D ffff8802e7440250 0 75602 2 0x00000000 [ 1559.059095] ffff8805e2f87a80 0000000000000046 0000000000000282 ffff8805e2f87fd8 [ 1559.066634] ffff8805e2f86000 ffff8805e2f86010 ffff8805e2f86000 ffff8805e2f86000 [ 1559.074240] ffff8805e2f87fd8 ffff8805e2f86000 ffff88098749bea0 ffff880506d95df0 [ 1559.081786] Call Trace: [ 1559.084252] [] schedule+0x5d/0x60 [ 1559.089261] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1559.096062] [] ? wake_up_bit+0x40/0x40 [ 1559.101478] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1559.108124] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1559.114669] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1559.121819] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1559.128425] [] ? kmem_cache_alloc_trace+0x5b/0x1b0 [ 1559.134890] [] btrfs_lookup_csum+0x84/0x180 [btrfs] [ 1559.141422] [] ? kmem_cache_alloc+0xd3/0x1b0 [ 1559.147385] [] btrfs_csum_file_blocks+0xe0/0x6d0 [btrfs] [ 1559.154382] [] ? unpin_extent_cache+0xeb/0x120 [btrfs] [ 1559.161222] [] add_pending_csums+0x49/0x70 [btrfs] [ 1559.167681] [] btrfs_finish_ordered_io+0x392/0x4d0 [btrfs] [ 1559.174817] [] ? _raw_spin_unlock_irq+0x30/0x50 [ 1559.181027] [] finish_ordered_fn+0x15/0x20 [btrfs] [ 1559.187507] [] worker_loop+0x1a2/0x410 [btrfs] [ 1559.193628] [] ? check_pending_worker_creates+0xe0/0xe0 [btrfs] [ 1559.201226] [] kthread+0xb4/0xc0 [ 1559.206113] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1559.212738] [] kernel_thread_helper+0x4/0x10 [ 1559.218669] [] ? retint_restore_args+0xe/0xe [ 1559.224608] [] ? __init_kthread_worker+0x70/0x70 [ 1559.230895] [] ? gs_change+0xb/0xb [ 1559.236380] INFO: lockdep is turned off. [ 1559.240519] INFO: task btrfs-transacti:75608 blocked for more than 120 seconds. [ 1559.247816] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1559.255641] btrfs-transacti D ffff8802cba07780 0 75608 2 0x00000000 [ 1559.262745] ffff8804712035b0 0000000000000046 0000000000000286 ffff880471203fd8 [ 1559.270249] ffff880471202000 ffff880471202010 ffff880471202000 ffff880471202000 [ 1559.277760] ffff880471203fd8 ffff880471202000 ffff880624610000 ffff88034b571f50 [ 1559.285289] Call Trace: [ 1559.287752] [] schedule+0x5d/0x60 [ 1559.292757] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1559.299544] [] ? wake_up_bit+0x40/0x40 [ 1559.304975] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1559.311600] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1559.318142] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1559.325293] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1559.331933] [] ? free_extent_map+0x87/0x90 [btrfs] [ 1559.338403] [] btrfs_lookup_file_extent+0x3d/0x40 [btrfs] [ 1559.345481] [] __btrfs_drop_extents+0x171/0xad0 [btrfs] [ 1559.352356] [] ? kmem_cache_alloc+0xd3/0x1b0 [ 1559.358297] [] btrfs_drop_extents+0x73/0xa0 [btrfs] [ 1559.364834] [] cow_file_range_inline+0xe5/0x1c0 [btrfs] [ 1559.371732] [] ? test_range_bit+0x17c/0x190 [btrfs] [ 1559.378284] [] cow_file_range+0x172/0x4b0 [btrfs] [ 1559.384651] [] run_delalloc_range+0x7b/0xa0 [btrfs] [ 1559.391195] [] __extent_writepage+0x280/0x7b0 [btrfs] [ 1559.397900] [] ? find_get_pages_tag+0x28f/0x2f0 [ 1559.404079] [] ? find_get_pages_tag+0x2a7/0x2f0 [ 1559.410260] [] ? find_get_pages_tag+0x38/0x2f0 [ 1559.416346] [] ? igrab+0x40/0x70 [ 1559.421254] [] ? clear_page_dirty_for_io+0xe5/0x100 [ 1559.427810] [] extent_write_cache_pages.clone.3+0x242/0x3c0 [btrfs] [ 1559.435769] [] ? btrfs_run_ordered_operations+0x3d/0x220 [btrfs] [ 1559.443428] [] ? __mutex_lock_common+0x36b/0x3a0 [ 1559.449726] [] extent_writepages+0x4f/0x70 [btrfs] [ 1559.456188] [] ? can_nocow_odirect+0x260/0x260 [btrfs] [ 1559.462975] [] ? igrab+0x40/0x70 [ 1559.467939] [] btrfs_writepages+0x27/0x30 [btrfs] [ 1559.474330] [] do_writepages+0x23/0x40 [ 1559.479754] [] __filemap_fdatawrite_range+0x4e/0x50 [ 1559.486282] [] ? _raw_spin_unlock+0x2b/0x50 [ 1559.492123] [] filemap_flush+0x1c/0x20 [ 1559.497567] [] btrfs_run_ordered_operations+0x179/0x220 [btrfs] [ 1559.505158] [] btrfs_commit_transaction+0x91/0xa50 [btrfs] [ 1559.512296] [] ? _raw_spin_unlock+0x2b/0x50 [ 1559.518151] [] ? start_transaction+0x403/0x490 [btrfs] [ 1559.524946] [] ? wake_up_bit+0x40/0x40 [ 1559.530387] [] transaction_kthread+0x123/0x210 [btrfs] [ 1559.537210] [] ? btrfs_bio_wq_end_io+0x90/0x90 [btrfs] [ 1559.544017] [] kthread+0xb4/0xc0 [ 1559.548916] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1559.555529] [] kernel_thread_helper+0x4/0x10 [ 1559.561454] [] ? retint_restore_args+0xe/0xe [ 1559.567387] [] ? __init_kthread_worker+0x70/0x70 [ 1559.573662] [] ? gs_change+0xb/0xb [ 1559.578717] INFO: lockdep is turned off. [ 1559.582654] INFO: task flush-btrfs-141:78560 blocked for more than 120 seconds. [ 1559.589952] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1559.597771] flush-btrfs-141 D ffff8802cba07780 0 78560 2 0x00000000 [ 1559.604854] ffff8806225ad420 0000000000000046 0000000000000286 ffff8806225adfd8 [ 1559.612338] ffff8806225ac000 ffff8806225ac010 ffff8806225ac000 ffff8806225ac000 [ 1559.619823] ffff8806225adfd8 ffff8806225ac000 ffffffff81a13420 ffff88048b3c5df0 [ 1559.627319] Call Trace: [ 1559.629801] [] schedule+0x5d/0x60 [ 1559.634799] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1559.641592] [] ? wake_up_bit+0x40/0x40 [ 1559.647024] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1559.653657] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1559.660230] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1559.667400] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1559.674039] [] ? free_extent_map+0x87/0x90 [btrfs] [ 1559.680519] [] btrfs_lookup_file_extent+0x3d/0x40 [btrfs] [ 1559.687595] [] __btrfs_drop_extents+0x171/0xad0 [btrfs] [ 1559.694466] [] ? kmem_cache_alloc+0xd3/0x1b0 [ 1559.700400] [] ? join_transaction+0xc0/0x370 [btrfs] [ 1559.707040] [] btrfs_drop_extents+0x73/0xa0 [btrfs] [ 1559.713588] [] cow_file_range_inline+0xe5/0x1c0 [btrfs] [ 1559.720496] [] ? test_range_bit+0x17c/0x190 [btrfs] [ 1559.727071] [] cow_file_range+0x172/0x4b0 [btrfs] [ 1559.733447] [] run_delalloc_range+0x7b/0xa0 [btrfs] [ 1559.739991] [] __extent_writepage+0x280/0x7b0 [btrfs] [ 1559.746690] [] ? find_get_pages_tag+0x28f/0x2f0 [ 1559.752863] [] ? find_get_pages_tag+0x2a7/0x2f0 [ 1559.759036] [] ? find_get_pages_tag+0x38/0x2f0 [ 1559.765131] [] ? igrab+0x40/0x70 [ 1559.770014] [] ? clear_page_dirty_for_io+0xe5/0x100 [ 1559.776574] [] extent_write_cache_pages.clone.3+0x242/0x3c0 [btrfs] [ 1559.784494] [] ? __lock_acquire+0x3dd/0x480 [ 1559.790343] [] extent_writepages+0x4f/0x70 [btrfs] [ 1559.796816] [] ? can_nocow_odirect+0x260/0x260 [btrfs] [ 1559.803620] [] btrfs_writepages+0x27/0x30 [btrfs] [ 1559.809980] [] do_writepages+0x23/0x40 [ 1559.815393] [] __writeback_single_inode+0x5b/0x1e0 [ 1559.821832] [] writeback_sb_inodes+0x2c9/0x3e0 [ 1559.827929] [] ? _raw_spin_unlock+0x2b/0x50 [ 1559.833764] [] __writeback_inodes_wb+0x86/0xd0 [ 1559.839850] [] wb_writeback+0x20b/0x550 [ 1559.845355] [] ? local_bh_enable_ip+0xcd/0xe0 [ 1559.851371] [] wb_do_writeback+0x243/0x310 [ 1559.857129] [] bdi_writeback_thread+0x133/0x3f0 [ 1559.863323] [] ? wb_do_writeback+0x310/0x310 [ 1559.869249] [] ? wb_do_writeback+0x310/0x310 [ 1559.875182] [] kthread+0xb4/0xc0 [ 1559.880067] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1559.886677] [] kernel_thread_helper+0x4/0x10 [ 1559.892592] [] ? retint_restore_args+0xe/0xe [ 1559.898505] [] ? __init_kthread_worker+0x70/0x70 [ 1559.904786] [] ? gs_change+0xb/0xb [ 1559.909835] INFO: lockdep is turned off. [ 1559.917333] INFO: task ceph-osd:88950 blocked for more than 120 seconds. [ 1559.924022] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1559.931839] ceph-osd D ffff8802cba07780 0 88950 1 0x00000004 [ 1559.938943] ffff880b646a19c8 0000000000000046 0000000000000282 ffff880b646a1fd8 [ 1559.946424] ffff880b646a0000 ffff880b646a0010 ffff880b646a0000 ffff880b646a0000 [ 1559.953935] ffff880b646a1fd8 ffff880b646a0000 ffff8806245d0000 ffff880c0a539f50 [ 1559.961467] Call Trace: [ 1559.963933] [] schedule+0x5d/0x60 [ 1559.968927] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1559.975702] [] ? wake_up_bit+0x40/0x40 [ 1559.981127] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1559.987784] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1559.994342] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1560.001489] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1560.008136] [] btrfs_lookup_dir_item+0x7d/0xd0 [btrfs] [ 1560.014952] [] btrfs_lookup_dentry+0xe4/0x420 [btrfs] [ 1560.021709] [] btrfs_lookup+0x1d/0x70 [btrfs] [ 1560.027736] [] ? lookup_dcache+0x9b/0xd0 [ 1560.033312] [] lookup_real+0x36/0x60 [ 1560.038546] [] __lookup_hash+0x38/0x50 [ 1560.043954] [] lookup_slow+0x64/0xe0 [ 1560.049190] [] path_lookupat+0xf7/0x6e0 [ 1560.054691] [] ? kmem_cache_alloc+0x57/0x1b0 [ 1560.060617] [] do_path_lookup+0x31/0xd0 [ 1560.066117] [] user_path_at_empty+0x6c/0xb0 [ 1560.071977] [] ? lg_local_unlock+0x23/0x50 [ 1560.077742] [] ? cp_new_stat+0x116/0x130 [ 1560.083324] [] user_path_at+0x11/0x20 [ 1560.088653] [] vfs_fstatat+0x47/0x80 [ 1560.093900] [] vfs_stat+0x1b/0x20 [ 1560.098867] [] sys_newstat+0x24/0x50 [ 1560.104105] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1560.110727] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 1560.117184] [] system_call_fastpath+0x16/0x1b [ 1560.123186] INFO: lockdep is turned off. [ 1560.127116] INFO: task ceph-osd:88953 blocked for more than 120 seconds. [ 1560.133814] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1560.141633] ceph-osd D 0000000000000246 0 88953 1 0x00000004 [ 1560.148748] ffff8808f73ed388 0000000000000046 00007fffeced05a0 ffff8808f73edfd8 [ 1560.156235] ffff8808f73ec000 ffff8808f73ec010 ffff8808f73ec000 ffff8808f73ec000 [ 1560.163704] ffff8808f73edfd8 ffff8808f73ec000 ffff880a74d1ddf0 ffff880add0a9f50 [ 1560.171187] Call Trace: [ 1560.173644] [] schedule+0x5d/0x60 [ 1560.178616] [] schedule_preempt_disabled+0x27/0x40 [ 1560.185048] [] __mutex_lock_common+0x255/0x3a0 [ 1560.191169] [] ? do_chunk_alloc+0x183/0x290 [btrfs] [ 1560.197738] [] ? do_chunk_alloc+0x183/0x290 [btrfs] [ 1560.204257] [] mutex_lock_nested+0x4a/0x60 [ 1560.210022] [] do_chunk_alloc+0x183/0x290 [btrfs] [ 1560.216409] [] find_free_extent+0xa9c/0xbc0 [btrfs] [ 1560.222955] [] ? btrfs_reduce_alloc_profile+0xa9/0x120 [btrfs] [ 1560.230458] [] btrfs_reserve_extent+0x82/0x1e0 [btrfs] [ 1560.237263] [] btrfs_alloc_free_block+0x85/0x230 [btrfs] [ 1560.244234] [] __btrfs_cow_block+0x14a/0x4b0 [btrfs] [ 1560.250868] [] ? btrfs_set_lock_blocking_rw+0xe3/0x160 [btrfs] [ 1560.258367] [] btrfs_cow_block+0x18d/0x2d0 [btrfs] [ 1560.264845] [] btrfs_search_slot+0x368/0x720 [btrfs] [ 1560.271497] [] btrfs_insert_empty_items+0x8d/0x100 [btrfs] [ 1560.278630] [] ? kmem_cache_alloc+0xd3/0x1b0 [ 1560.284595] [] btrfs_alloc_dev_extent+0xb5/0x190 [btrfs] [ 1560.291576] [] __btrfs_alloc_chunk+0x6e7/0x790 [btrfs] [ 1560.298377] [] btrfs_alloc_chunk+0x5e/0x90 [btrfs] [ 1560.304852] [] ? check_system_chunk+0x71/0x130 [btrfs] [ 1560.311665] [] do_chunk_alloc+0x21e/0x290 [btrfs] [ 1560.318037] [] btrfs_check_data_free_space+0x13c/0x2f0 [btrfs] [ 1560.325548] [] btrfs_delalloc_reserve_space+0x20/0x60 [btrfs] [ 1560.332942] [] __btrfs_buffered_write+0x15e/0x350 [btrfs] [ 1560.340018] [] btrfs_file_aio_write+0x209/0x320 [btrfs] [ 1560.346912] [] ? __btrfs_direct_write+0x130/0x130 [btrfs] [ 1560.353957] [] do_sync_readv_writev+0x94/0xe0 [ 1560.359963] [] do_readv_writev+0xe3/0x1e0 [ 1560.365620] [] ? fget_light+0x388/0x3e0 [ 1560.371101] [] vfs_writev+0x46/0x60 [ 1560.376230] [] sys_writev+0x51/0xb0 [ 1560.381363] [] system_call_fastpath+0x16/0x1b [ 1560.387361] INFO: lockdep is turned off. [ 1560.391291] INFO: task ceph-osd:88964 blocked for more than 120 seconds. [ 1560.397976] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1560.405789] ceph-osd D 0000000000000246 0 88964 1 0x00000004 [ 1560.412876] ffff8809107ef5c8 0000000000000046 ffff8809107ef6b8 ffff8809107effd8 [ 1560.420343] ffff8809107ee000 ffff8809107ee010 ffff8809107ee000 ffff8809107ee000 [ 1560.427854] ffff8809107effd8 ffff8809107ee000 ffff880af56d3ea0 ffff8809107f1f50 [ 1560.435350] Call Trace: [ 1560.437819] [] schedule+0x5d/0x60 [ 1560.442789] [] schedule_preempt_disabled+0x27/0x40 [ 1560.449224] [] __mutex_lock_common+0x255/0x3a0 [ 1560.455347] [] ? do_chunk_alloc+0x1be/0x290 [btrfs] [ 1560.461888] [] ? do_chunk_alloc+0x1be/0x290 [btrfs] [ 1560.468419] [] mutex_lock_nested+0x4a/0x60 [ 1560.474187] [] do_chunk_alloc+0x1be/0x290 [btrfs] [ 1560.480570] [] find_free_extent+0xa9c/0xbc0 [btrfs] [ 1560.487123] [] ? btrfs_reduce_alloc_profile+0xa9/0x120 [btrfs] [ 1560.494624] [] btrfs_reserve_extent+0x82/0x1e0 [btrfs] [ 1560.501442] [] btrfs_alloc_free_block+0x85/0x230 [btrfs] [ 1560.508417] [] split_leaf+0x3cc/0x700 [btrfs] [ 1560.514474] [] btrfs_search_slot+0x638/0x720 [btrfs] [ 1560.521108] [] btrfs_insert_empty_items+0x8d/0x100 [btrfs] [ 1560.528239] [] ? _raw_spin_unlock+0x2b/0x50 [ 1560.534082] [] btrfs_new_inode+0x1b6/0x4f0 [btrfs] [ 1560.540515] [] ? trace_hardirqs_off+0xd/0x10 [ 1560.546441] [] ? walk_down_tree+0x40/0x100 [btrfs] [ 1560.552909] [] btrfs_create+0xc0/0x200 [btrfs] [ 1560.559013] [] ? security_inode_permission+0x25/0x30 [ 1560.565623] [] vfs_create+0x9f/0xd0 [ 1560.570767] [] ? do_last+0x231/0x720 [ 1560.575995] [] lookup_open+0x16a/0x1c0 [ 1560.581407] [] do_last+0x24b/0x720 [ 1560.586457] [] ? inode_permission+0x4d/0x50 [ 1560.592291] [] path_openat+0xc7/0x470 [ 1560.597602] [] ? putname+0x33/0x50 [ 1560.602656] [] do_filp_open+0x49/0xb0 [ 1560.607961] [] ? _raw_spin_unlock+0x2b/0x50 [ 1560.613801] [] ? alloc_fd+0x1ed/0x200 [ 1560.619133] [] do_sys_open+0x135/0x1d0 [ 1560.624548] [] sys_open+0x21/0x30 [ 1560.629510] [] system_call_fastpath+0x16/0x1b [ 1560.635506] INFO: lockdep is turned off. [ 1560.639429] INFO: task ceph-osd:89821 blocked for more than 120 seconds. [ 1560.646112] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1560.653928] ceph-osd D ffff8802cba07780 0 89821 1 0x00000004 [ 1560.661034] ffff880a03afd9c8 0000000000000046 0000000000000282 ffff880a03afdfd8 [ 1560.668515] ffff880a03afc000 ffff880a03afc010 ffff880a03afc000 ffff880a03afc000 [ 1560.676000] ffff880a03afdfd8 ffff880a03afc000 ffff8806245e0000 ffff88096c6a1f50 [ 1560.683485] Call Trace: [ 1560.685949] [] schedule+0x5d/0x60 [ 1560.690962] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1560.697753] [] ? wake_up_bit+0x40/0x40 [ 1560.703162] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1560.709797] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1560.716370] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1560.723514] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1560.730156] [] btrfs_lookup_dir_item+0x7d/0xd0 [btrfs] [ 1560.736973] [] btrfs_lookup_dentry+0xe4/0x420 [btrfs] [ 1560.743680] [] btrfs_lookup+0x1d/0x70 [btrfs] [ 1560.749684] [] ? lookup_dcache+0x9b/0xd0 [ 1560.755244] [] lookup_real+0x36/0x60 [ 1560.760472] [] __lookup_hash+0x38/0x50 [ 1560.765874] [] lookup_slow+0x64/0xe0 [ 1560.771103] [] path_lookupat+0xf7/0x6e0 [ 1560.776600] [] ? kmem_cache_alloc+0x57/0x1b0 [ 1560.782522] [] do_path_lookup+0x31/0xd0 [ 1560.788013] [] user_path_at_empty+0x6c/0xb0 [ 1560.793847] [] ? lg_local_unlock+0x23/0x50 [ 1560.799601] [] ? cp_new_stat+0x116/0x130 [ 1560.805177] [] user_path_at+0x11/0x20 [ 1560.810491] [] vfs_fstatat+0x47/0x80 [ 1560.815723] [] vfs_stat+0x1b/0x20 [ 1560.820699] [] sys_newstat+0x24/0x50 [ 1560.825938] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1560.832551] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 1560.838997] [] system_call_fastpath+0x16/0x1b [ 1560.845013] INFO: lockdep is turned off. [ 1560.848951] INFO: task ceph-osd:89829 blocked for more than 120 seconds. [ 1560.855648] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1560.863468] ceph-osd D 0000000000000246 0 89829 1 0x00000004 [ 1560.870551] ffff88096c6adbb8 0000000000000046 ffffffff8118c6ce ffff88096c6adfd8 [ 1560.878021] ffff88096c6ac000 ffff88096c6ac010 ffff88096c6ac000 ffff88096c6ac000 [ 1560.885537] ffff88096c6adfd8 ffff88096c6ac000 ffff8806245d3ea0 ffff88096c6b0000 [ 1560.893020] Call Trace: [ 1560.895483] [] ? __d_lookup+0x20e/0x300 [ 1560.900971] [] schedule+0x5d/0x60 [ 1560.905937] [] schedule_preempt_disabled+0x27/0x40 [ 1560.912386] [] __mutex_lock_common+0x255/0x3a0 [ 1560.918482] [] ? lookup_slow+0x56/0xe0 [ 1560.923886] [] ? lookup_slow+0x56/0xe0 [ 1560.929291] [] mutex_lock_nested+0x4a/0x60 [ 1560.935038] [] lookup_slow+0x56/0xe0 [ 1560.940265] [] path_lookupat+0xf7/0x6e0 [ 1560.945753] [] ? kmem_cache_alloc+0x57/0x1b0 [ 1560.951675] [] do_path_lookup+0x31/0xd0 [ 1560.957152] [] user_path_at_empty+0x6c/0xb0 [ 1560.962981] [] user_path_at+0x11/0x20 [ 1560.968302] [] vfs_fstatat+0x47/0x80 [ 1560.973528] [] vfs_stat+0x1b/0x20 [ 1560.978512] [] sys_newstat+0x24/0x50 [ 1560.983746] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1560.990345] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 1560.996792] [] system_call_fastpath+0x16/0x1b [ 1561.002793] INFO: lockdep is turned off. [ 1561.006712] INFO: task ceph-osd:89839 blocked for more than 120 seconds. [ 1561.013394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1561.021205] ceph-osd D ffff8802cba07780 0 89839 1 0x00000004 [ 1561.028293] ffff880a736a19c8 0000000000000046 0000000000000282 ffff880a736a1fd8 [ 1561.035764] ffff880a736a0000 ffff880a736a0010 ffff880a736a0000 ffff880a736a0000 [ 1561.043251] ffff880a736a1fd8 ffff880a736a0000 ffff8806245e1f50 ffff88096c6b5df0 [ 1561.050726] Call Trace: [ 1561.053178] [] schedule+0x5d/0x60 [ 1561.058171] [] btrfs_tree_read_lock+0xf3/0x140 [btrfs] [ 1561.064951] [] ? wake_up_bit+0x40/0x40 [ 1561.070385] [] ? btrfs_root_node+0x198/0x230 [btrfs] [ 1561.077019] [] ? btrfs_root_node+0x30/0x230 [btrfs] [ 1561.083581] [] btrfs_read_lock_root_node+0x23/0x50 [btrfs] [ 1561.090759] [] btrfs_search_slot+0x1f0/0x720 [btrfs] [ 1561.097426] [] btrfs_lookup_dir_item+0x7d/0xd0 [btrfs] [ 1561.104274] [] btrfs_lookup_dentry+0xe4/0x420 [btrfs] [ 1561.110996] [] btrfs_lookup+0x1d/0x70 [btrfs] [ 1561.116996] [] ? lookup_dcache+0x9b/0xd0 [ 1561.122578] [] lookup_real+0x36/0x60 [ 1561.127803] [] __lookup_hash+0x38/0x50 [ 1561.133211] [] lookup_slow+0x64/0xe0 [ 1561.138458] [] path_lookupat+0xf7/0x6e0 [ 1561.143955] [] ? kmem_cache_alloc+0x57/0x1b0 [ 1561.149897] [] do_path_lookup+0x31/0xd0 [ 1561.155385] [] user_path_at_empty+0x6c/0xb0 [ 1561.161223] [] user_path_at+0x11/0x20 [ 1561.166534] [] vfs_fstatat+0x47/0x80 [ 1561.171758] [] vfs_stat+0x1b/0x20 [ 1561.176724] [] sys_newstat+0x24/0x50 [ 1561.181955] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1561.188564] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 1561.195000] [] system_call_fastpath+0x16/0x1b [ 1561.201000] INFO: lockdep is turned off. [ 1561.204933] INFO: task ceph-osd:89859 blocked for more than 120 seconds. [ 1561.211619] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1561.219434] ceph-osd D 0000000000000246 0 89859 1 0x00000004 [ 1561.226542] ffff880a7f725bb8 0000000000000046 ffffffff8118c6ce ffff880a7f725fd8 [ 1561.234038] ffff880a7f724000 ffff880a7f724010 ffff880a7f724000 ffff880a7f724000 [ 1561.241531] ffff880a7f725fd8 ffff880a7f724000 ffff880624600000 ffff880a736b5df0 [ 1561.249042] Call Trace: [ 1561.251526] [] ? __d_lookup+0x20e/0x300 [ 1561.257020] [] schedule+0x5d/0x60 [ 1561.261995] [] schedule_preempt_disabled+0x27/0x40 [ 1561.268435] [] __mutex_lock_common+0x255/0x3a0 [ 1561.274531] [] ? lookup_slow+0x56/0xe0 [ 1561.279935] [] ? lookup_slow+0x56/0xe0 [ 1561.285348] [] mutex_lock_nested+0x4a/0x60 [ 1561.291095] [] lookup_slow+0x56/0xe0 [ 1561.296327] [] path_lookupat+0xf7/0x6e0 [ 1561.301808] [] ? kmem_cache_alloc+0x57/0x1b0 [ 1561.307715] [] do_path_lookup+0x31/0xd0 [ 1561.313200] [] user_path_at_empty+0x6c/0xb0 [ 1561.319029] [] user_path_at+0x11/0x20 [ 1561.324361] [] vfs_fstatat+0x47/0x80 [ 1561.329599] [] vfs_stat+0x1b/0x20 [ 1561.334568] [] sys_newstat+0x24/0x50 [ 1561.339784] [] ? trace_hardirqs_on_caller+0x20/0x1e0 [ 1561.346403] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 1561.352849] [] system_call_fastpath+0x16/0x1b [ 1561.358852] INFO: lockdep is turned off. -- Jim