From: Wang Yugui <wangyugui@e16-tech.com>
To: linux-btrfs@vger.kernel.org
Subject: btrfs reflink take too long time(21s)
Date: Wed, 03 Nov 2021 18:41:34 +0800 [thread overview]
Message-ID: <20211103184134.631B.409509F4@e16-tech.com> (raw)
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 reply other threads:[~2021-11-03 10:41 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
2021-11-03 10:41 Wang Yugui [this message]
2021-11-05 13:08 ` btrfs reflink take too long time(21s) Wang Yugui
2021-11-05 13:16 ` Qu Wenruo
2021-11-05 13:55 ` Wang Yugui
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=20211103184134.631B.409509F4@e16-tech.com \
--to=wangyugui@e16-tech.com \
--cc=linux-btrfs@vger.kernel.org \
/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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox