Re: [PATCH] fuse_writepages_fill() optimization to avoid WARN_ON in tree_insert

[Vivek Goyal]

On Thu, Jun 25, 2020 at 12:02:53PM +0300, Vasily Averin wrote:
> In current implementation fuse_writepages_fill() tries to share the code:
> for new wpa it calls tree_insert() with num_pages = 0
> then switches to common code used non-modified num_pages
> and increments it at the very end.
> 
> Though it triggers WARN_ON(!wpa->ia.ap.num_pages) in tree_insert()
>  WARNING: CPU: 1 PID: 17211 at fs/fuse/file.c:1728 tree_insert+0xab/0xc0 [fuse]
>  RIP: 0010:tree_insert+0xab/0xc0 [fuse]
>  Call Trace:
>   fuse_writepages_fill+0x5da/0x6a0 [fuse]
>   write_cache_pages+0x171/0x470
>   fuse_writepages+0x8a/0x100 [fuse]
>   do_writepages+0x43/0xe0
> 
> This patch re-works fuse_writepages_fill() to call tree_insert()
> with num_pages = 1 and avoids its subsequent increment and
> an extra spin_lock(&fi->lock) for newly added wpa.
> 
> Fixes: 6b2fb79963fb ("fuse: optimize writepages search")
> Reported-by: kernel test robot <rong.a.chen@xxxxxxxxx>
> Signed-off-by: Vasily Averin <vvs@xxxxxxxxxxxxx>

I think I am facing this issue with virtiofs. I am running podman which
mounts overlayfs over virtiofs (virtiofs uses fuse). While running podman
I am seeing tons of following warnings no console. So this needs to
be fixed in 5.8-rc.

[24908.795483] ------------[ cut here ]------------
[24908.795484] WARNING: CPU: 6 PID: 11376 at fs/fuse/file.c:1684 tree_insert+0xaf/0xc0
[24908.795484] Modules linked in: ip6table_nat ip6_tables xt_conntrack xt_MASQUERADE xt_comment iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 veth overlay dax_pmem_compat virtio_net device_dax dax_pmem_core net_failover joydev failover br_netfilter bridge drm stp llc virtiofs virtio_blk serio_raw nd_pmem nd_btt qemu_fw_cfg
[24908.795495] CPU: 6 PID: 11376 Comm: dnf Tainted: G        W         5.8.0-rc2+ #18
[24908.795496] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014
[24908.795496] RIP: 0010:tree_insert+0xaf/0xc0
[24908.795497] Code: 80 c8 00 00 00 49 c7 80 d0 00 00 00 00 00 00 00 49 c7 80 d8 00 00 00 00 00 00 00 48 89 39 e9 a8 9a 1b 00 0f 0b eb a5 0f 0b c3 <0f> 0b e9 71 ff ff ff 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
[24908.795497] RSP: 0018:ffffb17840717bc0 EFLAGS: 00010246
[24908.795498] RAX: 0000000000000000 RBX: ffffb17840717d20 RCX: 8c6318c6318c6319
[24908.795499] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9f6cc1a72ee0
[24908.795499] RBP: ffffe0dedfd6e640 R08: ffff9f6d1261c800 R09: ffffffffffffffff
[24908.795500] R10: ffff9f6cc1a72ee0 R11: 0000000000000000 R12: ffffe0dee05725c0
[24908.795500] R13: ffff9f6cc1a72a00 R14: ffff9f6cc1a72f90 R15: ffff9f6d1261c800
[24908.795501] FS:  00007f377b267740(0000) GS:ffff9f6d1fa00000(0000) knlGS:0000000000000000
[24908.795501] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[24908.795502] CR2: 00007f37777588e8 CR3: 0000000828a0e000 CR4: 00000000000006e0
[24908.795502] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[24908.795503] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[24908.795503] Call Trace:
[24908.795504]  fuse_writepages_fill+0x5b0/0x670
[24908.795504]  write_cache_pages+0x1c2/0x4b0
[24908.795504]  ? fuse_writepages+0x110/0x110
[24908.795505]  fuse_writepages+0x8d/0x110
[24908.795505]  do_writepages+0x34/0xc0
[24908.795506]  __filemap_fdatawrite_range+0xc5/0x100
[24908.795506]  filemap_write_and_wait_range+0x40/0xa0
[24908.795507]  remove_vma+0x31/0x70
[24908.795507]  __do_munmap+0x2d9/0x4a0
[24908.795507]  __vm_munmap+0x6a/0xc0
[24908.795508]  __x64_sys_munmap+0x28/0x30
[24908.795508]  do_syscall_64+0x52/0xb0
[24908.795509]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[24908.795509] RIP: 0033:0x7f377b81067b
[24908.795510] Code: Bad RIP value.
[24908.795510] RSP: 002b:00007ffd88f96fd8 EFLAGS: 00000246 ORIG_RAX: 000000000000000b
[24908.795511] RAX: ffffffffffffffda RBX: 0000559c662c79d0 RCX: 00007f377b81067b
[24908.795511] RDX: 0000559c66349720 RSI: 0000000000104000 RDI: 00007f37778da000
[24908.795512] RBP: 00007f37778da1e0 R08: 00007f3777894308 R09: 0000000000000001
[24908.795512] R10: 00000000000001a4 R11: 0000000000000246 R12: 0000000000000000
[24908.795513] R13: 0000559c65d843a0 R14: 00007f37778da000 R15: 0000000000000017
[24908.795515] irq event stamp: 3775373
[24908.795515] hardirqs last  enabled at (3775373): [<ffffffffa72f6a21>] page_outside_zone_boundaries+0xd1/0x100
[24908.795516] hardirqs last disabled at (3775372): [<ffffffffa72f698e>] page_outside_zone_boundaries+0x3e/0x100
[24908.795517] softirqs last  enabled at (3775348): [<ffffffffa7e0035d>] __do_softirq+0x35d/0x400
[24908.795517] softirqs last disabled at (3775341): [<ffffffffa7c01052>] asm_call_on_stack+0x12/0x20
[24908.795518] ---[ end trace f23c513c015212d2 ]---