Re: bisected: btrfs dedupe regression in v5.11-rc1: 3078d85c9a10 vfs: verify source area in vfs_dedupe_file_range_one()

[Nikolay Borisov <nborisov@suse.com>]

On 16.12.21 г. 7:33, Zygo Blaxell wrote:
> On Wed, Dec 15, 2021 at 12:25:04AM +0200, Nikolay Borisov wrote:
>> Huhz, this means there is an open transaction handle somewhere o_O. I
>> checked back the stacktraces in your original email but couldn't see
>> where that might be coming from. I.e all processes are waiting on
>> wait_current_trans and this happens _before_ the transaction handle is
>> opened, hence num_extwriters can't have been incremented by them.
>>
>> When an fs wedges, and you get again num_extwriters can you provde the
>> output of "echo w > /proc/sysrq-trigger"
> 
> Here you go...

<snip>

> 
> Again we have "3 locks held" but no list of locks.  WTF is 10883 doing?
> Well, first of all it's using 100% CPU in the kernel.  Some samples of
> kernel stacks:
> 
> 	# cat /proc/*/task/10883/stack
> 	[<0>] down_read_nested+0x32/0x140
> 	[<0>] __btrfs_tree_read_lock+0x2d/0x110
> 	[<0>] btrfs_tree_read_lock+0x10/0x20
> 	[<0>] btrfs_search_old_slot+0x627/0x8a0
> 	[<0>] btrfs_next_old_leaf+0xcb/0x340
> 	[<0>] find_parent_nodes+0xcd7/0x1c40
> 	[<0>] btrfs_find_all_leafs+0x63/0xb0
> 	[<0>] iterate_extent_inodes+0xc8/0x270
> 	[<0>] iterate_inodes_from_logical+0x9f/0xe0

That's the real culprit, in this case we are not searching the commit
root hence we've attached to the transaction. So we are doing backref
resolution which either:

a) Hits some pathological case and loops for very long time, backref
resolution is known to take a lot of time.

b) We hit a bug in backref resolution and loop forever which again
results in the transaction being kept open.

Now I wonder why you were able to bisect this to the seemingly unrelated
commit in the vfs code.

Josef any ideas how to proceed further to debug why backref resolution
takes a long time and if it's just an infinite loop?

> 	[<0>] btrfs_ioctl_logical_to_ino+0x183/0x210
> 	[<0>] btrfs_ioctl+0xa81/0x2fb0
> 	[<0>] __x64_sys_ioctl+0x91/0xc0
> 	[<0>] do_syscall_64+0x38/0x90
> 	[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	[<0>] __tree_mod_log_rewind+0x57/0x250
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	# cat /proc/*/task/10883/stack
> 	[<0>] free_extent_buffer.part.0+0x51/0xa0
> 	# cat /proc/*/task/10883/stack
> 	[<0>] find_held_lock+0x38/0x90
> 	[<0>] kmem_cache_alloc+0x22d/0x360
> 	[<0>] __alloc_extent_buffer+0x2a/0xa0
> 	[<0>] btrfs_clone_extent_buffer+0x42/0x130
> 	[<0>] btrfs_search_old_slot+0x660/0x8a0
> 	[<0>] btrfs_next_old_leaf+0xcb/0x340
> 	[<0>] find_parent_nodes+0xcd7/0x1c40
> 	[<0>] btrfs_find_all_leafs+0x63/0xb0
> 	[<0>] iterate_extent_inodes+0xc8/0x270
> 	[<0>] iterate_inodes_from_logical+0x9f/0xe0
> 	[<0>] btrfs_ioctl_logical_to_ino+0x183/0x210
> 	[<0>] btrfs_ioctl+0xa81/0x2fb0
> 	[<0>] __x64_sys_ioctl+0x91/0xc0
> 	[<0>] do_syscall_64+0x38/0x90
> 	[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> 
> So it looks like tree mod log is doing some infinite (or very large
> finite) looping in the LOGICAL_INO ioctl.  That ioctl holds a transaction
> open while it runs, but it's not blocked per se, so it doesn't show up
> in SysRq-W output.
>