Re: LMDB mdb_copy produces a corrupt database on btrfs, but not on ext4

[Boris Burkov <boris@bur.io>]

On Thu, Feb 16, 2023 at 11:57:37AM +0000, Filipe Manana wrote:
> On Thu, Feb 16, 2023 at 12:42 AM Boris Burkov <boris@bur.io> wrote:
> >
> > On Wed, Feb 15, 2023 at 03:21:38PM -0800, Boris Burkov wrote:
> > > On Wed, Feb 15, 2023 at 03:16:39PM -0500, Chris Murphy wrote:
> > > >
> > > >
> > > > On Wed, Feb 15, 2023, at 3:04 PM, Chris Murphy wrote:
> > > > > Downstream bug report, reproducer test file, and gdb session transcript
> > > > > https://bugzilla.redhat.com/show_bug.cgi?id=2169947
> > > > >
> > > > > I speculated that maybe it's similar to the issue we have with VM's
> > > > > when O_DIRECT is used, but it seems that's not the case here.
> > > >
> > > > I can reproduce the mismatching checksums whether the test files are datacow or nodatacow (using chattr +C). There are no kernel messages during the tests.
> > > >
> > > > kernel 6.2rc7 in my case; and in the bug report kernel series 6.1, 6.0, and 5.17 reproduce the problem.
> > > >
> > >
> > > I was also able to reproduce on the current misc-next. However, when I
> > > hacked the kernel to always fall back from DIO to buffered IO, it no
> > > longer reproduced. So that's one hint..
> > >
> > > The next observation comes from comparing the happy vs unhappy file
> > > extents on disk:
> > > happy: https://pastebin.com/k4EPFKhc
> > > unhappy: https://pastebin.com/hNSBR0yv
> > >
> > > The broken DIO case is missing file extents between bytes 8192 and 65536
> > > which corresponds to the observed zeros.
> > >
> > > Next, at Josef's suggestion, I looked at the IOMAP_DIO_PARTIAL and
> > > instrumented that codepath. I observed a single successful write to 8192
> > > bytes, then a second write which first does a partial write from 8192 to
> > > 65536 and then faults in the rest of the iov_iter and finishes the
> > > write.
> > >
> > > I'm now trying to figure out how these partial writes might lead us to
> > > not create all the EXTENT_DATA items for the file extents.
> >
> > I believe the issue is indeed caused by faults reading the mapped region
> > during direct io. Roughly what is happening is:
> >
> > - we start the dio write (offset 8192 len 1826816)
> > - __iomap_dio_rw calls iomap_iter which calls btrfs_dio_iomap_begin which
> >   creates an ordered extent for the full write.
> > - iomap_dio_iter hits a page fault in bio_iov_iter_get_pages after 57344
> >   bytes and breaks out early, but submits the partial bio.
> > - the partial bio completes and calls the various endio callbacks,
> >   resulting in a call to btrfs_mark_ordered_io_finished.
> > - btrfs_mark_ordered_io_finished looks up the ordered extent and finds
> >   the full ordered extent, but the write that finished is partial, so
> >   the check for entry->bytes_left fails, and we don't call
> >   finish_ordered_fn and thus don't create a file extent item for this
> >   endio.
> > - the IOMAP_DIO_PARTIAL logic results in us retrying starting from 65536
> >   (8192 + 57344) but we fully exit and re-enter __iomap_dio_rw, which
> >   creates a new ordered extent for off 65536 len 1769472 and that
> >   ordered extent proceeds as above but successfully, and we get the
> >   second file extent.
> 
> So one thing doesn't add up here.
> 
> The first write attempt creates the ordered extent for the range
> [8192, 1835008],
> we then submit a bio only for the range [8192, 65535], due to the page
> fault at 64K.
> 
> That means that the ordered extent can not be completed, as you said
> before, as ->bytes_left will be > 0 even after the submitted bio
> completes.
> 
> However, the second time we enter btrfs_dio_iomap_begin(), for the
> range [65536, 1835008], when we call lock_extent_direct(), we should
> find the previous ordered extent, for range [8192, 1835008], which
> intersects this second range - and that should make us wait for the
> previous
> ordered extent until it completes by calling
> btrfs_start_ordered_extent() at lock_extent_direct(). This is clearly
> not happening, as it would cause
> a deadlock/hang.
> 
> So something is missing in your analysis, and that's important to
> figure out the best solution to the problem.
> 
> Thanks.
> 

Good point. I was confused about the extra ordered extents floating
around as well. I believe I do have an explanation now. I think the
following annotated callchain should explain it decently, but the tl;dr
is that iomap_iter calls btrfs_dio_iomap_end which marks the ordered
extent finished and clears the extent bits, but hits an error so it does
not do much other endio work. (the error comes from
mark_ordered_io_finished getting called without uptodate set)

btrfs_direct_write
  __iomap_dio_rw
    iomap_iter
      btrfs_dio_iomap_begin # creates the oe 8192 1835008
    iomap_dio_iter # submits the partial bio 8192 57344 (CB1)
      btrfs_dio_iomap_end
        btrfs_mark_ordered_io_finished 65536 1769472
        # ^ finds and munges the oe, decides bytes_left is 0 and queues
        # the full finish work (CB2)
    # partial write return
  __iomap_dio_rw # btrfs_direct_write tries again
    iomap_dio_iter
      btrfs_dio_iomap_begin # makes the next OE
    iomap_dio_iter # submits the remaining write 65536 1769472 (CB3)

btrfs_dio_end_io 8192 57344 (CB1)
# finds the full oe and bails, as discussed above

btrfs_finish_ordered_io 65536 1769472 (CB2)
# sees BTRFS_ORDERED_IOERR exits and clears the extent

btrfs_dio_end_io 65536 1769472 (CB3)
# succeeds on the new oe for that range and queues full finish work
# which writes an extent

In my opinion, the part of this that feels like it is not behaving
properly is the interaction between the iomap_iter logic of
__iomap_dio_rw and the implementation of btrfs_dio_iomap_begin/end.
Something about the begin/end calls the generic loop is doing is getting
us to believe that large extent was "finished" but with an error set. If
that is an appropriate way to handle the partial write, then maybe the
splitting I proposed earlier works as a fix. Otherwise we may need to
handle this case more explicitly in iomap_iter/btrfs_dio_iomap_end.

> 
> 
> 
> >
> > I'm not yet sure how to fix this, but have a couple ideas/questions:
> > 1. Is there anyway we can split off a partial ordered extent and finish
> > it when we get the partial write done?
> > 2. Can we detect that there is an unfinished ordered extent that
> > overlaps with our new one on the second write of the partial write
> > logic?
> >
> > I'll play around and see if I can hack together a fix..
> >
> > >
> > > Boris
> > >
> > > >
> > > > --
> > > > Chris Murphy