Btrfs: sync log after logging new name
PATCH 2/2 Btrfs: sync log after logging new name
From: Filipe Manana <[email protected]>
When we add a new name for an inode which was logged in the current transaction, we update the inode in the log so that its new name and ancestors are added to the log. However when we do this we do not persist the log, so the changes remain in memory only, and as a consequence, any ancestors that were created in the current transaction are updated such that future calls to btrfs_inode_in_log() return true. This leads to a subsequent fsync against such new ancestor directories returning immediately, without persisting the log, therefore after a power failure the new ancestor directories do not exist, despite fsync being called against them explicitly.
Example:
$ mkfs.btrfs -f /dev/sdb $ mount /dev/sdb /mnt
$ mkdir /mnt/A $ mkdir /mnt/B $ mkdir /mnt/A/C $ touch /mnt/B/foo $ xfs_io -c "fsync" /mnt/B/foo $ ln /mnt/B/foo /mnt/A/C/foo $ xfs_io -c "fsync" /mnt/A <power failure>
After the power failure, directory "A" does not exist, despite the explicit fsync on it.
Instead of fixing this by changing the behaviour of the explicit fsync on directory "A" to persist the log instead of doing nothing, make the logging of the new file name (which happens when creating a hard link or renaming) persist the log. This approach not only is simpler, not requiring addition of new fields to the inode in memory structure, but also gives us the same behaviour as ext4, xfs and f2fs (possibly other filesystems too).
A test case for fstests follows soon.
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")
Reported-by Vijay Chidambaram <[email protected]>
Signed-off-by Filipe Manana <[email protected]>
--- fs/btrfs/inode.c | 92 ++++++++++++++++++++++++++++++++++++++++++++++------- fs/btrfs/tree-log.c | 48 ++++++++++++++++++++++++---- fs/btrfs/tree-log.h | 10 +++++- 3 files changed, 131 insertions(+), 19 deletions(-)
fs/btrfs/inode.c +80 -12
@@ -6692,6 +6692,8 @@ static int btrfs_link(struct dentry *old_dentry, struct inode *dir, drop_inode =1 ; }else {struct dentry *parent = dentry->d_parent; +int ret; + err =btrfs_update_inode (trans, root, inode);if (err) goto fail;
@@ -6705,7 +6707,12 @@ static int btrfs_link(struct dentry *old_dentry, struct inode *dir, goto fail; }d_instantiate (dentry, inode); -btrfs_log_new_name (trans,BTRFS_I (inode),NULL , parent); + ret =btrfs_log_new_name (trans,BTRFS_I (inode),NULL , parent, + true,NULL ); +if (ret ==BTRFS_NEED_TRANS_COMMIT ) { + err =btrfs_commit_transaction (trans); + trans =NULL ; + } } fail:
@@ -9445,14 +9452,21 @@ static int btrfs_rename_exchange(struct inode *old_dir,u64 new_idx =0 ;u64 root_objectid;int ret; -int ret2;bool root_log_pinned = false;bool dest_log_pinned = false; +struct btrfs_log_ctx ctx_root; +struct btrfs_log_ctx ctx_dest; +bool sync_log_root = false; +bool sync_log_dest = false; +bool commit_transaction = false;/* we only allow rename subvolume link between subvolumes */ if (old_ino !=BTRFS_FIRST_FREE_OBJECTID && root != dest)return -EXDEV ; +btrfs_init_log_ctx (&ctx_root, old_inode); +btrfs_init_log_ctx (&ctx_dest, new_inode); +/* close the race window with snapshot create/destroy ioctl */ if (old_ino ==BTRFS_FIRST_FREE_OBJECTID )down_read (&fs_info->subvol_sem);
@@ -9601,15 +9615,29 @@ static int btrfs_rename_exchange(struct inode *old_dir,if (root_log_pinned) { parent = new_dentry->d_parent; -btrfs_log_new_name (trans,BTRFS_I (old_inode),BTRFS_I (old_dir), - parent); + ret =btrfs_log_new_name (trans,BTRFS_I (old_inode), +BTRFS_I (old_dir), parent, + false, &ctx_root); +if (ret ==BTRFS_NEED_LOG_SYNC ) + sync_log_root = true; +else if (ret ==BTRFS_NEED_TRANS_COMMIT ) + commit_transaction = true; + ret =0 ;btrfs_end_log_trans (root); root_log_pinned = false; }if (dest_log_pinned) { - parent = old_dentry->d_parent; -btrfs_log_new_name (trans,BTRFS_I (new_inode),BTRFS_I (new_dir), - parent); +if (!commit_transaction) { + parent = old_dentry->d_parent; + ret =btrfs_log_new_name (trans,BTRFS_I (new_inode), +BTRFS_I (new_dir), parent, + false, &ctx_dest); +if (ret ==BTRFS_NEED_LOG_SYNC ) + sync_log_dest = true; +else if (ret ==BTRFS_NEED_TRANS_COMMIT ) + commit_transaction = true; + ret =0 ; + }btrfs_end_log_trans (dest); dest_log_pinned = false; }
@@ -9642,8 +9670,26 @@ static int btrfs_rename_exchange(struct inode *old_dir, dest_log_pinned = false; } } - ret2 =btrfs_end_transaction (trans); - ret = ret ? ret : ret2; +if (!ret && sync_log_root && !commit_transaction) { + ret =btrfs_sync_log (trans,BTRFS_I (old_inode)->root, + &ctx_root); +if (ret) + commit_transaction = true; + } +if (!ret && sync_log_dest && !commit_transaction) { + ret =btrfs_sync_log (trans,BTRFS_I (new_inode)->root, + &ctx_dest); +if (ret) + commit_transaction = true; + } +if (commit_transaction) { + ret =btrfs_commit_transaction (trans); + }else { +int ret2; + + ret2 =btrfs_end_transaction (trans); + ret = ret ? ret : ret2; + } out_notrans:if (new_ino ==BTRFS_FIRST_FREE_OBJECTID )up_read (&fs_info->subvol_sem);
@@ -9720,6 +9766,9 @@ static int btrfs_rename(struct inode *old_dir, struct dentry *old_dentry,int ret;u64 old_ino =btrfs_ino (BTRFS_I (old_inode));bool log_pinned = false; +struct btrfs_log_ctx ctx; +bool sync_log = false; +bool commit_transaction = false;if (btrfs_ino (BTRFS_I (new_dir)) ==BTRFS_EMPTY_SUBVOL_DIR_OBJECTID )return -EPERM ;
@@ -9878,8 +9927,15 @@ static int btrfs_rename(struct inode *old_dir, struct dentry *old_dentry,if (log_pinned) {struct dentry *parent = new_dentry->d_parent; -btrfs_log_new_name (trans,BTRFS_I (old_inode),BTRFS_I (old_dir), - parent); +btrfs_init_log_ctx (&ctx, old_inode); + ret =btrfs_log_new_name (trans,BTRFS_I (old_inode), +BTRFS_I (old_dir), parent, + false, &ctx); +if (ret ==BTRFS_NEED_LOG_SYNC ) + sync_log = true; +else if (ret ==BTRFS_NEED_TRANS_COMMIT ) + commit_transaction = true; + ret =0 ;btrfs_end_log_trans (root); log_pinned = false; }
@@ -9916,7 +9972,19 @@ static int btrfs_rename(struct inode *old_dir, struct dentry *old_dentry,btrfs_end_log_trans (root); log_pinned = false; } -btrfs_end_transaction (trans); +if (!ret && sync_log) { + ret =btrfs_sync_log (trans,BTRFS_I (old_inode)->root, &ctx); +if (ret) + commit_transaction = true; + } +if (commit_transaction) { + ret =btrfs_commit_transaction (trans); + }else { +int ret2; + + ret2 =btrfs_end_transaction (trans); + ret = ret ? ret : ret2; + } out_notrans:if (old_ino ==BTRFS_FIRST_FREE_OBJECTID )up_read (&fs_info->subvol_sem);
fs/btrfs/tree-log.c +42 -6
65 lines not on this page · raw message
fs/btrfs/tree-log.h +9 -1
@@ -71,8 +71,16 @@ void btrfs_record_unlink_dir(struct btrfs_trans_handle *trans, int for_rename);void btrfs_record_snapshot_destroy (struct btrfs_trans_handle *trans,struct btrfs_inode *dir); +/* Return values for btrfs_log_new_name() */ +enum { +BTRFS_DONT_NEED_TRANS_COMMIT , +BTRFS_NEED_TRANS_COMMIT , +BTRFS_DONT_NEED_LOG_SYNC , +BTRFS_NEED_LOG_SYNC , +};int btrfs_log_new_name (struct btrfs_trans_handle *trans,struct btrfs_inode *inode,struct btrfs_inode *old_dir, -struct dentry *parent); +struct dentry *parent, +bool sync_log,struct btrfs_log_ctx *ctx);#endif
Signature · 1 line
2.11.0
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>
There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
It's a qemu with 4 cpus and 2g of memory.
btrfs/011
[ 876.705586] watchdog: BUG: soft lockup - CPU#2 stuck for 77s! [od:12857] [ 876.708167] Modules linked in: btrfs libcrc32c xor zstd_decompresszstd_compress xxhash raid6_pq loop [ 876.710717] CPU: 2 PID: 12857 Comm: od Not tainted4.17.0-rc7-default+ #143 [ 876.712007] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),BIOS 1.0.0-prebuilt.qemu-project.org 04/01/2014 [ 876.713333] RIP: 0010:copy_user_generic_string+0x2c/0x40 [ 876.714586] RSP: 0018:ffffa7968344bc68 EFLAGS: 00010246 ORIG_RAX:ffffffffffffff13 [ 876.716411] RAX: 000055b128b4a370 RBX: 0000000000001000 RCX:0000000000000200 [ 876.718023] RDX: 0000000000000000 RSI: 000055b128b49370 RDI:ffff88bb1b600000 [ 876.719681] RBP: 0000000000001000 R08: ffff88bb1b600000 R09:ffff88bb00000000 [ 876.721568] R10: 0000000000001000 R11: 0000000000000030 R12:0000000000001000 [ 876.723123] R13: ffff88bb1b601000 R14: ffffa7968344be58 R15:0000000000000000 [ 876.724087] FS: 00007f417c596540(0000) GS:ffff88bb7fd00000(0000)knlGS:0000000000000000 [ 876.725165] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 876.726375] CR2: 000055c99ecbf298 CR3: 0000000068436000 CR4:00000000000006e0 [ 876.728080] Call Trace: [ 876.728849] copyin+0x22/0x30 [ 876.729704] iov_iter_copy_from_user_atomic+0x19a/0x410 [ 876.730789] ? ptep_clear_flush+0x40/0x40 [ 876.731391] btrfs_copy_from_user+0xab/0x120 [btrfs] [ 876.732058] __btrfs_buffered_write+0x367/0x710 [btrfs] [ 876.732747] btrfs_file_write_iter+0x2b8/0x5d0 [btrfs] [ 876.733507] ? touch_atime+0x27/0xb0 [ 876.734257] __vfs_write+0xd4/0x130 [ 876.734860] vfs_write+0xad/0x1e0 [ 876.735346] ksys_write+0x42/0x90 [ 876.735858] do_syscall_64+0x4f/0xe0 [ 876.736515] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 876.737690] RIP: 0033:0x7f417c0a3c94 [ 876.738565] RSP: 002b:00007ffc07af7c48 EFLAGS: 00000246 ORIG_RAX:0000000000000001 [ 876.740186] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:00007f417c0a3c94 [ 876.741263] RDX: 0000000000001000 RSI: 000055b128b49370 RDI:0000000000000001 [ 876.742819] RBP: 000055b128b49370 R08: 00007f417c372760 R09:0000000000000000 [ 876.744157] R10: 00000000000007d0 R11: 0000000000000246 R12:00007f417c372760 [ 876.745507] R13: 0000000000001000 R14: 00007f417c36d760 R15:0000000000001000 [ 1463.260071] INFO: task kworker/u8:12:9261 blocked for more than 480seconds. [ 1463.264100] Tainted: G L 4.17.0-rc7-default+#143 [ 1463.267639] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"disables this message. [ 1463.272086] kworker/u8:12 D 0 9261 2 0x80000000 [ 1463.274224] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 1463.275442] Call Trace: [ 1463.276221] ? __schedule+0x268/0x7f0 [ 1463.277348] schedule+0x33/0x90 [ 1463.278105] io_schedule+0x16/0x40 [ 1463.279053] wbt_wait+0x19b/0x310 [ 1463.280085] ? finish_wait+0x80/0x80 [ 1463.281153] blk_mq_make_request+0xba/0x6f0 [ 1463.282354] generic_make_request+0x173/0x3d0 [ 1463.283617] ? submit_bio+0x6c/0x140 [ 1463.284678] submit_bio+0x6c/0x140 [ 1463.285705] run_scheduled_bios+0x18e/0x480 [btrfs] [ 1463.287121] ? normal_work_helper+0x6a/0x330 [btrfs] [ 1463.288543] normal_work_helper+0x6a/0x330 [btrfs] [ 1463.289937] process_one_work+0x16d/0x380 [ 1463.291119] worker_thread+0x2e/0x380 [ 1463.292205] ? process_one_work+0x380/0x380 [ 1463.293420] kthread+0x111/0x130 [ 1463.294377] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1463.295782] ret_from_fork+0x1f/0x30 [ 1463.296827] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 1463.298874] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.300596] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.302784] btrfs-transacti D 0 5799 2 0x80000000 [ 1463.305441] Call Trace: [ 1463.306176] ? __schedule+0x268/0x7f0 [ 1463.307207] schedule+0x33/0x90 [ 1463.308134] wait_for_commit+0x2c/0x60 [btrfs] [ 1463.309359] ? finish_wait+0x80/0x80 [ 1463.310389] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 1463.311852] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1463.313209] transaction_kthread+0x151/0x180 [btrfs] [ 1463.314541] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 1463.316024] kthread+0x111/0x130 [ 1463.316868] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1463.318134] ret_from_fork+0x1f/0x30 [ 1463.319116] INFO: task btrfs:12859 blocked for more than 480 seconds. [ 1463.320402] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.321759] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.323299] btrfs D 0 12859 1 0x00000002 [ 1463.324395] Call Trace: [ 1463.325049] ? __schedule+0x268/0x7f0 [ 1463.325987] ? bit_wait+0x50/0x50 [ 1463.326835] schedule+0x33/0x90 [ 1463.327646] io_schedule+0x16/0x40 [ 1463.328556] bit_wait_io+0xd/0x50 [ 1463.329512] __wait_on_bit+0x42/0x80 [ 1463.330471] ? submit_bio+0x6c/0x140 [ 1463.331425] out_of_line_wait_on_bit+0x81/0x90 [ 1463.332581] ? init_wait_var_entry+0x40/0x40 [ 1463.333731] write_all_supers+0x3fe/0xe60 [btrfs] [ 1463.334947] btrfs_commit_transaction+0x5aa/0x920 [btrfs] [ 1463.336326] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1463.337588] btrfs_dev_replace_finishing+0x49e/0x520 [btrfs] [ 1463.338957] btrfs_dev_replace_start+0x42e/0x590 [btrfs] [ 1463.340188] btrfs_dev_replace_by_ioctl+0x35/0x60 [btrfs] [ 1463.341496] btrfs_ioctl+0x263f/0x3080 [btrfs] [ 1463.342609] ? alloc_set_pte+0x10a/0x3b0 [ 1463.343593] ? filemap_map_pages+0x127/0x2a0 [ 1463.344644] ? __handle_mm_fault+0x84e/0xc60 [ 1463.345704] ? do_vfs_ioctl+0x8d/0x5d0 [ 1463.346675] do_vfs_ioctl+0x8d/0x5d0 [ 1463.347629] ? handle_mm_fault+0xe6/0x220 [ 1463.348668] ksys_ioctl+0x3a/0x70 [ 1463.349575] __x64_sys_ioctl+0x16/0x20 [ 1463.350576] do_syscall_64+0x4f/0xe0 [ 1463.351529] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1463.352824] RIP: 0033:0x7f2105516967 [ 1463.353787] RSP: 002b:00007ffe5626bd98 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 1463.355689] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2105516967 [ 1463.357422] RDX: 00007ffe5626c1d0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1463.359146] RBP: 0000000000000004 R08: 00007f21067308c0 R09: 00007f21059fe2a0 [ 1463.360889] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe5626f368 [ 1463.362625] R13: 0000000000000000 R14: 0000000000000001 R15: 000056541bbfd2a0 [ 1463.364368] INFO: task btrfs:12861 blocked for more than 480 seconds. [ 1463.365917] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.367483] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.369453] btrfs D 0 12861 19330 0x00000000 [ 1463.370799] Call Trace: [ 1463.371492] ? __schedule+0x268/0x7f0 [ 1463.372453] schedule+0x33/0x90 [ 1463.373316] schedule_preempt_disabled+0x15/0x20 [ 1463.374472] __mutex_lock.isra.3+0x282/0x500 [ 1463.375562] ? btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1463.376915] btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1463.378245] btrfs_ioctl+0xe8b/0x3080 [btrfs] [ 1463.379172] ? mem_cgroup_commit_charge+0x54/0x470 [ 1463.380228] ? __alloc_pages_nodemask+0xb2/0x220 [ 1463.381341] ? get_mem_cgroup_from_mm+0x6f/0xc0 [ 1463.382309] ? __handle_mm_fault+0x65b/0xc60 [ 1463.383186] ? do_vfs_ioctl+0x8d/0x5d0 [ 1463.384010] do_vfs_ioctl+0x8d/0x5d0 [ 1463.384851] ? handle_mm_fault+0xe6/0x220 [ 1463.385808] ksys_ioctl+0x3a/0x70 [ 1463.386671] __x64_sys_ioctl+0x16/0x20 [ 1463.387635] do_syscall_64+0x4f/0xe0 [ 1463.388462] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1463.389714] RIP: 0033:0x7fa32c72d967 [ 1463.390643] RSP: 002b:00007fff8d37f398 EFLAGS: 00000202 ORIG_RAX: 0000000000000010 [ 1463.392538] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa32c72d967 [ 1463.394208] RDX: 00007fff8d37f3b0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1463.395913] RBP: 00007fff8d37f3b0 R08: 0000000000000003 R09: 00007fa32c6e1490 [ 1463.397332] R10: 0000000000000573 R11: 0000000000000202 R12: 0000000000000003 [ 1463.398682] R13: 00007fff8d382368 R14: 0000000000000000 R15: 0000000000000000 [ 1954.780101] INFO: task kworker/u8:12:9261 blocked for more than 480 seconds. [ 1954.783606] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.785435] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.787603] kworker/u8:12 D 0 9261 2 0x80000000 [ 1954.789838] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 1954.791942] Call Trace: [ 1954.792896] ? __schedule+0x268/0x7f0 [ 1954.794021] schedule+0x33/0x90 [ 1954.794781] io_schedule+0x16/0x40 [ 1954.795687] wbt_wait+0x19b/0x310 [ 1954.796663] ? finish_wait+0x80/0x80 [ 1954.797528] blk_mq_make_request+0xba/0x6f0 [ 1954.798404] generic_make_request+0x173/0x3d0 [ 1954.799477] ? submit_bio+0x6c/0x140 [ 1954.800427] submit_bio+0x6c/0x140 [ 1954.801008] run_scheduled_bios+0x18e/0x480 [btrfs] [ 1954.802338] ? normal_work_helper+0x6a/0x330 [btrfs] [ 1954.803289] normal_work_helper+0x6a/0x330 [btrfs] [ 1954.803931] process_one_work+0x16d/0x380 [ 1954.804493] worker_thread+0x2e/0x380 [ 1954.805014] ? process_one_work+0x380/0x380 [ 1954.805838] kthread+0x111/0x130 [ 1954.806679] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1954.807709] ret_from_fork+0x1f/0x30 [ 1954.808620] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 1954.810106] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.811695] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.813547] btrfs-transacti D 0 5799 2 0x80000000 [ 1954.814841] Call Trace: [ 1954.815397] ? __schedule+0x268/0x7f0 [ 1954.816027] schedule+0x33/0x90 [ 1954.816510] wait_for_commit+0x2c/0x60 [btrfs] [ 1954.817111] ? finish_wait+0x80/0x80 [ 1954.817918] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 1954.819088] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1954.820060] transaction_kthread+0x151/0x180 [btrfs] [ 1954.821122] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 1954.822076] kthread+0x111/0x130 [ 1954.822561] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1954.823215] ret_from_fork+0x1f/0x30 [ 1954.823724] INFO: task btrfs:12859 blocked for more than 480 seconds. [ 1954.824519] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.825355] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.827235] btrfs D 0 12859 1 0x00000002 [ 1954.828439] Call Trace: [ 1954.828977] ? __schedule+0x268/0x7f0 [ 1954.829776] ? bit_wait+0x50/0x50 [ 1954.830560] schedule+0x33/0x90 [ 1954.831467] io_schedule+0x16/0x40 [ 1954.832322] bit_wait_io+0xd/0x50 [ 1954.833109] __wait_on_bit+0x42/0x80 [ 1954.833931] ? submit_bio+0x6c/0x140 [ 1954.834754] out_of_line_wait_on_bit+0x81/0x90 [ 1954.835755] ? init_wait_var_entry+0x40/0x40 [ 1954.836717] write_all_supers+0x3fe/0xe60 [btrfs] [ 1954.837879] btrfs_commit_transaction+0x5aa/0x920 [btrfs] [ 1954.839093] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1954.840340] btrfs_dev_replace_finishing+0x49e/0x520 [btrfs] [ 1954.841258] btrfs_dev_replace_start+0x42e/0x590 [btrfs] [ 1954.841954] btrfs_dev_replace_by_ioctl+0x35/0x60 [btrfs] [ 1954.842657] btrfs_ioctl+0x263f/0x3080 [btrfs] [ 1954.843258] ? alloc_set_pte+0x10a/0x3b0 [ 1954.843800] ? filemap_map_pages+0x127/0x2a0 [ 1954.844382] ? __handle_mm_fault+0x84e/0xc60 [ 1954.844962] ? do_vfs_ioctl+0x8d/0x5d0 [ 1954.845557] do_vfs_ioctl+0x8d/0x5d0 [ 1954.846438] ? handle_mm_fault+0xe6/0x220 [ 1954.847293] ksys_ioctl+0x3a/0x70 [ 1954.847861] __x64_sys_ioctl+0x16/0x20 [ 1954.848398] do_syscall_64+0x4f/0xe0 [ 1954.848910] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1954.849589] RIP: 0033:0x7f2105516967 [ 1954.850272] RSP: 002b:00007ffe5626bd98 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 1954.851350] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2105516967 [ 1954.852212] RDX: 00007ffe5626c1d0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1954.853069] RBP: 0000000000000004 R08: 00007f21067308c0 R09: 00007f21059fe2a0 [ 1954.854601] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe5626f368 [ 1954.855957] R13: 0000000000000000 R14: 0000000000000001 R15: 000056541bbfd2a0 [ 1954.857196] INFO: task btrfs:12861 blocked for more than 480 seconds. [ 1954.858748] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.860162] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.861666] btrfs D 0 12861 19330 0x00000000 [ 1954.863070] Call Trace: [ 1954.863797] ? __schedule+0x268/0x7f0 [ 1954.864782] schedule+0x33/0x90 [ 1954.865511] schedule_preempt_disabled+0x15/0x20 [ 1954.866394] __mutex_lock.isra.3+0x282/0x500 [ 1954.867398] ? btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1954.869333] btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1954.870820] btrfs_ioctl+0xe8b/0x3080 [btrfs] [ 1954.874085] ? mem_cgroup_commit_charge+0x54/0x470 [ 1954.875247] ? __alloc_pages_nodemask+0xb2/0x220 [ 1954.875927] ? get_mem_cgroup_from_mm+0x6f/0xc0 [ 1954.876541] ? __handle_mm_fault+0x65b/0xc60 [ 1954.877126] ? do_vfs_ioctl+0x8d/0x5d0 [ 1954.877808] do_vfs_ioctl+0x8d/0x5d0 [ 1954.878421] ? handle_mm_fault+0xe6/0x220 [ 1954.878988] ksys_ioctl+0x3a/0x70 [ 1954.879476] __x64_sys_ioctl+0x16/0x20 [ 1954.880015] do_syscall_64+0x4f/0xe0 [ 1954.880533] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1954.881200] RIP: 0033:0x7fa32c72d967 [ 1954.882170] RSP: 002b:00007fff8d37f398 EFLAGS: 00000202 ORIG_RAX: 0000000000000010 [ 1954.884106] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa32c72d967 [ 1954.885784] RDX: 00007fff8d37f3b0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1954.886774] RBP: 00007fff8d37f3b0 R08: 0000000000000003 R09: 00007fa32c6e1490 [ 1954.887639] R10: 0000000000000573 R11: 0000000000000202 R12: 0000000000000003 [ 1954.888524] R13: 00007fff8d382368 R14: 0000000000000000 R15: 0000000000000000 [ 2446.300063] INFO: task kworker/u8:12:9261 blocked for more than 480 seconds. [ 2446.304546] Tainted: G L 4.17.0-rc7-default+ #143 [ 2446.308635] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2446.311008] kworker/u8:12 D 0 9261 2 0x80000000 [ 2446.312565] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 2446.314264] Call Trace: [ 2446.315048] ? __schedule+0x268/0x7f0 [ 2446.316167] schedule+0x33/0x90 [ 2446.317137] io_schedule+0x16/0x40 [ 2446.318178] wbt_wait+0x19b/0x310 [ 2446.319184] ? finish_wait+0x80/0x80 [ 2446.320270] blk_mq_make_request+0xba/0x6f0 [ 2446.321515] generic_make_request+0x173/0x3d0 [ 2446.322842] ? submit_bio+0x6c/0x140 [ 2446.323900] submit_bio+0x6c/0x140 [ 2446.324936] run_scheduled_bios+0x18e/0x480 [btrfs] [ 2446.326333] ? normal_work_helper+0x6a/0x330 [btrfs] [ 2446.327699] normal_work_helper+0x6a/0x330 [btrfs] [ 2446.328901] process_one_work+0x16d/0x380 [ 2446.329809] worker_thread+0x2e/0x380 [ 2446.330711] ? process_one_work+0x380/0x380 [ 2446.331858] kthread+0x111/0x130 [ 2446.332840] ? kthread_create_worker_on_cpu+0x50/0x50 [ 2446.333796] ret_from_fork+0x1f/0x30 [ 2446.334822] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 2446.336809] Tainted: G L 4.17.0-rc7-default+ #143 [ 2446.337828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2446.338864] btrfs-transacti D 0 5799 2 0x80000000 [ 2446.339562] Call Trace: [ 2446.339964] ? __schedule+0x268/0x7f0 [ 2446.340490] schedule+0x33/0x90 [ 2446.340973] wait_for_commit+0x2c/0x60 [btrfs] [ 2446.341905] ? finish_wait+0x80/0x80 [ 2446.342947] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 2446.344438] ? start_transaction+0xa1/0x3f0 [btrfs] [ 2446.345781] transaction_kthread+0x151/0x180 [btrfs] [ 2446.347136] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 2446.348645] kthread+0x111/0x130 [ 2446.349577] ? kthread_create_worker_on_cpu+0x50/0x50 [ 2446.350932] ret_from_fork+0x1f/0x30
Quoted 10 lines · David Sterba
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
Are you sure it's this patch?
On top of for-4.18 it didn't cause any problems here, plus the trace below has nothing to do with renames, hard links or fsync at all - everything seems stuck on waiting for IO from dev replace.
Quoted 296 lines
It's a qemu with 4 cpus and 2g of memory.
btrfs/011
[ 876.705586] watchdog: BUG: soft lockup - CPU#2 stuck for 77s! [od:12857] [ 876.708167] Modules linked in: btrfs libcrc32c xor zstd_decompresszstd_compress xxhash raid6_pq loop [ 876.710717] CPU: 2 PID: 12857 Comm: od Not tainted4.17.0-rc7-default+ #143 [ 876.712007] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),BIOS 1.0.0-prebuilt.qemu-project.org 04/01/2014 [ 876.713333] RIP: 0010:copy_user_generic_string+0x2c/0x40 [ 876.714586] RSP: 0018:ffffa7968344bc68 EFLAGS: 00010246 ORIG_RAX:ffffffffffffff13 [ 876.716411] RAX: 000055b128b4a370 RBX: 0000000000001000 RCX:0000000000000200 [ 876.718023] RDX: 0000000000000000 RSI: 000055b128b49370 RDI:ffff88bb1b600000 [ 876.719681] RBP: 0000000000001000 R08: ffff88bb1b600000 R09:ffff88bb00000000 [ 876.721568] R10: 0000000000001000 R11: 0000000000000030 R12:0000000000001000 [ 876.723123] R13: ffff88bb1b601000 R14: ffffa7968344be58 R15:0000000000000000 [ 876.724087] FS: 00007f417c596540(0000) GS:ffff88bb7fd00000(0000)knlGS:0000000000000000 [ 876.725165] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 876.726375] CR2: 000055c99ecbf298 CR3: 0000000068436000 CR4:00000000000006e0 [ 876.728080] Call Trace: [ 876.728849] copyin+0x22/0x30 [ 876.729704] iov_iter_copy_from_user_atomic+0x19a/0x410 [ 876.730789] ? ptep_clear_flush+0x40/0x40 [ 876.731391] btrfs_copy_from_user+0xab/0x120 [btrfs] [ 876.732058] __btrfs_buffered_write+0x367/0x710 [btrfs] [ 876.732747] btrfs_file_write_iter+0x2b8/0x5d0 [btrfs] [ 876.733507] ? touch_atime+0x27/0xb0 [ 876.734257] __vfs_write+0xd4/0x130 [ 876.734860] vfs_write+0xad/0x1e0 [ 876.735346] ksys_write+0x42/0x90 [ 876.735858] do_syscall_64+0x4f/0xe0 [ 876.736515] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 876.737690] RIP: 0033:0x7f417c0a3c94 [ 876.738565] RSP: 002b:00007ffc07af7c48 EFLAGS: 00000246 ORIG_RAX:0000000000000001 [ 876.740186] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:00007f417c0a3c94 [ 876.741263] RDX: 0000000000001000 RSI: 000055b128b49370 RDI:0000000000000001 [ 876.742819] RBP: 000055b128b49370 R08: 00007f417c372760 R09:0000000000000000 [ 876.744157] R10: 00000000000007d0 R11: 0000000000000246 R12:00007f417c372760 [ 876.745507] R13: 0000000000001000 R14: 00007f417c36d760 R15:0000000000001000 [ 1463.260071] INFO: task kworker/u8:12:9261 blocked for more than 480seconds. [ 1463.264100] Tainted: G L 4.17.0-rc7-default+#143 [ 1463.267639] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"disables this message. [ 1463.272086] kworker/u8:12 D 0 9261 2 0x80000000 [ 1463.274224] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 1463.275442] Call Trace: [ 1463.276221] ? __schedule+0x268/0x7f0 [ 1463.277348] schedule+0x33/0x90 [ 1463.278105] io_schedule+0x16/0x40 [ 1463.279053] wbt_wait+0x19b/0x310 [ 1463.280085] ? finish_wait+0x80/0x80 [ 1463.281153] blk_mq_make_request+0xba/0x6f0 [ 1463.282354] generic_make_request+0x173/0x3d0 [ 1463.283617] ? submit_bio+0x6c/0x140 [ 1463.284678] submit_bio+0x6c/0x140 [ 1463.285705] run_scheduled_bios+0x18e/0x480 [btrfs] [ 1463.287121] ? normal_work_helper+0x6a/0x330 [btrfs] [ 1463.288543] normal_work_helper+0x6a/0x330 [btrfs] [ 1463.289937] process_one_work+0x16d/0x380 [ 1463.291119] worker_thread+0x2e/0x380 [ 1463.292205] ? process_one_work+0x380/0x380 [ 1463.293420] kthread+0x111/0x130 [ 1463.294377] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1463.295782] ret_from_fork+0x1f/0x30 [ 1463.296827] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 1463.298874] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.300596] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.302784] btrfs-transacti D 0 5799 2 0x80000000 [ 1463.305441] Call Trace: [ 1463.306176] ? __schedule+0x268/0x7f0 [ 1463.307207] schedule+0x33/0x90 [ 1463.308134] wait_for_commit+0x2c/0x60 [btrfs] [ 1463.309359] ? finish_wait+0x80/0x80 [ 1463.310389] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 1463.311852] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1463.313209] transaction_kthread+0x151/0x180 [btrfs] [ 1463.314541] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 1463.316024] kthread+0x111/0x130 [ 1463.316868] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1463.318134] ret_from_fork+0x1f/0x30 [ 1463.319116] INFO: task btrfs:12859 blocked for more than 480 seconds. [ 1463.320402] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.321759] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.323299] btrfs D 0 12859 1 0x00000002 [ 1463.324395] Call Trace: [ 1463.325049] ? __schedule+0x268/0x7f0 [ 1463.325987] ? bit_wait+0x50/0x50 [ 1463.326835] schedule+0x33/0x90 [ 1463.327646] io_schedule+0x16/0x40 [ 1463.328556] bit_wait_io+0xd/0x50 [ 1463.329512] __wait_on_bit+0x42/0x80 [ 1463.330471] ? submit_bio+0x6c/0x140 [ 1463.331425] out_of_line_wait_on_bit+0x81/0x90 [ 1463.332581] ? init_wait_var_entry+0x40/0x40 [ 1463.333731] write_all_supers+0x3fe/0xe60 [btrfs] [ 1463.334947] btrfs_commit_transaction+0x5aa/0x920 [btrfs] [ 1463.336326] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1463.337588] btrfs_dev_replace_finishing+0x49e/0x520 [btrfs] [ 1463.338957] btrfs_dev_replace_start+0x42e/0x590 [btrfs] [ 1463.340188] btrfs_dev_replace_by_ioctl+0x35/0x60 [btrfs] [ 1463.341496] btrfs_ioctl+0x263f/0x3080 [btrfs] [ 1463.342609] ? alloc_set_pte+0x10a/0x3b0 [ 1463.343593] ? filemap_map_pages+0x127/0x2a0 [ 1463.344644] ? __handle_mm_fault+0x84e/0xc60 [ 1463.345704] ? do_vfs_ioctl+0x8d/0x5d0 [ 1463.346675] do_vfs_ioctl+0x8d/0x5d0 [ 1463.347629] ? handle_mm_fault+0xe6/0x220 [ 1463.348668] ksys_ioctl+0x3a/0x70 [ 1463.349575] __x64_sys_ioctl+0x16/0x20 [ 1463.350576] do_syscall_64+0x4f/0xe0 [ 1463.351529] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1463.352824] RIP: 0033:0x7f2105516967 [ 1463.353787] RSP: 002b:00007ffe5626bd98 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 1463.355689] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2105516967 [ 1463.357422] RDX: 00007ffe5626c1d0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1463.359146] RBP: 0000000000000004 R08: 00007f21067308c0 R09: 00007f21059fe2a0 [ 1463.360889] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe5626f368 [ 1463.362625] R13: 0000000000000000 R14: 0000000000000001 R15: 000056541bbfd2a0 [ 1463.364368] INFO: task btrfs:12861 blocked for more than 480 seconds. [ 1463.365917] Tainted: G L 4.17.0-rc7-default+ #143 [ 1463.367483] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1463.369453] btrfs D 0 12861 19330 0x00000000 [ 1463.370799] Call Trace: [ 1463.371492] ? __schedule+0x268/0x7f0 [ 1463.372453] schedule+0x33/0x90 [ 1463.373316] schedule_preempt_disabled+0x15/0x20 [ 1463.374472] __mutex_lock.isra.3+0x282/0x500 [ 1463.375562] ? btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1463.376915] btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1463.378245] btrfs_ioctl+0xe8b/0x3080 [btrfs] [ 1463.379172] ? mem_cgroup_commit_charge+0x54/0x470 [ 1463.380228] ? __alloc_pages_nodemask+0xb2/0x220 [ 1463.381341] ? get_mem_cgroup_from_mm+0x6f/0xc0 [ 1463.382309] ? __handle_mm_fault+0x65b/0xc60 [ 1463.383186] ? do_vfs_ioctl+0x8d/0x5d0 [ 1463.384010] do_vfs_ioctl+0x8d/0x5d0 [ 1463.384851] ? handle_mm_fault+0xe6/0x220 [ 1463.385808] ksys_ioctl+0x3a/0x70 [ 1463.386671] __x64_sys_ioctl+0x16/0x20 [ 1463.387635] do_syscall_64+0x4f/0xe0 [ 1463.388462] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1463.389714] RIP: 0033:0x7fa32c72d967 [ 1463.390643] RSP: 002b:00007fff8d37f398 EFLAGS: 00000202 ORIG_RAX: 0000000000000010 [ 1463.392538] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa32c72d967 [ 1463.394208] RDX: 00007fff8d37f3b0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1463.395913] RBP: 00007fff8d37f3b0 R08: 0000000000000003 R09: 00007fa32c6e1490 [ 1463.397332] R10: 0000000000000573 R11: 0000000000000202 R12: 0000000000000003 [ 1463.398682] R13: 00007fff8d382368 R14: 0000000000000000 R15: 0000000000000000 [ 1954.780101] INFO: task kworker/u8:12:9261 blocked for more than 480 seconds. [ 1954.783606] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.785435] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.787603] kworker/u8:12 D 0 9261 2 0x80000000 [ 1954.789838] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 1954.791942] Call Trace: [ 1954.792896] ? __schedule+0x268/0x7f0 [ 1954.794021] schedule+0x33/0x90 [ 1954.794781] io_schedule+0x16/0x40 [ 1954.795687] wbt_wait+0x19b/0x310 [ 1954.796663] ? finish_wait+0x80/0x80 [ 1954.797528] blk_mq_make_request+0xba/0x6f0 [ 1954.798404] generic_make_request+0x173/0x3d0 [ 1954.799477] ? submit_bio+0x6c/0x140 [ 1954.800427] submit_bio+0x6c/0x140 [ 1954.801008] run_scheduled_bios+0x18e/0x480 [btrfs] [ 1954.802338] ? normal_work_helper+0x6a/0x330 [btrfs] [ 1954.803289] normal_work_helper+0x6a/0x330 [btrfs] [ 1954.803931] process_one_work+0x16d/0x380 [ 1954.804493] worker_thread+0x2e/0x380 [ 1954.805014] ? process_one_work+0x380/0x380 [ 1954.805838] kthread+0x111/0x130 [ 1954.806679] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1954.807709] ret_from_fork+0x1f/0x30 [ 1954.808620] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 1954.810106] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.811695] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.813547] btrfs-transacti D 0 5799 2 0x80000000 [ 1954.814841] Call Trace: [ 1954.815397] ? __schedule+0x268/0x7f0 [ 1954.816027] schedule+0x33/0x90 [ 1954.816510] wait_for_commit+0x2c/0x60 [btrfs] [ 1954.817111] ? finish_wait+0x80/0x80 [ 1954.817918] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 1954.819088] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1954.820060] transaction_kthread+0x151/0x180 [btrfs] [ 1954.821122] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 1954.822076] kthread+0x111/0x130 [ 1954.822561] ? kthread_create_worker_on_cpu+0x50/0x50 [ 1954.823215] ret_from_fork+0x1f/0x30 [ 1954.823724] INFO: task btrfs:12859 blocked for more than 480 seconds. [ 1954.824519] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.825355] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.827235] btrfs D 0 12859 1 0x00000002 [ 1954.828439] Call Trace: [ 1954.828977] ? __schedule+0x268/0x7f0 [ 1954.829776] ? bit_wait+0x50/0x50 [ 1954.830560] schedule+0x33/0x90 [ 1954.831467] io_schedule+0x16/0x40 [ 1954.832322] bit_wait_io+0xd/0x50 [ 1954.833109] __wait_on_bit+0x42/0x80 [ 1954.833931] ? submit_bio+0x6c/0x140 [ 1954.834754] out_of_line_wait_on_bit+0x81/0x90 [ 1954.835755] ? init_wait_var_entry+0x40/0x40 [ 1954.836717] write_all_supers+0x3fe/0xe60 [btrfs] [ 1954.837879] btrfs_commit_transaction+0x5aa/0x920 [btrfs] [ 1954.839093] ? start_transaction+0xa1/0x3f0 [btrfs] [ 1954.840340] btrfs_dev_replace_finishing+0x49e/0x520 [btrfs] [ 1954.841258] btrfs_dev_replace_start+0x42e/0x590 [btrfs] [ 1954.841954] btrfs_dev_replace_by_ioctl+0x35/0x60 [btrfs] [ 1954.842657] btrfs_ioctl+0x263f/0x3080 [btrfs] [ 1954.843258] ? alloc_set_pte+0x10a/0x3b0 [ 1954.843800] ? filemap_map_pages+0x127/0x2a0 [ 1954.844382] ? __handle_mm_fault+0x84e/0xc60 [ 1954.844962] ? do_vfs_ioctl+0x8d/0x5d0 [ 1954.845557] do_vfs_ioctl+0x8d/0x5d0 [ 1954.846438] ? handle_mm_fault+0xe6/0x220 [ 1954.847293] ksys_ioctl+0x3a/0x70 [ 1954.847861] __x64_sys_ioctl+0x16/0x20 [ 1954.848398] do_syscall_64+0x4f/0xe0 [ 1954.848910] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1954.849589] RIP: 0033:0x7f2105516967 [ 1954.850272] RSP: 002b:00007ffe5626bd98 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 1954.851350] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2105516967 [ 1954.852212] RDX: 00007ffe5626c1d0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1954.853069] RBP: 0000000000000004 R08: 00007f21067308c0 R09: 00007f21059fe2a0 [ 1954.854601] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe5626f368 [ 1954.855957] R13: 0000000000000000 R14: 0000000000000001 R15: 000056541bbfd2a0 [ 1954.857196] INFO: task btrfs:12861 blocked for more than 480 seconds. [ 1954.858748] Tainted: G L 4.17.0-rc7-default+ #143 [ 1954.860162] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.861666] btrfs D 0 12861 19330 0x00000000 [ 1954.863070] Call Trace: [ 1954.863797] ? __schedule+0x268/0x7f0 [ 1954.864782] schedule+0x33/0x90 [ 1954.865511] schedule_preempt_disabled+0x15/0x20 [ 1954.866394] __mutex_lock.isra.3+0x282/0x500 [ 1954.867398] ? btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1954.869333] btrfs_dev_replace_cancel+0x3f/0x270 [btrfs] [ 1954.870820] btrfs_ioctl+0xe8b/0x3080 [btrfs] [ 1954.874085] ? mem_cgroup_commit_charge+0x54/0x470 [ 1954.875247] ? __alloc_pages_nodemask+0xb2/0x220 [ 1954.875927] ? get_mem_cgroup_from_mm+0x6f/0xc0 [ 1954.876541] ? __handle_mm_fault+0x65b/0xc60 [ 1954.877126] ? do_vfs_ioctl+0x8d/0x5d0 [ 1954.877808] do_vfs_ioctl+0x8d/0x5d0 [ 1954.878421] ? handle_mm_fault+0xe6/0x220 [ 1954.878988] ksys_ioctl+0x3a/0x70 [ 1954.879476] __x64_sys_ioctl+0x16/0x20 [ 1954.880015] do_syscall_64+0x4f/0xe0 [ 1954.880533] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 1954.881200] RIP: 0033:0x7fa32c72d967 [ 1954.882170] RSP: 002b:00007fff8d37f398 EFLAGS: 00000202 ORIG_RAX: 0000000000000010 [ 1954.884106] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fa32c72d967 [ 1954.885784] RDX: 00007fff8d37f3b0 RSI: 00000000ca289435 RDI: 0000000000000003 [ 1954.886774] RBP: 00007fff8d37f3b0 R08: 0000000000000003 R09: 00007fa32c6e1490 [ 1954.887639] R10: 0000000000000573 R11: 0000000000000202 R12: 0000000000000003 [ 1954.888524] R13: 00007fff8d382368 R14: 0000000000000000 R15: 0000000000000000 [ 2446.300063] INFO: task kworker/u8:12:9261 blocked for more than 480 seconds. [ 2446.304546] Tainted: G L 4.17.0-rc7-default+ #143 [ 2446.308635] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2446.311008] kworker/u8:12 D 0 9261 2 0x80000000 [ 2446.312565] Workqueue: btrfs-submit btrfs_submit_helper [btrfs] [ 2446.314264] Call Trace: [ 2446.315048] ? __schedule+0x268/0x7f0 [ 2446.316167] schedule+0x33/0x90 [ 2446.317137] io_schedule+0x16/0x40 [ 2446.318178] wbt_wait+0x19b/0x310 [ 2446.319184] ? finish_wait+0x80/0x80 [ 2446.320270] blk_mq_make_request+0xba/0x6f0 [ 2446.321515] generic_make_request+0x173/0x3d0 [ 2446.322842] ? submit_bio+0x6c/0x140 [ 2446.323900] submit_bio+0x6c/0x140 [ 2446.324936] run_scheduled_bios+0x18e/0x480 [btrfs] [ 2446.326333] ? normal_work_helper+0x6a/0x330 [btrfs] [ 2446.327699] normal_work_helper+0x6a/0x330 [btrfs] [ 2446.328901] process_one_work+0x16d/0x380 [ 2446.329809] worker_thread+0x2e/0x380 [ 2446.330711] ? process_one_work+0x380/0x380 [ 2446.331858] kthread+0x111/0x130 [ 2446.332840] ? kthread_create_worker_on_cpu+0x50/0x50 [ 2446.333796] ret_from_fork+0x1f/0x30 [ 2446.334822] INFO: task btrfs-transacti:5799 blocked for more than 480 seconds. [ 2446.336809] Tainted: G L 4.17.0-rc7-default+ #143 [ 2446.337828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2446.338864] btrfs-transacti D 0 5799 2 0x80000000 [ 2446.339562] Call Trace: [ 2446.339964] ? __schedule+0x268/0x7f0 [ 2446.340490] schedule+0x33/0x90 [ 2446.340973] wait_for_commit+0x2c/0x60 [btrfs] [ 2446.341905] ? finish_wait+0x80/0x80 [ 2446.342947] btrfs_commit_transaction+0x18c/0x920 [btrfs] [ 2446.344438] ? start_transaction+0xa1/0x3f0 [btrfs] [ 2446.345781] transaction_kthread+0x151/0x180 [btrfs] [ 2446.347136] ? btrfs_cleanup_transaction+0x4e0/0x4e0 [btrfs] [ 2446.348645] kthread+0x111/0x130 [ 2446.349577] ? kthread_create_worker_on_cpu+0x50/0x50 [ 2446.350932] ret_from_fork+0x1f/0x30
Quoted 12 lines · Filipe Manana
Quoted 10 lines · David Sterba
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
Quoted 4 lines
Are you sure it's this patch?
On top of for-4.18 it didn't cause any problems here, plus the trace below has nothing to do with renames, hard links or fsync at all - everything seems stuck on waiting for IO from dev replace.
It was a false alert, sorry. Strange that the warnings appeared only in the VM running both patches and not otherwise.
Though the test did not directly use rename, the possible error scenario I had in mind was some leftover from locking, error handling or state that blocked umount of 011.
Quoted 18 lines · David Sterba
Quoted 12 lines · Filipe Manana
Quoted 10 lines · David Sterba
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
Quoted 4 lines
Are you sure it's this patch?
On top of for-4.18 it didn't cause any problems here, plus the trace below has nothing to do with renames, hard links or fsync at all - everything seems stuck on waiting for IO from dev replace.
Quoted 6 lines
It was a false alert, sorry. Strange that the warnings appeared only in the VM running both patches and not otherwise.
Though the test did not directly use rename, the possible error scenario I had in mind was some leftover from locking, error handling or state that blocked umount of 011.
Dave, are you sending this in for 4.19? I don't see it in your first pull request.
Quoted 22 lines · Omar Sandoval
Quoted 21 lines · David Sterba
Quoted 12 lines · Filipe Manana
Quoted 10 lines · David Sterba
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
Quoted 4 lines
Are you sure it's this patch?
On top of for-4.18 it didn't cause any problems here, plus the trace below has nothing to do with renames, hard links or fsync at all - everything seems stuck on waiting for IO from dev replace.It was a false alert, sorry. Strange that the warnings appeared only in the VM running both patches and not otherwise.
Quoted 6 lines
Quoted 3 lines
Though the test did not directly use rename, the possible error scenario I had in mind was some leftover from locking, error handling or state that blocked umount of 011.
Dave, are you sending this in for 4.19? I don't see it in your first pull request.
Will send it in 2nd pull for 4.19. The patch is 2 months old and I don't remember where it was lost on the way. I had some suspicions but turned out to be false. Thanks for the reminder.
Quoted 23 lines · David Sterba
Quoted 22 lines · Omar Sandoval
Quoted 21 lines · David Sterba
Quoted 12 lines · Filipe Manana
Quoted 10 lines · David Sterba
Quoted 4 lines · On Mon, Jun 11, 2018 at 07:24:28PM +0100, [email protected] wrote:
From: Filipe Manana <[email protected]>
Fixes 12fcfd22fe5b ("Btrfs: tree logging unlink/rename fixes")Reported-by Vijay Chidambaram <[email protected]>Signed-off-by Filipe Manana <[email protected]>There are some warnings and possible lock up caused by this patch, the 1/2 alone is ok but 1/2 + 2/2 leads to the following warnings. I checked twice, the patch base was the pull request ie. without any other 4.18 stuff.
Quoted 4 lines
Are you sure it's this patch?
On top of for-4.18 it didn't cause any problems here, plus the trace below has nothing to do with renames, hard links or fsync at all - everything seems stuck on waiting for IO from dev replace.It was a false alert, sorry. Strange that the warnings appeared only in the VM running both patches and not otherwise.
Quoted 6 lines
Quoted 6 lines
Quoted 3 lines
Though the test did not directly use rename, the possible error scenario I had in mind was some leftover from locking, error handling or state that blocked umount of 011.
Dave, are you sending this in for 4.19? I don't see it in your first pull request.
In another thread, related to the first patch in the series iirc, I specifically asked to not merge it.
That's because I run twice (in the long period of nearly 2 months now) into a hang which could be caused
by this patch. The traces were weird and only contained inexact lines that showed only the transaction kthread
waiting forever on transaction commit.
I recently found that I have hardware problems that were causing issues with qemu (stalls, ocassional crashes)
so I'm hoping that's the cause but I still need to test it with long stress tests on good hardware.
I don't mind getting it to linux-next in the meanwhile, but for 4.19 I would prefer to not include yet.
Quoted 4 lines
Will send it in 2nd pull for 4.19. The patch is 2 months old and I don't remember where it was lost on the way. I had some suspicions but turned out to be false. Thanks for the reminder.
Quoted 8 lines · Filipe Manana
Quoted 5 lines
Quoted 5 lines
Quoted 2 lines
I had in mind was some leftover from locking, error handling or state that blocked umount of 011.
Dave, are you sending this in for 4.19? I don't see it in your first pull request.
In another thread, related to the first patch in the series iirc, I specifically asked to not merge it.
Ah right, I remember now. Yesterday I only checked mails in the thread of the patch and the mail was marked as 'applied to some branch'.
Quoted 6 lines
That's because I run twice (in the long period of nearly 2 months now) into a hang which could be caused
by this patch. The traces were weird and only contained inexact lines that showed only the transaction kthread
waiting forever on transaction commit.
Quoted 7 lines
I recently found that I have hardware problems that were causing issues with qemu (stalls, ocassional crashes)
so I'm hoping that's the cause but I still need to test it with long stress tests on good hardware.I don't mind getting it to linux-next in the meanwhile, but for 4.19 I would prefer to not include yet.
Ok, understood.