Re: bisected: btrfs dedupe regression in v5.11-rc1

[Zygo Blaxell <ce3g8jdj@umail.furryterror.org>]

On Fri, Dec 17, 2021 at 03:50:44PM -0500, Zygo Blaxell wrote:
> On Thu, Dec 16, 2021 at 05:07:50PM -0500, Josef Bacik wrote:
> > On Thu, Dec 16, 2021 at 11:29:06PM +0200, Nikolay Borisov wrote:
> > > On 16.12.21 г. 7:33, Zygo Blaxell wrote:
> > > > 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?
> > > 
> > 
> > It's probably an infinite loop, I'd just start with something like this
> > 
> > bpftrace -e 'tracepoint:btrfs:btrfs_prelim_ref_insert { printf("bytenr is %llu", args->bytenr); }'
> > 
> > and see if it's spitting out the same shit over and over again.  If it is can I
> > get a btrfs inspect-internal dump-tree -e on the device along with the bytenr
> > it's hung up on so I can figure out wtf it's tripping over?
> 
> That bpftrace command doesn't output anything after the hang.  Before the
> hang, it's thousands and thousands of values changing as bees moves around
> the filesystem.

I left my VM running tests for a few weeks and got some more information.
Or at least more data, I'm not feeling particularly informed by it.  :-P

1.  It's not a regression.  5.10 has the same symptoms, but about 100x
less often (once a week under these test conditions, compared to once
every 90 minutes or so on 5.11-rc1).

