[btrfs?] INFO: task hung in start_transaction

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=124042b0480000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=edcc9d8008424faab3de
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=123acc60480000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=13059c88480000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/98c0bdb4abb3/disk-3f8a27f9.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/ea228ff02669/vmlinux-3f8a27f9.xz
mounted in repro: https://storage.googleapis.com/syzbot-assets/d35bf6256313/mount_0.gz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+edcc9d...@syzkaller.appspotmail.com

INFO: task kworker/u4:0:7 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:0 D26352 7 2 0x80000000
Workqueue: events_unbound btrfs_async_reclaim_metadata_space
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
wait_current_trans+0x2e2/0x390 fs/btrfs/transaction.c:422
start_transaction+0x699/0xf90 fs/btrfs/transaction.c:536
flush_space+0x9af/0xee0 fs/btrfs/extent-tree.c:4839
btrfs_async_reclaim_metadata_space+0x466/0x1050 fs/btrfs/extent-tree.c:4977
process_one_work+0x864/0x1570 kernel/workqueue.c:2153
worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task btrfs-transacti:8129 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D26296 8129 2 0x80000000
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
btrfs_tree_lock+0x4fe/0x810 fs/btrfs/locking.c:233
btrfs_init_new_buffer fs/btrfs/extent-tree.c:8145 [inline]
btrfs_alloc_tree_block+0x9b1/0x15f0 fs/btrfs/extent-tree.c:8284
alloc_tree_block_no_bg_flush+0x1b6/0x250 fs/btrfs/ctree.c:1039
__btrfs_cow_block+0x3c7/0x10a0 fs/btrfs/ctree.c:1094
btrfs_cow_block+0x276/0x840 fs/btrfs/ctree.c:1557
btrfs_search_slot+0x66a/0x1ee0 fs/btrfs/ctree.c:2881
btrfs_update_root+0xc9/0x6b0 fs/btrfs/root-tree.c:134
commit_fs_roots+0x3b5/0x530 fs/btrfs/transaction.c:1286
btrfs_commit_transaction+0x8ca/0x2480 fs/btrfs/transaction.c:2178
transaction_kthread+0x385/0x490 fs/btrfs/disk-io.c:1794
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415

Showing all locks held in the system:
3 locks held by kworker/u4:0/7:
#0: 00000000dd4ea6b7 ((wq_completion)"events_unbound"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
#1: 00000000c4223881 ((work_completion)(work)#2){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
#2: 000000007292fc44 (sb_internal#2){.+.+}, at: sb_start_intwrite include/linux/fs.h:1626 [inline]
#2: 000000007292fc44 (sb_internal#2){.+.+}, at: start_transaction+0xa37/0xf90 fs/btrfs/transaction.c:528
1 lock held by khungtaskd/1570:
#0: 0000000013e9af05 (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
1 lock held by in:imklog/7758:
#0: 000000009892ed3c (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
3 locks held by btrfs-transacti/8129:
#0: 000000002af6b2b8 (&fs_info->transaction_kthread_mutex){+.+.}, at: transaction_kthread+0xfa/0x490 fs/btrfs/disk-io.c:1765
#1: 00000000291f04a6 (&fs_info->reloc_mutex){+.+.}, at: btrfs_commit_transaction+0x80b/0x2480 fs/btrfs/transaction.c:2120
#2: 00000000216c0ce4 (&fs_info->tree_log_mutex){+.+.}, at: btrfs_commit_transaction+0x8c2/0x2480 fs/btrfs/transaction.c:2176
2 locks held by syz-executor231/16927:

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 1570 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x991/0xe60 kernel/hung_task.c:287
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 16927 Comm: syz-executor231 Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
RIP: 0010:free_pages_prepare mm/page_alloc.c:1062 [inline]
RIP: 0010:free_pcp_prepare mm/page_alloc.c:1070 [inline]
RIP: 0010:free_unref_page_prepare+0x1f9/0x5d0 mm/page_alloc.c:2763
Code: c1 e4 0c 49 01 fc 4c 89 e7 e8 93 66 cc ff be 00 10 00 00 4c 89 e7 e8 b6 e6 f8 01 31 d2 be 01 00 00 00 48 89 ef e8 77 7d 19 00 <31> f6 48 89 ef e8 ad f3 19 00 48 c7 c0 20 5a 25 8d 48 ba 00 00 00
RSP: 0018:ffff888090a17860 EFLAGS: 00000293
RAX: ffff888095214280 RBX: 00000000000881cf RCX: ffffffff8197e0dc
RDX: 0000000000000000 RSI: ffffffff817e6339 RDI: 0000000000000001
RBP: ffffea00022073c0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000000 R12: ffff8880881cf000
R13: 0000000000000011 R14: dffffc0000000000 R15: ffffea0002207380
FS: 00005555556ed3c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000559bc203f0e8 CR3: 00000000b4c15000 CR4: 00000000003406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
free_unref_page_list+0xd8/0x7b0 mm/page_alloc.c:2832
release_pages+0xb0d/0x15a0 mm/swap.c:800
__pagevec_release+0x7b/0x150 mm/swap.c:820
pagevec_release include/linux/pagevec.h:86 [inline]
shmem_undo_range+0xb35/0x1e40 mm/shmem.c:873
shmem_truncate_range mm/shmem.c:995 [inline]
shmem_evict_inode+0x31c/0x8f0 mm/shmem.c:1095
evict+0x2ed/0x760 fs/inode.c:559
iput_final fs/inode.c:1555 [inline]
iput+0x4f1/0x860 fs/inode.c:1581
dentry_unlink_inode+0x265/0x320 fs/dcache.c:374
__dentry_kill+0x3c0/0x640 fs/dcache.c:566
dentry_kill+0xc4/0x510 fs/dcache.c:685
dput+0x55f/0x640 fs/dcache.c:846
__fput+0x415/0x890 fs/file_table.c:291
task_work_run+0x148/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x251/0x2a0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7fef46f82a53
Code: c7 c2 c0 ff ff ff f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb ba 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8
RSP: 002b:00007ffe62137bb8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000003 RCX: 00007fef46f82a53
RDX: 0000000000000010 RSI: 0000000000004c00 RDI: 0000000000000003
RBP: 00007ffe62137bd0 R08: 00000000000050ed R09: 00000000000050e9
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000004
R13: 00005555556ed380 R14: 0000000000000080 R15: 00007ffe62137c10


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches