* btrfs reflink take too long time(21s)
@ 2021-11-03 10:41 Wang Yugui
2021-11-05 13:08 ` Wang Yugui
0 siblings, 1 reply; 5+ messages in thread
From: Wang Yugui @ 2021-11-03 10:41 UTC (permalink / raw)
To: linux-btrfs
Hi,
fstests(generic/297) report that btrfs reflink take too long time(21s)
reflink didn't stop in time, n=17179869184 t=21
reproduce frequency:
DUP metadata(mkfs.btrfs -m DUP): about 20%
single metadata(mkfs.btrfs -m single): < 3%
kernel/btrfs: 5.15
I just begin to test DUP metadata(mkfs.btrfs -m DUP) recently,
so it may NOT a problem introduced in 5.15
DUP metadata is useful to reproduce.
--- a/tests/generic/297
+++ b/tests/generic/297
@@ -29,7 +32,7 @@ _require_command "$TIMEOUT_PROG" "timeout"
test $FSTYP == "nfs" && _notrun "NFS can't interrupt clone operations"
echo "Format and mount"
-_scratch_mkfs > $seqres.full 2>&1
+_scratch_mkfs -m DUP > $seqres.full 2>&1
_scratch_mount >> $seqres.full 2>&1
testdir=$SCRATCH_MNT/test-$seq
I used 'hung_task_timeout_secs=2' to gather some call trace
[ 572.942085] INFO: task btrfs-transacti:8203 blocked for more than 2 seconds.
[ 572.943264] Not tainted 5.15.0-1.el7.x86_64 #1
[ 572.944391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 572.945516] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
[ 572.946653] Call Trace:
[ 572.947789] __schedule+0x37c/0x7a0
[ 572.948928] schedule+0x3a/0xa0
[ 572.950066] btrfs_commit_transaction+0x200/0xac0 [btrfs]
[ 572.951284] ? finish_wait+0x80/0x80
[ 572.952422] transaction_kthread+0x13d/0x190 [btrfs]
[ 572.953613] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[ 572.954807] kthread+0x118/0x140
[ 572.955954] ? set_kthread_struct+0x40/0x40
[ 572.957091] ret_from_fork+0x1f/0x30
[ 572.958231] INFO: task xfs_io:8398 blocked for more than 2 seconds.
[ 572.959385] Not tainted 5.15.0-1.el7.x86_64 #1
[ 572.960539] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 572.961723] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
[ 572.962873] Call Trace:
[ 572.964006] __schedule+0x37c/0x7a0
[ 572.965142] schedule+0x3a/0xa0
[ 572.966277] wait_current_trans+0xc2/0x120 [btrfs]
[ 572.967475] ? finish_wait+0x80/0x80
[ 572.968595] start_transaction+0x490/0x590 [btrfs]
[ 572.969745] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
[ 572.970898] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
[ 572.972051] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
[ 572.973180] btrfs_clone+0x796/0x7f0 [btrfs]
[ 572.974366] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
[ 572.975552] btrfs_clone_files+0xfc/0x150 [btrfs]
[ 572.976918] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
[ 572.978111] do_clone_file_range+0xea/0x230
[ 572.979250] vfs_clone_file_range+0x37/0x110
[ 572.980384] ioctl_file_clone+0x7d/0xb0
[ 572.981512] do_vfs_ioctl+0x47d/0x7f0
[ 572.982639] __x64_sys_ioctl+0x62/0xc0
[ 572.983766] do_syscall_64+0x37/0x80
[ 572.984869] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 572.985958] RIP: 0033:0x7fe48946c62b
[ 572.987037] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 572.988145] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
[ 572.989259] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
[ 572.990382] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
[ 572.991501] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
[ 572.992621] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
[ 575.054091] INFO: task btrfs-transacti:8203 blocked for more than 4 seconds.
[ 575.055252] Not tainted 5.15.0-1.el7.x86_64 #1
[ 575.056391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 575.057540] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
[ 575.058704] Call Trace:
[ 575.059864] __schedule+0x37c/0x7a0
[ 575.061026] schedule+0x3a/0xa0
[ 575.062157] btrfs_commit_transaction+0x200/0xac0 [btrfs]
[ 575.063352] ? finish_wait+0x80/0x80
[ 575.064463] transaction_kthread+0x13d/0x190 [btrfs]
[ 575.065628] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[ 575.066796] kthread+0x118/0x140
[ 575.067924] ? set_kthread_struct+0x40/0x40
[ 575.069029] ret_from_fork+0x1f/0x30
[ 575.070112] INFO: task xfs_io:8398 blocked for more than 4 seconds.
[ 575.071207] Not tainted 5.15.0-1.el7.x86_64 #1
[ 575.072303] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 575.073424] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
[ 575.074566] Call Trace:
[ 575.075688] __schedule+0x37c/0x7a0
[ 575.076799] schedule+0x3a/0xa0
[ 575.077893] wait_current_trans+0xc2/0x120 [btrfs]
[ 575.079036] ? finish_wait+0x80/0x80
[ 575.080110] start_transaction+0x490/0x590 [btrfs]
[ 575.081239] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
[ 575.082378] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
[ 575.083506] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
[ 575.084609] btrfs_clone+0x796/0x7f0 [btrfs]
[ 575.085765] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
[ 575.086920] btrfs_clone_files+0xfc/0x150 [btrfs]
[ 575.088072] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
[ 575.089226] do_clone_file_range+0xea/0x230
[ 575.090328] vfs_clone_file_range+0x37/0x110
[ 575.091419] ioctl_file_clone+0x7d/0xb0
[ 575.092505] do_vfs_ioctl+0x47d/0x7f0
[ 575.093575] __x64_sys_ioctl+0x62/0xc0
[ 575.094628] do_syscall_64+0x37/0x80
[ 575.095670] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 575.096722] RIP: 0033:0x7fe48946c62b
[ 575.097773] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 575.098845] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
[ 575.099923] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
[ 575.101002] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
[ 575.102080] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
[ 575.103155] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
[ 577.166111] INFO: task btrfs-transacti:8203 blocked for more than 6 seconds.
[ 577.167209] Not tainted 5.15.0-1.el7.x86_64 #1
[ 577.168289] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 577.169385] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
[ 577.170499] Call Trace:
[ 577.171601] __schedule+0x37c/0x7a0
[ 577.172709] schedule+0x3a/0xa0
[ 577.173812] btrfs_commit_transaction+0x200/0xac0 [btrfs]
[ 577.175005] ? finish_wait+0x80/0x80
[ 577.176118] transaction_kthread+0x13d/0x190 [btrfs]
[ 577.177281] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[ 577.178446] kthread+0x118/0x140
[ 577.179576] ? set_kthread_struct+0x40/0x40
[ 577.180683] ret_from_fork+0x1f/0x30
[ 577.181823] INFO: task xfs_io:8398 blocked for more than 6 seconds.
[ 577.182977] Not tainted 5.15.0-1.el7.x86_64 #1
[ 577.184087] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 577.185216] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
[ 577.186364] Call Trace:
[ 577.187492] __schedule+0x37c/0x7a0
[ 577.188611] schedule+0x3a/0xa0
[ 577.189711] wait_current_trans+0xc2/0x120 [btrfs]
[ 577.190862] ? finish_wait+0x80/0x80
[ 577.191941] start_transaction+0x490/0x590 [btrfs]
[ 577.193073] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
[ 577.194220] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
[ 577.195355] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
[ 577.196464] btrfs_clone+0x796/0x7f0 [btrfs]
[ 577.197627] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
[ 577.198790] btrfs_clone_files+0xfc/0x150 [btrfs]
[ 577.199947] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
[ 577.201105] do_clone_file_range+0xea/0x230
[ 577.202212] vfs_clone_file_range+0x37/0x110
[ 577.203308] ioctl_file_clone+0x7d/0xb0
[ 577.204398] do_vfs_ioctl+0x47d/0x7f0
[ 577.205470] __x64_sys_ioctl+0x62/0xc0
[ 577.206527] do_syscall_64+0x37/0x80
[ 577.207573] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 577.208627] RIP: 0033:0x7fe48946c62b
[ 577.209679] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 577.210755] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
[ 577.211834] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
[ 577.212913] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
[ 577.213992] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
[ 577.215066] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
[ 579.278098] INFO: task btrfs-transacti:8203 blocked for more than 8 seconds.
[ 579.279201] Not tainted 5.15.0-1.el7.x86_64 #1
[ 579.280278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 579.281373] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
[ 579.282486] Call Trace:
[ 579.283590] __schedule+0x37c/0x7a0
[ 579.284698] schedule+0x3a/0xa0
[ 579.285801] btrfs_commit_transaction+0x200/0xac0 [btrfs]
[ 579.286991] ? finish_wait+0x80/0x80
[ 579.288104] transaction_kthread+0x13d/0x190 [btrfs]
[ 579.289270] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[ 579.290435] kthread+0x118/0x140
[ 579.291553] ? set_kthread_struct+0x40/0x40
[ 579.292661] ret_from_fork+0x1f/0x30
[ 579.293764] INFO: task xfs_io:8398 blocked for more than 8 seconds.
[ 579.294880] Not tainted 5.15.0-1.el7.x86_64 #1
[ 579.295990] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 579.297120] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
[ 579.298264] Call Trace:
[ 579.299388] __schedule+0x37c/0x7a0
[ 579.300503] schedule+0x3a/0xa0
[ 579.301601] wait_current_trans+0xc2/0x120 [btrfs]
[ 579.302747] ? finish_wait+0x80/0x80
[ 579.303828] start_transaction+0x490/0x590 [btrfs]
[ 579.304959] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
[ 579.306103] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
[ 579.307235] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
[ 579.308341] btrfs_clone+0x796/0x7f0 [btrfs]
[ 579.309500] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
[ 579.310661] btrfs_clone_files+0xfc/0x150 [btrfs]
[ 579.311817] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
[ 579.313144] do_clone_file_range+0xea/0x230
[ 579.314251] vfs_clone_file_range+0x37/0x110
[ 579.315350] ioctl_file_clone+0x7d/0xb0
[ 579.316441] do_vfs_ioctl+0x47d/0x7f0
[ 579.317516] __x64_sys_ioctl+0x62/0xc0
[ 579.318576] do_syscall_64+0x37/0x80
[ 579.319623] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 579.320682] RIP: 0033:0x7fe48946c62b
[ 579.321736] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 579.322812] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
[ 579.323895] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
[ 579.324980] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
[ 579.326061] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
[ 579.327139] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
[ 581.390104] INFO: task btrfs-transacti:8203 blocked for more than 10 seconds.
[ 581.391207] Not tainted 5.15.0-1.el7.x86_64 #1
[ 581.392290] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 581.393391] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
[ 581.394513] Call Trace:
[ 581.395621] __schedule+0x37c/0x7a0
[ 581.396733] schedule+0x3a/0xa0
[ 581.397841] btrfs_commit_transaction+0x200/0xac0 [btrfs]
[ 581.399040] ? finish_wait+0x80/0x80
[ 581.400160] transaction_kthread+0x13d/0x190 [btrfs]
[ 581.401331] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[ 581.402502] kthread+0x118/0x140
[ 581.403626] ? set_kthread_struct+0x40/0x40
[ 581.404741] ret_from_fork+0x1f/0x30
[ 581.405848] INFO: task xfs_io:8398 blocked for more than 10 seconds.
[ 581.406966] Not tainted 5.15.0-1.el7.x86_64 #1
[ 581.408082] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 581.409220] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
[ 581.410373] Call Trace:
[ 581.411507] __schedule+0x37c/0x7a0
[ 581.412632] schedule+0x3a/0xa0
[ 581.413739] wait_current_trans+0xc2/0x120 [btrfs]
[ 581.414893] ? finish_wait+0x80/0x80
[ 581.415977] start_transaction+0x490/0x590 [btrfs]
[ 581.417116] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
[ 581.418438] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
[ 581.419577] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
[ 581.420691] btrfs_clone+0x796/0x7f0 [btrfs]
[ 581.422025] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
[ 581.423199] btrfs_clone_files+0xfc/0x150 [btrfs]
[ 581.424364] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
[ 581.425528] do_clone_file_range+0xea/0x230
[ 581.426640] vfs_clone_file_range+0x37/0x110
[ 581.427743] ioctl_file_clone+0x7d/0xb0
[ 581.428839] do_vfs_ioctl+0x47d/0x7f0
[ 581.429919] __x64_sys_ioctl+0x62/0xc0
[ 581.430983] do_syscall_64+0x37/0x80
[ 581.432121] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 581.433302] RIP: 0033:0x7fe48946c62b
[ 581.434368] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 581.435457] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
[ 581.436547] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
[ 581.437636] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
[ 581.438722] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
[ 581.439808] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
Best Regards
Wang Yugui (wangyugui@e16-tech.com)
2021/11/03
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: btrfs reflink take too long time(21s)
2021-11-03 10:41 btrfs reflink take too long time(21s) Wang Yugui
@ 2021-11-05 13:08 ` Wang Yugui
2021-11-05 13:16 ` Qu Wenruo
2021-11-05 16:08 ` David Sterba
0 siblings, 2 replies; 5+ messages in thread
From: Wang Yugui @ 2021-11-05 13:08 UTC (permalink / raw)
To: linux-btrfs
Hi, David Sterba
Is this problem reproduced by other people?
It seems a blocker kernel issue for the coming btrfs-progs 5.15 release.
becase DUP metadata become default for single SSD in the coming btrfs-progs 5.15 release.
Best Regards
Wang Yugui (wangyugui@e16-tech.com)
2021/11/05
> Hi,
>
> fstests(generic/297) report that btrfs reflink take too long time(21s)
> reflink didn't stop in time, n=17179869184 t=21
>
> reproduce frequency:
> DUP metadata(mkfs.btrfs -m DUP): about 20%
> single metadata(mkfs.btrfs -m single): < 3%
>
> kernel/btrfs: 5.15
> I just begin to test DUP metadata(mkfs.btrfs -m DUP) recently,
> so it may NOT a problem introduced in 5.15
>
> DUP metadata is useful to reproduce.
> --- a/tests/generic/297
> +++ b/tests/generic/297
> @@ -29,7 +32,7 @@ _require_command "$TIMEOUT_PROG" "timeout"
> test $FSTYP == "nfs" && _notrun "NFS can't interrupt clone operations"
>
> echo "Format and mount"
> -_scratch_mkfs > $seqres.full 2>&1
> +_scratch_mkfs -m DUP > $seqres.full 2>&1
> _scratch_mount >> $seqres.full 2>&1
>
> testdir=$SCRATCH_MNT/test-$seq
>
>
> I used 'hung_task_timeout_secs=2' to gather some call trace
>
> [ 572.942085] INFO: task btrfs-transacti:8203 blocked for more than 2 seconds.
> [ 572.943264] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 572.944391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 572.945516] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> [ 572.946653] Call Trace:
> [ 572.947789] __schedule+0x37c/0x7a0
> [ 572.948928] schedule+0x3a/0xa0
> [ 572.950066] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> [ 572.951284] ? finish_wait+0x80/0x80
> [ 572.952422] transaction_kthread+0x13d/0x190 [btrfs]
> [ 572.953613] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> [ 572.954807] kthread+0x118/0x140
> [ 572.955954] ? set_kthread_struct+0x40/0x40
> [ 572.957091] ret_from_fork+0x1f/0x30
>
> [ 572.958231] INFO: task xfs_io:8398 blocked for more than 2 seconds.
> [ 572.959385] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 572.960539] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 572.961723] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> [ 572.962873] Call Trace:
> [ 572.964006] __schedule+0x37c/0x7a0
> [ 572.965142] schedule+0x3a/0xa0
> [ 572.966277] wait_current_trans+0xc2/0x120 [btrfs]
> [ 572.967475] ? finish_wait+0x80/0x80
> [ 572.968595] start_transaction+0x490/0x590 [btrfs]
> [ 572.969745] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> [ 572.970898] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> [ 572.972051] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> [ 572.973180] btrfs_clone+0x796/0x7f0 [btrfs]
> [ 572.974366] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> [ 572.975552] btrfs_clone_files+0xfc/0x150 [btrfs]
> [ 572.976918] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> [ 572.978111] do_clone_file_range+0xea/0x230
> [ 572.979250] vfs_clone_file_range+0x37/0x110
> [ 572.980384] ioctl_file_clone+0x7d/0xb0
> [ 572.981512] do_vfs_ioctl+0x47d/0x7f0
> [ 572.982639] __x64_sys_ioctl+0x62/0xc0
> [ 572.983766] do_syscall_64+0x37/0x80
> [ 572.984869] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 572.985958] RIP: 0033:0x7fe48946c62b
> [ 572.987037] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 572.988145] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> [ 572.989259] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> [ 572.990382] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> [ 572.991501] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> [ 572.992621] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>
> [ 575.054091] INFO: task btrfs-transacti:8203 blocked for more than 4 seconds.
> [ 575.055252] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 575.056391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 575.057540] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> [ 575.058704] Call Trace:
> [ 575.059864] __schedule+0x37c/0x7a0
> [ 575.061026] schedule+0x3a/0xa0
> [ 575.062157] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> [ 575.063352] ? finish_wait+0x80/0x80
> [ 575.064463] transaction_kthread+0x13d/0x190 [btrfs]
> [ 575.065628] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> [ 575.066796] kthread+0x118/0x140
> [ 575.067924] ? set_kthread_struct+0x40/0x40
> [ 575.069029] ret_from_fork+0x1f/0x30
> [ 575.070112] INFO: task xfs_io:8398 blocked for more than 4 seconds.
> [ 575.071207] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 575.072303] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 575.073424] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> [ 575.074566] Call Trace:
> [ 575.075688] __schedule+0x37c/0x7a0
> [ 575.076799] schedule+0x3a/0xa0
> [ 575.077893] wait_current_trans+0xc2/0x120 [btrfs]
> [ 575.079036] ? finish_wait+0x80/0x80
> [ 575.080110] start_transaction+0x490/0x590 [btrfs]
> [ 575.081239] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> [ 575.082378] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> [ 575.083506] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> [ 575.084609] btrfs_clone+0x796/0x7f0 [btrfs]
> [ 575.085765] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> [ 575.086920] btrfs_clone_files+0xfc/0x150 [btrfs]
> [ 575.088072] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> [ 575.089226] do_clone_file_range+0xea/0x230
> [ 575.090328] vfs_clone_file_range+0x37/0x110
> [ 575.091419] ioctl_file_clone+0x7d/0xb0
> [ 575.092505] do_vfs_ioctl+0x47d/0x7f0
> [ 575.093575] __x64_sys_ioctl+0x62/0xc0
> [ 575.094628] do_syscall_64+0x37/0x80
> [ 575.095670] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 575.096722] RIP: 0033:0x7fe48946c62b
> [ 575.097773] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 575.098845] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> [ 575.099923] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> [ 575.101002] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> [ 575.102080] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> [ 575.103155] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>
>
> [ 577.166111] INFO: task btrfs-transacti:8203 blocked for more than 6 seconds.
> [ 577.167209] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 577.168289] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 577.169385] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> [ 577.170499] Call Trace:
> [ 577.171601] __schedule+0x37c/0x7a0
> [ 577.172709] schedule+0x3a/0xa0
> [ 577.173812] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> [ 577.175005] ? finish_wait+0x80/0x80
> [ 577.176118] transaction_kthread+0x13d/0x190 [btrfs]
> [ 577.177281] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> [ 577.178446] kthread+0x118/0x140
> [ 577.179576] ? set_kthread_struct+0x40/0x40
> [ 577.180683] ret_from_fork+0x1f/0x30
>
>
> [ 577.181823] INFO: task xfs_io:8398 blocked for more than 6 seconds.
> [ 577.182977] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 577.184087] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 577.185216] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> [ 577.186364] Call Trace:
> [ 577.187492] __schedule+0x37c/0x7a0
> [ 577.188611] schedule+0x3a/0xa0
> [ 577.189711] wait_current_trans+0xc2/0x120 [btrfs]
> [ 577.190862] ? finish_wait+0x80/0x80
> [ 577.191941] start_transaction+0x490/0x590 [btrfs]
> [ 577.193073] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> [ 577.194220] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> [ 577.195355] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> [ 577.196464] btrfs_clone+0x796/0x7f0 [btrfs]
> [ 577.197627] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> [ 577.198790] btrfs_clone_files+0xfc/0x150 [btrfs]
> [ 577.199947] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> [ 577.201105] do_clone_file_range+0xea/0x230
> [ 577.202212] vfs_clone_file_range+0x37/0x110
> [ 577.203308] ioctl_file_clone+0x7d/0xb0
> [ 577.204398] do_vfs_ioctl+0x47d/0x7f0
> [ 577.205470] __x64_sys_ioctl+0x62/0xc0
> [ 577.206527] do_syscall_64+0x37/0x80
> [ 577.207573] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 577.208627] RIP: 0033:0x7fe48946c62b
> [ 577.209679] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 577.210755] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> [ 577.211834] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> [ 577.212913] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> [ 577.213992] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> [ 577.215066] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>
>
> [ 579.278098] INFO: task btrfs-transacti:8203 blocked for more than 8 seconds.
> [ 579.279201] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 579.280278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 579.281373] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> [ 579.282486] Call Trace:
> [ 579.283590] __schedule+0x37c/0x7a0
> [ 579.284698] schedule+0x3a/0xa0
> [ 579.285801] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> [ 579.286991] ? finish_wait+0x80/0x80
> [ 579.288104] transaction_kthread+0x13d/0x190 [btrfs]
> [ 579.289270] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> [ 579.290435] kthread+0x118/0x140
> [ 579.291553] ? set_kthread_struct+0x40/0x40
> [ 579.292661] ret_from_fork+0x1f/0x30
> [ 579.293764] INFO: task xfs_io:8398 blocked for more than 8 seconds.
> [ 579.294880] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 579.295990] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 579.297120] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> [ 579.298264] Call Trace:
> [ 579.299388] __schedule+0x37c/0x7a0
> [ 579.300503] schedule+0x3a/0xa0
> [ 579.301601] wait_current_trans+0xc2/0x120 [btrfs]
> [ 579.302747] ? finish_wait+0x80/0x80
> [ 579.303828] start_transaction+0x490/0x590 [btrfs]
> [ 579.304959] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> [ 579.306103] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> [ 579.307235] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> [ 579.308341] btrfs_clone+0x796/0x7f0 [btrfs]
> [ 579.309500] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> [ 579.310661] btrfs_clone_files+0xfc/0x150 [btrfs]
> [ 579.311817] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> [ 579.313144] do_clone_file_range+0xea/0x230
> [ 579.314251] vfs_clone_file_range+0x37/0x110
> [ 579.315350] ioctl_file_clone+0x7d/0xb0
> [ 579.316441] do_vfs_ioctl+0x47d/0x7f0
> [ 579.317516] __x64_sys_ioctl+0x62/0xc0
> [ 579.318576] do_syscall_64+0x37/0x80
> [ 579.319623] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 579.320682] RIP: 0033:0x7fe48946c62b
> [ 579.321736] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 579.322812] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> [ 579.323895] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> [ 579.324980] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> [ 579.326061] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> [ 579.327139] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>
>
> [ 581.390104] INFO: task btrfs-transacti:8203 blocked for more than 10 seconds.
> [ 581.391207] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 581.392290] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 581.393391] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> [ 581.394513] Call Trace:
> [ 581.395621] __schedule+0x37c/0x7a0
> [ 581.396733] schedule+0x3a/0xa0
> [ 581.397841] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> [ 581.399040] ? finish_wait+0x80/0x80
> [ 581.400160] transaction_kthread+0x13d/0x190 [btrfs]
> [ 581.401331] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> [ 581.402502] kthread+0x118/0x140
> [ 581.403626] ? set_kthread_struct+0x40/0x40
> [ 581.404741] ret_from_fork+0x1f/0x30
>
>
> [ 581.405848] INFO: task xfs_io:8398 blocked for more than 10 seconds.
> [ 581.406966] Not tainted 5.15.0-1.el7.x86_64 #1
> [ 581.408082] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 581.409220] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> [ 581.410373] Call Trace:
> [ 581.411507] __schedule+0x37c/0x7a0
> [ 581.412632] schedule+0x3a/0xa0
> [ 581.413739] wait_current_trans+0xc2/0x120 [btrfs]
> [ 581.414893] ? finish_wait+0x80/0x80
> [ 581.415977] start_transaction+0x490/0x590 [btrfs]
> [ 581.417116] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> [ 581.418438] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> [ 581.419577] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> [ 581.420691] btrfs_clone+0x796/0x7f0 [btrfs]
> [ 581.422025] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> [ 581.423199] btrfs_clone_files+0xfc/0x150 [btrfs]
> [ 581.424364] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> [ 581.425528] do_clone_file_range+0xea/0x230
> [ 581.426640] vfs_clone_file_range+0x37/0x110
> [ 581.427743] ioctl_file_clone+0x7d/0xb0
> [ 581.428839] do_vfs_ioctl+0x47d/0x7f0
> [ 581.429919] __x64_sys_ioctl+0x62/0xc0
> [ 581.430983] do_syscall_64+0x37/0x80
> [ 581.432121] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 581.433302] RIP: 0033:0x7fe48946c62b
> [ 581.434368] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 581.435457] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> [ 581.436547] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> [ 581.437636] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> [ 581.438722] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> [ 581.439808] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>
> Best Regards
> Wang Yugui (wangyugui@e16-tech.com)
> 2021/11/03
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: btrfs reflink take too long time(21s)
2021-11-05 13:08 ` Wang Yugui
@ 2021-11-05 13:16 ` Qu Wenruo
2021-11-05 13:55 ` Wang Yugui
2021-11-05 16:08 ` David Sterba
1 sibling, 1 reply; 5+ messages in thread
From: Qu Wenruo @ 2021-11-05 13:16 UTC (permalink / raw)
To: Wang Yugui, linux-btrfs
On 2021/11/5 21:08, Wang Yugui wrote:
> Hi, David Sterba
>
> Is this problem reproduced by other people?
>
> It seems a blocker kernel issue for the coming btrfs-progs 5.15 release.
> becase DUP metadata become default for single SSD in the coming btrfs-progs 5.15 release.
Just to be clear, it's purely -m DUP causing the problem? No other
features like free-space-tree involved?
If using v5.14.2 progs, just with -m DUP, it can still reproduce the
problem?
Thanks,
Qu
>
> Best Regards
> Wang Yugui (wangyugui@e16-tech.com)
> 2021/11/05
>
>> Hi,
>>
>> fstests(generic/297) report that btrfs reflink take too long time(21s)
>> reflink didn't stop in time, n=17179869184 t=21
>>
>> reproduce frequency:
>> DUP metadata(mkfs.btrfs -m DUP): about 20%
>> single metadata(mkfs.btrfs -m single): < 3%
>>
>> kernel/btrfs: 5.15
>> I just begin to test DUP metadata(mkfs.btrfs -m DUP) recently,
>> so it may NOT a problem introduced in 5.15
>>
>> DUP metadata is useful to reproduce.
>> --- a/tests/generic/297
>> +++ b/tests/generic/297
>> @@ -29,7 +32,7 @@ _require_command "$TIMEOUT_PROG" "timeout"
>> test $FSTYP == "nfs" && _notrun "NFS can't interrupt clone operations"
>>
>> echo "Format and mount"
>> -_scratch_mkfs > $seqres.full 2>&1
>> +_scratch_mkfs -m DUP > $seqres.full 2>&1
>> _scratch_mount >> $seqres.full 2>&1
>>
>> testdir=$SCRATCH_MNT/test-$seq
>>
>>
>> I used 'hung_task_timeout_secs=2' to gather some call trace
>>
>> [ 572.942085] INFO: task btrfs-transacti:8203 blocked for more than 2 seconds.
>> [ 572.943264] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 572.944391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 572.945516] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
>> [ 572.946653] Call Trace:
>> [ 572.947789] __schedule+0x37c/0x7a0
>> [ 572.948928] schedule+0x3a/0xa0
>> [ 572.950066] btrfs_commit_transaction+0x200/0xac0 [btrfs]
>> [ 572.951284] ? finish_wait+0x80/0x80
>> [ 572.952422] transaction_kthread+0x13d/0x190 [btrfs]
>> [ 572.953613] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
>> [ 572.954807] kthread+0x118/0x140
>> [ 572.955954] ? set_kthread_struct+0x40/0x40
>> [ 572.957091] ret_from_fork+0x1f/0x30
>>
>> [ 572.958231] INFO: task xfs_io:8398 blocked for more than 2 seconds.
>> [ 572.959385] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 572.960539] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 572.961723] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
>> [ 572.962873] Call Trace:
>> [ 572.964006] __schedule+0x37c/0x7a0
>> [ 572.965142] schedule+0x3a/0xa0
>> [ 572.966277] wait_current_trans+0xc2/0x120 [btrfs]
>> [ 572.967475] ? finish_wait+0x80/0x80
>> [ 572.968595] start_transaction+0x490/0x590 [btrfs]
>> [ 572.969745] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
>> [ 572.970898] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
>> [ 572.972051] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
>> [ 572.973180] btrfs_clone+0x796/0x7f0 [btrfs]
>> [ 572.974366] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
>> [ 572.975552] btrfs_clone_files+0xfc/0x150 [btrfs]
>> [ 572.976918] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
>> [ 572.978111] do_clone_file_range+0xea/0x230
>> [ 572.979250] vfs_clone_file_range+0x37/0x110
>> [ 572.980384] ioctl_file_clone+0x7d/0xb0
>> [ 572.981512] do_vfs_ioctl+0x47d/0x7f0
>> [ 572.982639] __x64_sys_ioctl+0x62/0xc0
>> [ 572.983766] do_syscall_64+0x37/0x80
>> [ 572.984869] entry_SYSCALL_64_after_hwframe+0x44/0xae
>> [ 572.985958] RIP: 0033:0x7fe48946c62b
>> [ 572.987037] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
>> [ 572.988145] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
>> [ 572.989259] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
>> [ 572.990382] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
>> [ 572.991501] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
>> [ 572.992621] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>>
>> [ 575.054091] INFO: task btrfs-transacti:8203 blocked for more than 4 seconds.
>> [ 575.055252] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 575.056391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 575.057540] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
>> [ 575.058704] Call Trace:
>> [ 575.059864] __schedule+0x37c/0x7a0
>> [ 575.061026] schedule+0x3a/0xa0
>> [ 575.062157] btrfs_commit_transaction+0x200/0xac0 [btrfs]
>> [ 575.063352] ? finish_wait+0x80/0x80
>> [ 575.064463] transaction_kthread+0x13d/0x190 [btrfs]
>> [ 575.065628] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
>> [ 575.066796] kthread+0x118/0x140
>> [ 575.067924] ? set_kthread_struct+0x40/0x40
>> [ 575.069029] ret_from_fork+0x1f/0x30
>> [ 575.070112] INFO: task xfs_io:8398 blocked for more than 4 seconds.
>> [ 575.071207] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 575.072303] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 575.073424] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
>> [ 575.074566] Call Trace:
>> [ 575.075688] __schedule+0x37c/0x7a0
>> [ 575.076799] schedule+0x3a/0xa0
>> [ 575.077893] wait_current_trans+0xc2/0x120 [btrfs]
>> [ 575.079036] ? finish_wait+0x80/0x80
>> [ 575.080110] start_transaction+0x490/0x590 [btrfs]
>> [ 575.081239] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
>> [ 575.082378] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
>> [ 575.083506] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
>> [ 575.084609] btrfs_clone+0x796/0x7f0 [btrfs]
>> [ 575.085765] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
>> [ 575.086920] btrfs_clone_files+0xfc/0x150 [btrfs]
>> [ 575.088072] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
>> [ 575.089226] do_clone_file_range+0xea/0x230
>> [ 575.090328] vfs_clone_file_range+0x37/0x110
>> [ 575.091419] ioctl_file_clone+0x7d/0xb0
>> [ 575.092505] do_vfs_ioctl+0x47d/0x7f0
>> [ 575.093575] __x64_sys_ioctl+0x62/0xc0
>> [ 575.094628] do_syscall_64+0x37/0x80
>> [ 575.095670] entry_SYSCALL_64_after_hwframe+0x44/0xae
>> [ 575.096722] RIP: 0033:0x7fe48946c62b
>> [ 575.097773] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
>> [ 575.098845] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
>> [ 575.099923] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
>> [ 575.101002] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
>> [ 575.102080] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
>> [ 575.103155] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>>
>>
>> [ 577.166111] INFO: task btrfs-transacti:8203 blocked for more than 6 seconds.
>> [ 577.167209] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 577.168289] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 577.169385] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
>> [ 577.170499] Call Trace:
>> [ 577.171601] __schedule+0x37c/0x7a0
>> [ 577.172709] schedule+0x3a/0xa0
>> [ 577.173812] btrfs_commit_transaction+0x200/0xac0 [btrfs]
>> [ 577.175005] ? finish_wait+0x80/0x80
>> [ 577.176118] transaction_kthread+0x13d/0x190 [btrfs]
>> [ 577.177281] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
>> [ 577.178446] kthread+0x118/0x140
>> [ 577.179576] ? set_kthread_struct+0x40/0x40
>> [ 577.180683] ret_from_fork+0x1f/0x30
>>
>>
>> [ 577.181823] INFO: task xfs_io:8398 blocked for more than 6 seconds.
>> [ 577.182977] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 577.184087] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 577.185216] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
>> [ 577.186364] Call Trace:
>> [ 577.187492] __schedule+0x37c/0x7a0
>> [ 577.188611] schedule+0x3a/0xa0
>> [ 577.189711] wait_current_trans+0xc2/0x120 [btrfs]
>> [ 577.190862] ? finish_wait+0x80/0x80
>> [ 577.191941] start_transaction+0x490/0x590 [btrfs]
>> [ 577.193073] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
>> [ 577.194220] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
>> [ 577.195355] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
>> [ 577.196464] btrfs_clone+0x796/0x7f0 [btrfs]
>> [ 577.197627] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
>> [ 577.198790] btrfs_clone_files+0xfc/0x150 [btrfs]
>> [ 577.199947] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
>> [ 577.201105] do_clone_file_range+0xea/0x230
>> [ 577.202212] vfs_clone_file_range+0x37/0x110
>> [ 577.203308] ioctl_file_clone+0x7d/0xb0
>> [ 577.204398] do_vfs_ioctl+0x47d/0x7f0
>> [ 577.205470] __x64_sys_ioctl+0x62/0xc0
>> [ 577.206527] do_syscall_64+0x37/0x80
>> [ 577.207573] entry_SYSCALL_64_after_hwframe+0x44/0xae
>> [ 577.208627] RIP: 0033:0x7fe48946c62b
>> [ 577.209679] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
>> [ 577.210755] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
>> [ 577.211834] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
>> [ 577.212913] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
>> [ 577.213992] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
>> [ 577.215066] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>>
>>
>> [ 579.278098] INFO: task btrfs-transacti:8203 blocked for more than 8 seconds.
>> [ 579.279201] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 579.280278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 579.281373] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
>> [ 579.282486] Call Trace:
>> [ 579.283590] __schedule+0x37c/0x7a0
>> [ 579.284698] schedule+0x3a/0xa0
>> [ 579.285801] btrfs_commit_transaction+0x200/0xac0 [btrfs]
>> [ 579.286991] ? finish_wait+0x80/0x80
>> [ 579.288104] transaction_kthread+0x13d/0x190 [btrfs]
>> [ 579.289270] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
>> [ 579.290435] kthread+0x118/0x140
>> [ 579.291553] ? set_kthread_struct+0x40/0x40
>> [ 579.292661] ret_from_fork+0x1f/0x30
>> [ 579.293764] INFO: task xfs_io:8398 blocked for more than 8 seconds.
>> [ 579.294880] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 579.295990] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 579.297120] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
>> [ 579.298264] Call Trace:
>> [ 579.299388] __schedule+0x37c/0x7a0
>> [ 579.300503] schedule+0x3a/0xa0
>> [ 579.301601] wait_current_trans+0xc2/0x120 [btrfs]
>> [ 579.302747] ? finish_wait+0x80/0x80
>> [ 579.303828] start_transaction+0x490/0x590 [btrfs]
>> [ 579.304959] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
>> [ 579.306103] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
>> [ 579.307235] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
>> [ 579.308341] btrfs_clone+0x796/0x7f0 [btrfs]
>> [ 579.309500] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
>> [ 579.310661] btrfs_clone_files+0xfc/0x150 [btrfs]
>> [ 579.311817] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
>> [ 579.313144] do_clone_file_range+0xea/0x230
>> [ 579.314251] vfs_clone_file_range+0x37/0x110
>> [ 579.315350] ioctl_file_clone+0x7d/0xb0
>> [ 579.316441] do_vfs_ioctl+0x47d/0x7f0
>> [ 579.317516] __x64_sys_ioctl+0x62/0xc0
>> [ 579.318576] do_syscall_64+0x37/0x80
>> [ 579.319623] entry_SYSCALL_64_after_hwframe+0x44/0xae
>> [ 579.320682] RIP: 0033:0x7fe48946c62b
>> [ 579.321736] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
>> [ 579.322812] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
>> [ 579.323895] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
>> [ 579.324980] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
>> [ 579.326061] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
>> [ 579.327139] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>>
>>
>> [ 581.390104] INFO: task btrfs-transacti:8203 blocked for more than 10 seconds.
>> [ 581.391207] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 581.392290] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 581.393391] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
>> [ 581.394513] Call Trace:
>> [ 581.395621] __schedule+0x37c/0x7a0
>> [ 581.396733] schedule+0x3a/0xa0
>> [ 581.397841] btrfs_commit_transaction+0x200/0xac0 [btrfs]
>> [ 581.399040] ? finish_wait+0x80/0x80
>> [ 581.400160] transaction_kthread+0x13d/0x190 [btrfs]
>> [ 581.401331] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
>> [ 581.402502] kthread+0x118/0x140
>> [ 581.403626] ? set_kthread_struct+0x40/0x40
>> [ 581.404741] ret_from_fork+0x1f/0x30
>>
>>
>> [ 581.405848] INFO: task xfs_io:8398 blocked for more than 10 seconds.
>> [ 581.406966] Not tainted 5.15.0-1.el7.x86_64 #1
>> [ 581.408082] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 581.409220] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
>> [ 581.410373] Call Trace:
>> [ 581.411507] __schedule+0x37c/0x7a0
>> [ 581.412632] schedule+0x3a/0xa0
>> [ 581.413739] wait_current_trans+0xc2/0x120 [btrfs]
>> [ 581.414893] ? finish_wait+0x80/0x80
>> [ 581.415977] start_transaction+0x490/0x590 [btrfs]
>> [ 581.417116] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
>> [ 581.418438] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
>> [ 581.419577] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
>> [ 581.420691] btrfs_clone+0x796/0x7f0 [btrfs]
>> [ 581.422025] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
>> [ 581.423199] btrfs_clone_files+0xfc/0x150 [btrfs]
>> [ 581.424364] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
>> [ 581.425528] do_clone_file_range+0xea/0x230
>> [ 581.426640] vfs_clone_file_range+0x37/0x110
>> [ 581.427743] ioctl_file_clone+0x7d/0xb0
>> [ 581.428839] do_vfs_ioctl+0x47d/0x7f0
>> [ 581.429919] __x64_sys_ioctl+0x62/0xc0
>> [ 581.430983] do_syscall_64+0x37/0x80
>> [ 581.432121] entry_SYSCALL_64_after_hwframe+0x44/0xae
>> [ 581.433302] RIP: 0033:0x7fe48946c62b
>> [ 581.434368] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
>> [ 581.435457] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
>> [ 581.436547] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
>> [ 581.437636] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
>> [ 581.438722] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
>> [ 581.439808] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
>>
>> Best Regards
>> Wang Yugui (wangyugui@e16-tech.com)
>> 2021/11/03
>>
>
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: btrfs reflink take too long time(21s)
2021-11-05 13:16 ` Qu Wenruo
@ 2021-11-05 13:55 ` Wang Yugui
0 siblings, 0 replies; 5+ messages in thread
From: Wang Yugui @ 2021-11-05 13:55 UTC (permalink / raw)
To: Qu Wenruo; +Cc: linux-btrfs
Hi,
> On 2021/11/5 21:08, Wang Yugui wrote:
> > Hi, David Sterba
> >
> > Is this problem reproduced by other people?
> >
> > It seems a blocker kernel issue for the coming btrfs-progs 5.15 release.
> > becase DUP metadata become default for single SSD in the coming btrfs-progs 5.15 release.
>
> Just to be clear, it's purely -m DUP causing the problem? No other
> features like free-space-tree involved?
>
> If using v5.14.2 progs, just with -m DUP, it can still reproduce the
> problem?
the cases that are well tesed
1) single metadata(mkfs.btrfs -m single -O no-holes -R free-space-tree)
2) DUP metadata(mkfs.btrfs -m DUP -O no-holes -R free-space-tree)
We tested it with '-O no-holes -R free-space-tree' as default for about
1 year.
so the cases that are not well tesed here.
1) DUP metadata(mkfs.btrfs -m DUP -O ^no-holes -R ^free-space-tree)
2) single metadata(mkfs.btrfs -m single -O ^no-holes -R ^free-space-tree)
tested disk: SSD/SAS, SSD/NVMe, both are Bare metal.
Best Regards
Wang Yugui (wangyugui@e16-tech.com)
2021/11/05
>
> Thanks,
> Qu
> >
> > Best Regards
> > Wang Yugui (wangyugui@e16-tech.com)
> > 2021/11/05
> >
> >> Hi,
> >>
> >> fstests(generic/297) report that btrfs reflink take too long time(21s)
> >> reflink didn't stop in time, n=17179869184 t=21
> >>
> >> reproduce frequency:
> >> DUP metadata(mkfs.btrfs -m DUP): about 20%
> >> single metadata(mkfs.btrfs -m single): < 3%
> >>
> >> kernel/btrfs: 5.15
> >> I just begin to test DUP metadata(mkfs.btrfs -m DUP) recently,
> >> so it may NOT a problem introduced in 5.15
> >>
> >> DUP metadata is useful to reproduce.
> >> --- a/tests/generic/297
> >> +++ b/tests/generic/297
> >> @@ -29,7 +32,7 @@ _require_command "$TIMEOUT_PROG" "timeout"
> >> test $FSTYP == "nfs" && _notrun "NFS can't interrupt clone operations"
> >>
> >> echo "Format and mount"
> >> -_scratch_mkfs > $seqres.full 2>&1
> >> +_scratch_mkfs -m DUP > $seqres.full 2>&1
> >> _scratch_mount >> $seqres.full 2>&1
> >>
> >> testdir=$SCRATCH_MNT/test-$seq
> >>
> >>
> >> I used 'hung_task_timeout_secs=2' to gather some call trace
> >>
> >> [ 572.942085] INFO: task btrfs-transacti:8203 blocked for more than 2 seconds.
> >> [ 572.943264] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 572.944391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 572.945516] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> >> [ 572.946653] Call Trace:
> >> [ 572.947789] __schedule+0x37c/0x7a0
> >> [ 572.948928] schedule+0x3a/0xa0
> >> [ 572.950066] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> >> [ 572.951284] ? finish_wait+0x80/0x80
> >> [ 572.952422] transaction_kthread+0x13d/0x190 [btrfs]
> >> [ 572.953613] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> >> [ 572.954807] kthread+0x118/0x140
> >> [ 572.955954] ? set_kthread_struct+0x40/0x40
> >> [ 572.957091] ret_from_fork+0x1f/0x30
> >>
> >> [ 572.958231] INFO: task xfs_io:8398 blocked for more than 2 seconds.
> >> [ 572.959385] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 572.960539] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 572.961723] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> >> [ 572.962873] Call Trace:
> >> [ 572.964006] __schedule+0x37c/0x7a0
> >> [ 572.965142] schedule+0x3a/0xa0
> >> [ 572.966277] wait_current_trans+0xc2/0x120 [btrfs]
> >> [ 572.967475] ? finish_wait+0x80/0x80
> >> [ 572.968595] start_transaction+0x490/0x590 [btrfs]
> >> [ 572.969745] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> >> [ 572.970898] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> >> [ 572.972051] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> >> [ 572.973180] btrfs_clone+0x796/0x7f0 [btrfs]
> >> [ 572.974366] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> >> [ 572.975552] btrfs_clone_files+0xfc/0x150 [btrfs]
> >> [ 572.976918] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> >> [ 572.978111] do_clone_file_range+0xea/0x230
> >> [ 572.979250] vfs_clone_file_range+0x37/0x110
> >> [ 572.980384] ioctl_file_clone+0x7d/0xb0
> >> [ 572.981512] do_vfs_ioctl+0x47d/0x7f0
> >> [ 572.982639] __x64_sys_ioctl+0x62/0xc0
> >> [ 572.983766] do_syscall_64+0x37/0x80
> >> [ 572.984869] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [ 572.985958] RIP: 0033:0x7fe48946c62b
> >> [ 572.987037] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> >> [ 572.988145] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> >> [ 572.989259] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> >> [ 572.990382] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> >> [ 572.991501] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> >> [ 572.992621] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
> >>
> >> [ 575.054091] INFO: task btrfs-transacti:8203 blocked for more than 4 seconds.
> >> [ 575.055252] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 575.056391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 575.057540] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> >> [ 575.058704] Call Trace:
> >> [ 575.059864] __schedule+0x37c/0x7a0
> >> [ 575.061026] schedule+0x3a/0xa0
> >> [ 575.062157] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> >> [ 575.063352] ? finish_wait+0x80/0x80
> >> [ 575.064463] transaction_kthread+0x13d/0x190 [btrfs]
> >> [ 575.065628] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> >> [ 575.066796] kthread+0x118/0x140
> >> [ 575.067924] ? set_kthread_struct+0x40/0x40
> >> [ 575.069029] ret_from_fork+0x1f/0x30
> >> [ 575.070112] INFO: task xfs_io:8398 blocked for more than 4 seconds.
> >> [ 575.071207] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 575.072303] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 575.073424] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> >> [ 575.074566] Call Trace:
> >> [ 575.075688] __schedule+0x37c/0x7a0
> >> [ 575.076799] schedule+0x3a/0xa0
> >> [ 575.077893] wait_current_trans+0xc2/0x120 [btrfs]
> >> [ 575.079036] ? finish_wait+0x80/0x80
> >> [ 575.080110] start_transaction+0x490/0x590 [btrfs]
> >> [ 575.081239] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> >> [ 575.082378] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> >> [ 575.083506] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> >> [ 575.084609] btrfs_clone+0x796/0x7f0 [btrfs]
> >> [ 575.085765] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> >> [ 575.086920] btrfs_clone_files+0xfc/0x150 [btrfs]
> >> [ 575.088072] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> >> [ 575.089226] do_clone_file_range+0xea/0x230
> >> [ 575.090328] vfs_clone_file_range+0x37/0x110
> >> [ 575.091419] ioctl_file_clone+0x7d/0xb0
> >> [ 575.092505] do_vfs_ioctl+0x47d/0x7f0
> >> [ 575.093575] __x64_sys_ioctl+0x62/0xc0
> >> [ 575.094628] do_syscall_64+0x37/0x80
> >> [ 575.095670] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [ 575.096722] RIP: 0033:0x7fe48946c62b
> >> [ 575.097773] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> >> [ 575.098845] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> >> [ 575.099923] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> >> [ 575.101002] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> >> [ 575.102080] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> >> [ 575.103155] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
> >>
> >>
> >> [ 577.166111] INFO: task btrfs-transacti:8203 blocked for more than 6 seconds.
> >> [ 577.167209] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 577.168289] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 577.169385] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> >> [ 577.170499] Call Trace:
> >> [ 577.171601] __schedule+0x37c/0x7a0
> >> [ 577.172709] schedule+0x3a/0xa0
> >> [ 577.173812] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> >> [ 577.175005] ? finish_wait+0x80/0x80
> >> [ 577.176118] transaction_kthread+0x13d/0x190 [btrfs]
> >> [ 577.177281] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> >> [ 577.178446] kthread+0x118/0x140
> >> [ 577.179576] ? set_kthread_struct+0x40/0x40
> >> [ 577.180683] ret_from_fork+0x1f/0x30
> >>
> >>
> >> [ 577.181823] INFO: task xfs_io:8398 blocked for more than 6 seconds.
> >> [ 577.182977] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 577.184087] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 577.185216] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> >> [ 577.186364] Call Trace:
> >> [ 577.187492] __schedule+0x37c/0x7a0
> >> [ 577.188611] schedule+0x3a/0xa0
> >> [ 577.189711] wait_current_trans+0xc2/0x120 [btrfs]
> >> [ 577.190862] ? finish_wait+0x80/0x80
> >> [ 577.191941] start_transaction+0x490/0x590 [btrfs]
> >> [ 577.193073] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> >> [ 577.194220] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> >> [ 577.195355] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> >> [ 577.196464] btrfs_clone+0x796/0x7f0 [btrfs]
> >> [ 577.197627] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> >> [ 577.198790] btrfs_clone_files+0xfc/0x150 [btrfs]
> >> [ 577.199947] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> >> [ 577.201105] do_clone_file_range+0xea/0x230
> >> [ 577.202212] vfs_clone_file_range+0x37/0x110
> >> [ 577.203308] ioctl_file_clone+0x7d/0xb0
> >> [ 577.204398] do_vfs_ioctl+0x47d/0x7f0
> >> [ 577.205470] __x64_sys_ioctl+0x62/0xc0
> >> [ 577.206527] do_syscall_64+0x37/0x80
> >> [ 577.207573] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [ 577.208627] RIP: 0033:0x7fe48946c62b
> >> [ 577.209679] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> >> [ 577.210755] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> >> [ 577.211834] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> >> [ 577.212913] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> >> [ 577.213992] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> >> [ 577.215066] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
> >>
> >>
> >> [ 579.278098] INFO: task btrfs-transacti:8203 blocked for more than 8 seconds.
> >> [ 579.279201] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 579.280278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 579.281373] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> >> [ 579.282486] Call Trace:
> >> [ 579.283590] __schedule+0x37c/0x7a0
> >> [ 579.284698] schedule+0x3a/0xa0
> >> [ 579.285801] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> >> [ 579.286991] ? finish_wait+0x80/0x80
> >> [ 579.288104] transaction_kthread+0x13d/0x190 [btrfs]
> >> [ 579.289270] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> >> [ 579.290435] kthread+0x118/0x140
> >> [ 579.291553] ? set_kthread_struct+0x40/0x40
> >> [ 579.292661] ret_from_fork+0x1f/0x30
> >> [ 579.293764] INFO: task xfs_io:8398 blocked for more than 8 seconds.
> >> [ 579.294880] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 579.295990] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 579.297120] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> >> [ 579.298264] Call Trace:
> >> [ 579.299388] __schedule+0x37c/0x7a0
> >> [ 579.300503] schedule+0x3a/0xa0
> >> [ 579.301601] wait_current_trans+0xc2/0x120 [btrfs]
> >> [ 579.302747] ? finish_wait+0x80/0x80
> >> [ 579.303828] start_transaction+0x490/0x590 [btrfs]
> >> [ 579.304959] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> >> [ 579.306103] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> >> [ 579.307235] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> >> [ 579.308341] btrfs_clone+0x796/0x7f0 [btrfs]
> >> [ 579.309500] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> >> [ 579.310661] btrfs_clone_files+0xfc/0x150 [btrfs]
> >> [ 579.311817] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> >> [ 579.313144] do_clone_file_range+0xea/0x230
> >> [ 579.314251] vfs_clone_file_range+0x37/0x110
> >> [ 579.315350] ioctl_file_clone+0x7d/0xb0
> >> [ 579.316441] do_vfs_ioctl+0x47d/0x7f0
> >> [ 579.317516] __x64_sys_ioctl+0x62/0xc0
> >> [ 579.318576] do_syscall_64+0x37/0x80
> >> [ 579.319623] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [ 579.320682] RIP: 0033:0x7fe48946c62b
> >> [ 579.321736] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> >> [ 579.322812] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> >> [ 579.323895] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> >> [ 579.324980] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> >> [ 579.326061] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> >> [ 579.327139] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
> >>
> >>
> >> [ 581.390104] INFO: task btrfs-transacti:8203 blocked for more than 10 seconds.
> >> [ 581.391207] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 581.392290] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 581.393391] task:btrfs-transacti state:D stack: 0 pid: 8203 ppid: 2 flags:0x00004000
> >> [ 581.394513] Call Trace:
> >> [ 581.395621] __schedule+0x37c/0x7a0
> >> [ 581.396733] schedule+0x3a/0xa0
> >> [ 581.397841] btrfs_commit_transaction+0x200/0xac0 [btrfs]
> >> [ 581.399040] ? finish_wait+0x80/0x80
> >> [ 581.400160] transaction_kthread+0x13d/0x190 [btrfs]
> >> [ 581.401331] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
> >> [ 581.402502] kthread+0x118/0x140
> >> [ 581.403626] ? set_kthread_struct+0x40/0x40
> >> [ 581.404741] ret_from_fork+0x1f/0x30
> >>
> >>
> >> [ 581.405848] INFO: task xfs_io:8398 blocked for more than 10 seconds.
> >> [ 581.406966] Not tainted 5.15.0-1.el7.x86_64 #1
> >> [ 581.408082] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [ 581.409220] task:xfs_io state:D stack: 0 pid: 8398 ppid: 8397 flags:0x00004004
> >> [ 581.410373] Call Trace:
> >> [ 581.411507] __schedule+0x37c/0x7a0
> >> [ 581.412632] schedule+0x3a/0xa0
> >> [ 581.413739] wait_current_trans+0xc2/0x120 [btrfs]
> >> [ 581.414893] ? finish_wait+0x80/0x80
> >> [ 581.415977] start_transaction+0x490/0x590 [btrfs]
> >> [ 581.417116] btrfs_replace_file_extents+0xfd/0x880 [btrfs]
> >> [ 581.418438] ? btrfs_search_slot+0x8e3/0x900 [btrfs]
> >> [ 581.419577] ? __raw_callee_save___native_queued_spin_unlock+0x11/0x1e
> >> [ 581.420691] btrfs_clone+0x796/0x7f0 [btrfs]
> >> [ 581.422025] ? __btrfs_add_free_space+0x8c/0x4c0 [btrfs]
> >> [ 581.423199] btrfs_clone_files+0xfc/0x150 [btrfs]
> >> [ 581.424364] btrfs_remap_file_range+0x3d8/0x4a0 [btrfs]
> >> [ 581.425528] do_clone_file_range+0xea/0x230
> >> [ 581.426640] vfs_clone_file_range+0x37/0x110
> >> [ 581.427743] ioctl_file_clone+0x7d/0xb0
> >> [ 581.428839] do_vfs_ioctl+0x47d/0x7f0
> >> [ 581.429919] __x64_sys_ioctl+0x62/0xc0
> >> [ 581.430983] do_syscall_64+0x37/0x80
> >> [ 581.432121] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [ 581.433302] RIP: 0033:0x7fe48946c62b
> >> [ 581.434368] RSP: 002b:00007ffff68bb648 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> >> [ 581.435457] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fe48946c62b
> >> [ 581.436547] RDX: 00007ffff68bb680 RSI: 000000004020940d RDI: 0000000000000003
> >> [ 581.437636] RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000000d5f2c
> >> [ 581.438722] R10: 00007ffff690d080 R11: 0000000000000246 R12: 0000000000000000
> >> [ 581.439808] R13: 0000000000000000 R14: 0000562c0a4f29c8 R15: 0000000400000000
> >>
> >> Best Regards
> >> Wang Yugui (wangyugui@e16-tech.com)
> >> 2021/11/03
> >>
> >
> >
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: btrfs reflink take too long time(21s)
2021-11-05 13:08 ` Wang Yugui
2021-11-05 13:16 ` Qu Wenruo
@ 2021-11-05 16:08 ` David Sterba
1 sibling, 0 replies; 5+ messages in thread
From: David Sterba @ 2021-11-05 16:08 UTC (permalink / raw)
To: Wang Yugui; +Cc: linux-btrfs
On Fri, Nov 05, 2021 at 09:08:54PM +0800, Wang Yugui wrote:
> Is this problem reproduced by other people?
>
> It seems a blocker kernel issue for the coming btrfs-progs 5.15 release.
> becase DUP metadata become default for single SSD in the coming btrfs-progs 5.15 release.
I don't consider it a blocker for btrfs-progs 5.15 release, the same set
of features can be enabled manually and it's reproduced by a fstest case
that's crafted to specially to make reflink slow and monitor how it
reacts to ctrl-c. This is probably a performance issue and to be fixed
on kernel side anyway.
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2021-11-05 16:09 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-11-03 10:41 btrfs reflink take too long time(21s) Wang Yugui
2021-11-05 13:08 ` Wang Yugui
2021-11-05 13:16 ` Qu Wenruo
2021-11-05 13:55 ` Wang Yugui
2021-11-05 16:08 ` David Sterba
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.