2.  Bisection doesn't work, because there are patches that are repeatably
good and bad mixed together, so the bisect algorithm (even with stochastic
enhancement) repeatably picks the wrong commits and converges with
high confidence on nonsense.  Instead of bisecting, I picked commits
semi-randomly from 5.11-rc1's patch set, and got these results:

   124  3a160a933111 btrfs: drop never met disk total bytes check in verify_one_dev_extent
	1x hang, 2x slower
   125  bacce86ae8a7 btrfs: drop unused argument step from btrfs_free_extra_devids
	1x pass (fast)
   126  2766ff61762c btrfs: update the number of bytes used by an inode atomically
	1x hang (<20 minutes)
   127  7f458a3873ae btrfs: fix race when defragmenting leads to unnecessary IO
	1x hang, runs 3x slower
   128  5893dfb98f25 btrfs: refactor btrfs_drop_extents() to make it easier to extend
	2x hang (<20 minutes)
   129  e114c545bb69 btrfs: set the lockdep class for extent buffers on creation
	2x pass (but runs 2x slower, both times)
   130  3fbaf25817f7 btrfs: pass the owner_root and level to alloc_extent_buffer
	1x pass
   131  5d81230baa90 btrfs: pass the root owner and level around for readahead
	1x pass
   132  1b7ec85ef490 btrfs: pass root owner to read_tree_block
	1x pass
   133  182c79fcb857 btrfs: use btrfs_read_node_slot in btrfs_qgroup_trace_subtree
   134  3acfbd6a990c btrfs: use btrfs_read_node_slot in qgroup_trace_new_subtree_blocks
	1x hang
   135  6b2cb7cb959a btrfs: use btrfs_read_node_slot in qgroup_trace_extent_swap
   136  c990ada2a0bb btrfs: use btrfs_read_node_slot in walk_down_tree
	1x hang
   137  6b3426be27de btrfs: use btrfs_read_node_slot in replace_path
	1x hang, 1x pass
   138  c975253682e0 btrfs: use btrfs_read_node_slot in do_relocation
	1x hang
   139  8ef385bbf099 btrfs: use btrfs_read_node_slot in walk_down_reloc_tree
	1x hang, 1x pass
   140  206983b72a36 btrfs: use btrfs_read_node_slot in btrfs_realloc_node
	1x pass
   141  bfb484d922a3 btrfs: cleanup extent buffer readahead
	1x pass
   142  416e3445ef80 btrfs: remove lockdep classes for the fs tree
   143  3e48d8d2540d btrfs: discard: reschedule work after sysfs param update
   144  df903e5d294f btrfs: don't miss async discards after scheduled work override
   145  6e88f116bd4c btrfs: discard: store async discard delay as ns not as jiffies
	2x hang
   146  e50404a8a699 btrfs: discard: speed up async discard up to iops_limit

   [snip]

   155  0d01e247a06b btrfs: assert page mapping lock in attach_extent_buffer_page
	1x hang, 1x pass
   156  bbb86a371791 btrfs: protect fs_info->caching_block_groups by block_group_cache_lock
	1x hang
   157  e747853cae3a btrfs: load free space cache asynchronously
	1x pass
   158  4d7240f0abda btrfs: load the free space cache inode extents from commit root
	1x hang
   159  cd79909bc7cd btrfs: load free space cache into a temporary ctl
	2x pass
   160  66b53bae46c8 btrfs: cleanup btrfs_discard_update_discardable usage
	2x hang, 1x pass
   161  2ca08c56e813 btrfs: explicitly protect ->last_byte_to_unpin in unpin_extent_range
	2x pass
   162  27d56e62e474 btrfs: update last_byte_to_unpin in switch_commit_roots
	2x pass
   163  9076dbd5ee83 btrfs: do not shorten unpin len for caching block groups
   164  dc5161648693 btrfs: reorder extent buffer members for better packing
	2x pass
   165  b9729ce014f6 btrfs: locking: rip out path->leave_spinning
   166  ac5887c8e013 btrfs: locking: remove all the blocking helpers
   167  2ae0c2d80d25 btrfs: scrub: remove local copy of csum_size from context
   168  419b791ce760 btrfs: check integrity: remove local copy of csum_size
	1x hang, 1x pass
   169  713cebfb9891 btrfs: remove unnecessary local variables for checksum size
   170  223486c27b36 btrfs: switch cached fs_info::csum_size from u16 to u32
   171  55fc29bed8dd btrfs: use cached value of fs_info::csum_size everywhere
   172  fe5ecbe818de btrfs: precalculate checksums per leaf once
   173  22b6331d9617 btrfs: store precalculated csum_size in fs_info
   174  265fdfa6ce0a btrfs: replace s_blocksize_bits with fs_info::sectorsize_bits
   175  098e63082b9b btrfs: replace div_u64 by shift in free_space_bitmap_size
	2x pass
   176  ab108d992b12 btrfs: use precalculated sectorsize_bits from fs_info

   [snip]

   200  5e8b9ef30392 btrfs: move pos increment and pagecache extension to btrfs_buffered_write
	1x pass
   201  4e4cabece9f9 btrfs: split btrfs_direct_IO to read and write

   [snip]

   215  d70bf7484f72 btrfs: unify the ro checking for mount options
	1x pass
   216  a6889caf6ec6 btrfs: do not start readahead for csum tree when scrubbing non-data block groups
   217  a57ad681f12e btrfs: assert we are holding the reada_lock when releasing a readahead zone
   218  aa8c1a41a1e6 btrfs: set EXTENT_NORESERVE bits side btrfs_dirty_pages()
   219  13f0dd8f7861 btrfs: use round_down while calculating start position in btrfs_dirty_pages()
   220  949b32732eab btrfs: use iosize while reading compressed pages
   221  eefa45f59379 btrfs: calculate num_pages, reserve_bytes once in btrfs_buffered_write
   222  fb8a7e941b1b btrfs: calculate more accurate remaining time to sleep in transaction_kthread
	1x pass

There is some repeatability in these results--some commits have a much
lower failure rate than others--but I don't see a reason why the bad
commits are bad or the good commits are good.  There are some commits with
locking and concurrency implications, but they're as likely to produce
good as bad results in test.  Sometimes there's a consistent change in
test result after a commit that only rearranges function arguments on
the stack.

Maybe what we're looking at is a subtle race that is popping up due
to unrelated changes in the kernel, and disappearing just as often,
and 5.11-rc1 in particular did something innocent that aggravates
it somehow, so all later kernels hit the problem more often than
5.10 did.

3.  Somewhere around "7f458a3873ae btrfs: fix race when defragmenting
leads to unnecessary IO" bees starts running about 3x slower than on
earlier kernels.  bees is a nightmare of nondeterministically racing
worker threads, so I'm not sure how important this observation is,
but it keeps showing up in the data.

4.  I had one machine on 5.10.84 (not a test VM) with a shell process
that got stuck spinning 100% CPU in the kernel on sys_write.  bees was
also running, but its threads were all stuck waiting for the shell to
release the transaction.  Other crashes on 5.10.8x kernels look more
like the one in this thread, with a logical_ino spinning.

> > If it's not looping there, it may be looping higher up, but I don't see where it
> > would be doing that.  Lets start here and work our way up if we need to.
> > Thanks,
> > 
> > Josef