Message ID | alpine.DEB.2.00.1208241439490.26910@cobra.newdream.net (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
Sadly, now I hit another one: [ 378.433842] ============================================= [ 378.433842] [ INFO: possible recursive locking detected ] [ 378.433845] 3.6.0-rc2-ceph-00143-g995fc06 #1 Not tainted [ 378.433845] --------------------------------------------- [ 378.433847] kworker/6:1/238 is trying to acquire lock: [ 378.433872] (sb_internal#2){.+.+..}, at: [<ffffffffa0042b74>] start_transaction+0x124/0x430 [btrfs] [ 378.433873] [ 378.433873] but task is already holding lock: [ 378.433890] (sb_internal#2){.+.+..}, at: [<ffffffffa0042590>] do_async_commit+0x0/0x80 [btrfs] [ 378.433891] [ 378.433891] other info that might help us debug this: [ 378.433892] Possible unsafe locking scenario: [ 378.433892] [ 378.433892] CPU0 [ 378.433893] ---- [ 378.433895] lock(sb_internal#2); [ 378.433897] lock(sb_internal#2); [ 378.433898] [ 378.433898] *** DEADLOCK *** [ 378.433898] [ 378.433898] May be due to missing lock nesting notation [ 378.433898] [ 378.433899] 3 locks held by kworker/6:1/238: [ 378.433906] #0: (events){.+.+.+}, at: [<ffffffff810717d6>] process_one_work+0x136/0x5f0 [ 378.433911] #1: ((&(&ac->work)->work)){+.+...}, at: [<ffffffff810717d6>] process_one_work+0x136/0x5f0 [ 378.433929] #2: (sb_internal#2){.+.+..}, at: [<ffffffffa0042590>] do_async_commit+0x0/0x80 [btrfs] [ 378.433932] [ 378.433932] stack backtrace: [ 378.433935] Pid: 238, comm: kworker/6:1 Not tainted 3.6.0-rc2-ceph-00143-g995fc06 #1 [ 378.433936] Call Trace: [ 378.433941] [<ffffffff810b2032>] __lock_acquire+0x1512/0x1b90 [ 378.433944] [<ffffffff810ada73>] ? __bfs+0x23/0x270 [ 378.433961] [<ffffffffa0042b74>] ? start_transaction+0x124/0x430 [btrfs] [ 378.433964] [<ffffffff810b2c82>] lock_acquire+0xa2/0x140 [ 378.433980] [<ffffffffa0042b74>] ? start_transaction+0x124/0x430 [btrfs] [ 378.433982] [<ffffffff810b3546>] ? mark_held_locks+0x86/0x140 [ 378.433987] [<ffffffff8117dac6>] __sb_start_write+0xc6/0x1b0 [ 378.434003] [<ffffffffa0042b74>] ? start_transaction+0x124/0x430 [btrfs] [ 378.434019] [<ffffffffa0042b74>] ? start_transaction+0x124/0x430 [btrfs] [ 378.434022] [<ffffffff81172e75>] ? kmem_cache_alloc+0xb5/0x160 [ 378.434024] [<ffffffff81172f9b>] ? kmem_cache_free+0x7b/0x160 [ 378.434042] [<ffffffffa0058b48>] ? free_extent_state+0x58/0xd0 [btrfs] [ 378.434058] [<ffffffffa0042b74>] start_transaction+0x124/0x430 [btrfs] [ 378.434076] [<ffffffffa005940d>] ? __set_extent_bit+0x37d/0x4e0 [btrfs] [ 378.434092] [<ffffffffa0042ed5>] btrfs_join_transaction+0x15/0x20 [btrfs] [ 378.434109] [<ffffffffa00496b7>] cow_file_range+0x87/0x4a0 [btrfs] [ 378.434114] [<ffffffff81634c6b>] ? _raw_spin_unlock+0x2b/0x40 [ 378.434131] [<ffffffffa004a80c>] run_delalloc_range+0x34c/0x370 [btrfs] [ 378.434149] [<ffffffffa005cbb0>] __extent_writepage+0x5e0/0x770 [btrfs] [ 378.434152] [<ffffffff810b3546>] ? mark_held_locks+0x86/0x140 [ 378.434155] [<ffffffff8112aa5e>] ? find_get_pages_tag+0x2e/0x1c0 [ 378.434174] [<ffffffffa005cffa>] extent_write_cache_pages.isra.25.constprop.39+0x2ba/0x410 [btrfs] [ 378.434187] [<ffffffffa002f7cc>] ? btrfs_run_delayed_refs+0xac/0x550 [btrfs] [ 378.434190] [<ffffffff81196117>] ? igrab+0x27/0x70 [ 378.434208] [<ffffffffa005d389>] extent_writepages+0x49/0x60 [btrfs] [ 378.434224] [<ffffffffa0046a90>] ? btrfs_submit_direct+0x670/0x670 [btrfs] [ 378.434240] [<ffffffffa00444c8>] btrfs_writepages+0x28/0x30 [btrfs] [ 378.434243] [<ffffffff81136443>] do_writepages+0x23/0x40 [ 378.434247] [<ffffffff8112b839>] __filemap_fdatawrite_range+0x59/0x60 [ 378.434249] [<ffffffff8112c6ac>] filemap_flush+0x1c/0x20 [ 378.434266] [<ffffffffa0050b1e>] btrfs_start_delalloc_inodes+0xbe/0x200 [btrfs] [ 378.434270] [<ffffffff8132babd>] ? do_raw_spin_unlock+0x5d/0xb0 [ 378.434286] [<ffffffffa0041ebd>] btrfs_commit_transaction+0x44d/0xb20 [btrfs] [ 378.434290] [<ffffffff81079850>] ? __init_waitqueue_head+0x60/0x60 [ 378.434293] [<ffffffff810717d6>] ? process_one_work+0x136/0x5f0 [ 378.434308] [<ffffffffa00425f1>] do_async_commit+0x61/0x80 [btrfs] [ 378.434324] [<ffffffffa0042590>] ? btrfs_commit_transaction+0xb20/0xb20 [btrfs] [ 378.434327] [<ffffffff81071840>] process_one_work+0x1a0/0x5f0 [ 378.434330] [<ffffffff810717d6>] ? process_one_work+0x136/0x5f0 [ 378.434346] [<ffffffffa0042590>] ? btrfs_commit_transaction+0xb20/0xb20 [btrfs] [ 378.434350] [<ffffffff8107360d>] worker_thread+0x18d/0x4c0 [ 378.434354] [<ffffffff81073480>] ? manage_workers.isra.22+0x2c0/0x2c0 [ 378.434356] [<ffffffff810791ee>] kthread+0xae/0xc0 [ 378.434359] [<ffffffff810b379d>] ? trace_hardirqs_on+0xd/0x10 [ 378.434363] [<ffffffff8163e744>] kernel_thread_helper+0x4/0x10 [ 378.434366] [<ffffffff81635430>] ? retint_restore_args+0x13/0x13 [ 378.434368] [<ffffffff81079140>] ? flush_kthread_work+0x1a0/0x1a0 [ 378.434371] [<ffffffff8163e740>] ? gs_change+0x13/0x13 On Fri, 24 Aug 2012, Sage Weil wrote: > The freeze rwsem is taken by sb_start_intwrite() and dropped during the > commit_ or end_transaction(). In the async case, that happens in a worker > thread. Tell lockdep the calling thread is releasing ownership of the > rwsem and the async thread is picking it up. > > Josef and I worked out a more complicated solution that made the async > commit thread join and potentially get a later transaction, but it failed > my initial smoke test and Dave pointed out that XFS avoids the issue by > just telling lockdep what's up. This is much simpler. XFS does the same > thing in fs/xfs/xfs_aops.c. > > Signed-off-by: Sage Weil <sage@inktank.com> > --- > fs/btrfs/transaction.c | 16 ++++++++++++++++ > 1 files changed, 16 insertions(+), 0 deletions(-) > > diff --git a/fs/btrfs/transaction.c b/fs/btrfs/transaction.c > index 17be3de..efc41a5 100644 > --- a/fs/btrfs/transaction.c > +++ b/fs/btrfs/transaction.c > @@ -1228,6 +1228,14 @@ static void do_async_commit(struct work_struct *work) > struct btrfs_async_commit *ac = > container_of(work, struct btrfs_async_commit, work.work); > > + /* > + * We've got freeze protection passed with the transaction. > + * Tell lockdep about it. > + */ > + rwsem_acquire_read( > + &ac->root->fs_info->sb->s_writers.lock_map[SB_FREEZE_FS-1], > + 0, 1, _THIS_IP_); > + > btrfs_commit_transaction(ac->newtrans, ac->root); > kfree(ac); > } > @@ -1257,6 +1265,14 @@ int btrfs_commit_transaction_async(struct btrfs_trans_handle *trans, > atomic_inc(&cur_trans->use_count); > > btrfs_end_transaction(trans, root); > + > + /* > + * Tell lockdep we've released the freeze rwsem, since the > + * async commit thread will be the one to unlock it. > + */ > + rwsem_release(&root->fs_info->sb->s_writers.lock_map[SB_FREEZE_FS-1], > + 1, _THIS_IP_); > + > schedule_delayed_work(&ac->work, 0); > > /* wait for transaction to start and unblock */ > -- > 1.7.9 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > > -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, Aug 24, 2012 at 04:47:56PM -0600, Sage Weil wrote: > Sadly, now I hit another one: > Oh haha you need to set current->journal_info to the trans you have before you call commit_transaction in do_async_commit. Thanks, Josef -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Sun, 26 Aug 2012, Josef Bacik wrote: > On Fri, Aug 24, 2012 at 04:47:56PM -0600, Sage Weil wrote: > > Sadly, now I hit another one: > > > > Oh haha you need to set current->journal_info to the trans you have before you > call commit_transaction in do_async_commit. Thanks, Ah, makes sense. But now... [ 604.090449] ====================================================== [ 604.114819] [ INFO: possible circular locking dependency detected ] [ 604.139262] 3.6.0-rc2-ceph-00144-g463b030 #1 Not tainted [ 604.162193] ------------------------------------------------------- [ 604.186139] btrfs-cleaner/6669 is trying to acquire lock: [ 604.209555] (sb_internal#2){.+.+..}, at: [<ffffffffa0042b84>] start_transaction+0x124/0x430 [btrfs] [ 604.257100] [ 604.257100] but task is already holding lock: [ 604.300366] (&fs_info->cleanup_work_sem){.+.+..}, at: [<ffffffffa0048002>] btrfs_run_delayed_iputs+0x72/0x130 [btrfs] [ 604.352989] [ 604.352989] which lock already depends on the new lock. [ 604.352989] [ 604.427104] [ 604.427104] the existing dependency chain (in reverse order) is: [ 604.478493] [ 604.478493] -> #1 (&fs_info->cleanup_work_sem){.+.+..}: [ 604.529313] [<ffffffff810b2c82>] lock_acquire+0xa2/0x140 [ 604.559621] [<ffffffff81632b69>] down_read+0x39/0x4e [ 604.589382] [<ffffffffa004db98>] btrfs_lookup_dentry+0x218/0x550 [btrfs] [ 604.596161] btrfs: unlinked 1 orphans [ 604.675002] [<ffffffffa006aadd>] create_subvol+0x62d/0x690 [btrfs] [ 604.708859] [<ffffffffa006d666>] btrfs_mksubvol.isra.52+0x346/0x3a0 [btrfs] [ 604.772466] [<ffffffffa006d7f2>] btrfs_ioctl_snap_create_transid+0x132/0x190 [btrfs] [ 604.842245] [<ffffffffa006d8ae>] btrfs_ioctl_snap_create+0x5e/0x80 [btrfs] [ 604.912852] [<ffffffffa00708ae>] btrfs_ioctl+0x138e/0x1990 [btrfs] [ 604.951888] [<ffffffff8118e9b8>] do_vfs_ioctl+0x98/0x560 [ 604.989961] [<ffffffff8118ef11>] sys_ioctl+0x91/0xa0 [ 605.026628] [<ffffffff8163d569>] system_call_fastpath+0x16/0x1b [ 605.064404] [ 605.064404] -> #0 (sb_internal#2){.+.+..}: [ 605.126832] [<ffffffff810b25e8>] __lock_acquire+0x1ac8/0x1b90 [ 605.163671] [<ffffffff810b2c82>] lock_acquire+0xa2/0x140 [ 605.200228] [<ffffffff8117dac6>] __sb_start_write+0xc6/0x1b0 [ 605.236818] [<ffffffffa0042b84>] start_transaction+0x124/0x430 [btrfs] [ 605.274029] [<ffffffffa00431a3>] btrfs_start_transaction+0x13/0x20 [btrfs] [ 605.340520] [<ffffffffa004ccfa>] btrfs_evict_inode+0x19a/0x330 [btrfs] [ 605.378720] [<ffffffff811972c8>] evict+0xb8/0x1c0 [ 605.416057] [<ffffffff811974d5>] iput+0x105/0x210 [ 605.452373] [<ffffffffa0048082>] btrfs_run_delayed_iputs+0xf2/0x130 [btrfs] [ 605.521627] [<ffffffffa003b5e1>] cleaner_kthread+0xa1/0x120 [btrfs] [ 605.560520] [<ffffffff810791ee>] kthread+0xae/0xc0 [ 605.598094] [<ffffffff8163e744>] kernel_thread_helper+0x4/0x10 This dependency chain makes no sense to me.. one is a kernel thread and one is a syscall. [ 605.636499] [ 605.636499] other info that might help us debug this: [ 605.636499] [ 605.736504] Possible unsafe locking scenario: [ 605.736504] [ 605.801931] CPU0 CPU1 [ 605.835126] ---- ---- [ 605.867093] lock(&fs_info->cleanup_work_sem); [ 605.898594] lock(sb_internal#2); [ 605.931954] lock(&fs_info->cleanup_work_sem); [ 605.965359] lock(sb_internal#2); [ 605.994758] [ 605.994758] *** DEADLOCK *** [ 605.994758] [ 606.075281] 2 locks held by btrfs-cleaner/6669: [ 606.104528] #0: (&fs_info->cleaner_mutex){+.+...}, at: [<ffffffffa003b5d5>] cleaner_kthread+0x95/0x120 [btrfs] [ 606.165626] #1: (&fs_info->cleanup_work_sem){.+.+..}, at: [<ffffffffa0048002>] btrfs_run_delayed_iputs+0x72/0x130 [btrfs] [ 606.231297] [ 606.231297] stack backtrace: [ 606.287723] Pid: 6669, comm: btrfs-cleaner Not tainted 3.6.0-rc2-ceph-00144-g463b030 #1 [ 606.347823] Call Trace: [ 606.376184] [<ffffffff8162a77c>] print_circular_bug+0x1fb/0x20c [ 606.409243] [<ffffffff810b25e8>] __lock_acquire+0x1ac8/0x1b90 [ 606.441343] [<ffffffffa0042b84>] ? start_transaction+0x124/0x430 [btrfs] [ 606.474583] [<ffffffff810b2c82>] lock_acquire+0xa2/0x140 [ 606.505934] [<ffffffffa0042b84>] ? start_transaction+0x124/0x430 [btrfs] [ 606.539429] [<ffffffff8132babd>] ? do_raw_spin_unlock+0x5d/0xb0 [ 606.571719] [<ffffffff8117dac6>] __sb_start_write+0xc6/0x1b0 [ 606.603498] [<ffffffffa0042b84>] ? start_transaction+0x124/0x430 [btrfs] [ 606.637405] [<ffffffffa0042b84>] ? start_transaction+0x124/0x430 [btrfs] [ 606.670165] [<ffffffff81172e75>] ? kmem_cache_alloc+0xb5/0x160 [ 606.702144] [<ffffffffa0042b84>] start_transaction+0x124/0x430 [btrfs] [ 606.735562] [<ffffffffa00256a6>] ? block_rsv_add_bytes+0x56/0x80 [btrfs] [ 606.769861] [<ffffffffa00431a3>] btrfs_start_transaction+0x13/0x20 [btrfs] [ 606.804575] [<ffffffffa004ccfa>] btrfs_evict_inode+0x19a/0x330 [btrfs] [ 606.838756] [<ffffffff81634c6b>] ? _raw_spin_unlock+0x2b/0x40 [ 606.872010] [<ffffffff811972c8>] evict+0xb8/0x1c0 [ 606.903800] [<ffffffff811974d5>] iput+0x105/0x210 [ 606.935416] [<ffffffffa0048082>] btrfs_run_delayed_iputs+0xf2/0x130 [btrfs] [ 606.970510] [<ffffffffa003b5d5>] ? cleaner_kthread+0x95/0x120 [btrfs] [ 607.005648] [<ffffffffa003b5e1>] cleaner_kthread+0xa1/0x120 [btrfs] [ 607.040724] [<ffffffffa003b540>] ? btrfs_destroy_delayed_refs.isra.102+0x220/0x220 [btrfs] [ 607.104740] [<ffffffff810791ee>] kthread+0xae/0xc0 [ 607.137119] [<ffffffff810b379d>] ? trace_hardirqs_on+0xd/0x10 [ 607.169797] [<ffffffff8163e744>] kernel_thread_helper+0x4/0x10 [ 607.202472] [<ffffffff81635430>] ? retint_restore_args+0x13/0x13 [ 607.235884] [<ffffffff81079140>] ? flush_kthread_work+0x1a0/0x1a0 [ 607.268731] [<ffffffff8163e740>] ? gs_change+0x13/0x13 [ 1080.982408] INFO: task kworker/3:1:158 blocked for more than 120 seconds. [ 1081.016622] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1081.079081] kworker/3:1 D 0000000000000001 0 158 2 0x00000000 [ 1081.114673] ffff88020ccc1b60 0000000000000046 0000000000000282 ffff880210480e50 [ 1081.114676] ffff88020c825e20 ffff88020ccc1fd8 ffff88020ccc1fd8 ffff88020ccc1fd8 [ 1081.114679] ffff880225d1bec0 ffff88020c825e20 ffff88020ccc1b70 ffff880210480e00 [ 1081.114680] Call Trace: [ 1081.114687] [<ffffffff81633979>] schedule+0x29/0x70 [ 1081.114715] [<ffffffffa0056c35>] btrfs_start_ordered_extent+0x95/0x140 [btrfs] [ 1081.114720] [<ffffffff81079850>] ? __init_waitqueue_head+0x60/0x60 [ 1081.114743] [<ffffffffa0056e09>] btrfs_wait_ordered_extents+0x129/0x1f0 [btrfs] [ 1081.114760] [<ffffffffa0041ecc>] btrfs_commit_transaction+0x45c/0xb20 [btrfs] [ 1081.114765] [<ffffffff81079850>] ? __init_waitqueue_head+0x60/0x60 [ 1081.114770] [<ffffffff810717d6>] ? process_one_work+0x136/0x5f0 [ 1081.114786] [<ffffffffa0042606>] do_async_commit+0x76/0x90 [btrfs] [ 1081.114802] [<ffffffffa0042590>] ? btrfs_commit_transaction+0xb20/0xb20 [btrfs] [ 1081.114805] [<ffffffff81071840>] process_one_work+0x1a0/0x5f0 [ 1081.114808] [<ffffffff810717d6>] ? process_one_work+0x136/0x5f0 [ 1081.114815] [<ffffffff810653c8>] ? mod_timer+0x118/0x240 [ 1081.114832] [<ffffffffa0042590>] ? btrfs_commit_transaction+0xb20/0xb20 [btrfs] [ 1081.114838] [<ffffffff8107360d>] worker_thread+0x18d/0x4c0 [ 1081.114843] [<ffffffff81073480>] ? manage_workers.isra.22+0x2c0/0x2c0 [ 1081.114845] [<ffffffff810791ee>] kthread+0xae/0xc0 [ 1081.114849] [<ffffffff810b379d>] ? trace_hardirqs_on+0xd/0x10 [ 1081.114853] [<ffffffff8163e744>] kernel_thread_helper+0x4/0x10 [ 1081.114857] [<ffffffff81635430>] ? retint_restore_args+0x13/0x13 [ 1081.114859] [<ffffffff81079140>] ? flush_kthread_work+0x1a0/0x1a0 [ 1081.114862] [<ffffffff8163e740>] ? gs_change+0x13/0x13 -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Mon, Aug 27, 2012 at 04:05:37PM -0600, Sage Weil wrote: > On Sun, 26 Aug 2012, Josef Bacik wrote: > > On Fri, Aug 24, 2012 at 04:47:56PM -0600, Sage Weil wrote: > > > Sadly, now I hit another one: > > > > > > > Oh haha you need to set current->journal_info to the trans you have before you > > call commit_transaction in do_async_commit. Thanks, > > Ah, makes sense. But now... > Um so I don't think we need to be holding cleanup_work_sem() in run_delayed_iputs(), it's meant to protect the running of the orphan cleanup. So just remove it in btrfs_run_delayed_iputs() and see how that goes? Thanks, Josef -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/fs/btrfs/transaction.c b/fs/btrfs/transaction.c index 17be3de..efc41a5 100644 --- a/fs/btrfs/transaction.c +++ b/fs/btrfs/transaction.c @@ -1228,6 +1228,14 @@ static void do_async_commit(struct work_struct *work) struct btrfs_async_commit *ac = container_of(work, struct btrfs_async_commit, work.work); + /* + * We've got freeze protection passed with the transaction. + * Tell lockdep about it. + */ + rwsem_acquire_read( + &ac->root->fs_info->sb->s_writers.lock_map[SB_FREEZE_FS-1], + 0, 1, _THIS_IP_); + btrfs_commit_transaction(ac->newtrans, ac->root); kfree(ac); } @@ -1257,6 +1265,14 @@ int btrfs_commit_transaction_async(struct btrfs_trans_handle *trans, atomic_inc(&cur_trans->use_count); btrfs_end_transaction(trans, root); + + /* + * Tell lockdep we've released the freeze rwsem, since the + * async commit thread will be the one to unlock it. + */ + rwsem_release(&root->fs_info->sb->s_writers.lock_map[SB_FREEZE_FS-1], + 1, _THIS_IP_); + schedule_delayed_work(&ac->work, 0); /* wait for transaction to start and unblock */
The freeze rwsem is taken by sb_start_intwrite() and dropped during the commit_ or end_transaction(). In the async case, that happens in a worker thread. Tell lockdep the calling thread is releasing ownership of the rwsem and the async thread is picking it up. Josef and I worked out a more complicated solution that made the async commit thread join and potentially get a later transaction, but it failed my initial smoke test and Dave pointed out that XFS avoids the issue by just telling lockdep what's up. This is much simpler. XFS does the same thing in fs/xfs/xfs_aops.c. Signed-off-by: Sage Weil <sage@inktank.com> --- fs/btrfs/transaction.c | 16 ++++++++++++++++ 1 files changed, 16 insertions(+), 0 deletions(-)