From: Wang Yugui <wangyugui@e16-tech.com>
To: Qu Wenruo <quwenruo.btrfs@gmx.com>
Cc: linux-btrfs@vger.kernel.org
Subject: Re: btrfs reflink take too long time(21s)
Date: Fri, 05 Nov 2021 21:55:41 +0800 [thread overview]
Message-ID: <20211105215541.64DF.409509F4@e16-tech.com> (raw)
In-Reply-To: <e1651d3b-e556-9f12-18f0-1d5728f33bb7@gmx.com>
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
> >>
> >
> >
next prev parent reply other threads:[~2021-11-05 13:55 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
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 [this message]
2021-11-05 16:08 ` David Sterba
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20211105215541.64DF.409509F4@e16-tech.com \
--to=wangyugui@e16-tech.com \
--cc=linux-btrfs@vger.kernel.org \
--cc=quwenruo.btrfs@gmx.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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.