Re: [syzbot] [btrfs?] kernel BUG in __folio_start_writeback

Matthew Wilcox
2024-11-24T21:48:18Z

On Sun, Nov 24, 2024 at 05:45:18AM -0800, syzbot wrote:
>
> __fput+0x5ba/0xa50 fs/file_table.c:458
> task_work_run+0x24f/0x310 kernel/task_work.c:239
> resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
> exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
> exit_to_user_mode_prepare include/linux/entry-common.h:329 [inline]
> __syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
> syscall_exit_to_user_mode+0x13f/0x340 kernel/entry/common.c:218
> do_syscall_64+0x100/0x230 arch/x86/entry/common.c:89
> entry_SYSCALL_64_after_hwframe+0x77/0x7f

This is:

VM_BUG_ON_FOLIO(folio_test_writeback(folio), folio);

ie we've called __folio_start_writeback() on a folio which is already
under writeback.

Higher up in the trace, we have the useful information:

page: refcount:6 mapcount:0 mapping:ffff888077139710 index:0x3 pfn:0x72ae5
memcg:ffff888140adc000
aops:btrfs_aops ino:105 dentry name(?):"file2"
flags: 0xfff000000040ab(locked|waiters|uptodate|lru|private|writeback|node=0|zone=1|lastcpupid=0x7ff)
raw: 00fff000000040ab ffffea0001c8f408 ffffea0000939708 ffff888077139710
raw: 0000000000000003 0000000000000001 00000006ffffffff ffff888140adc000
page dumped because: VM_BUG_ON_FOLIO(folio_test_writeback(folio))
page_owner tracks the page as allocated

The interesting part of the page_owner stacktrace is:

filemap_alloc_folio_noprof+0xdf/0x500
__filemap_get_folio+0x446/0xbd0
prepare_one_folio+0xb6/0xa20
btrfs_buffered_write+0x6bd/0x1150
btrfs_direct_write+0x52d/0xa30
btrfs_do_write_iter+0x2a0/0x760
do_iter_readv_writev+0x600/0x880
vfs_writev+0x376/0xba0

(ie not very interesting)

> Workqueue: btrfs-delalloc btrfs_work_helper
> RIP: 0010:__folio_start_writeback+0xc06/0x1050 mm/page-writeback.c:3119
> Call Trace:
> <TASK>
> process_one_folio fs/btrfs/extent_io.c:187 [inline]
> __process_folios_contig+0x31c/0x540 fs/btrfs/extent_io.c:216
> submit_one_async_extent fs/btrfs/inode.c:1229 [inline]
> submit_compressed_extents+0xdb3/0x16e0 fs/btrfs/inode.c:1632
> run_ordered_work fs/btrfs/async-thread.c:245 [inline]
> btrfs_work_helper+0x56b/0xc50 fs/btrfs/async-thread.c:324
> process_one_work kernel/workqueue.c:3229 [inline]

This looks like a race?

process_one_folio() calls
btrfs_folio_clamp_set_writeback calls
btrfs_subpage_set_writeback:

spin_lock_irqsave(&subpage->lock, flags);
bitmap_set(subpage->bitmaps, start_bit, len >> fs_info->sectorsize_bits)
;
if (!folio_test_writeback(folio))
folio_start_writeback(folio);
spin_unlock_irqrestore(&subpage->lock, flags);

so somebody else set writeback after we tested for writeback here.

One thing that comes to mind is that _usually_ we take folio_lock()
first, then start writeback, then call folio_unlock() and btrfs isn't
doing that here (afaict). Maybe that's not the source of the bug?

If it is, should we have a VM_BUG_ON_FOLIO(!folio_test_locked(folio), folio)
in __folio_start_writeback()? Or is there somewhere that can't lock the
folio before starting writeback?