Re: Possible io_uring related race leads to btrfs data csum mismatch

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

Hi Jens

I tried more on my side to debug the situation, and found a very weird
write behavior:

	Some unexpected direct IO happened, without corresponding
	fsstress workload.

The workload is:

	$fsstress -p 7 -n 50 -s 1691396493 -w -d $mnt -v > /tmp/fsstress

Which I can reliably reproduce the problem locally, around 1/50 possibility.
In my particular case, it results data corruption at root 5 inode 283
offset 8192.

Then I added some trace points for the following functions:

- btrfs_do_write_iter()
   Two trace points, one before btrfs_direct_write(), and one
   before btrfs_buffered_write(), outputting the aligned and unaligned
   write range, root/inode number, type of the write (buffered or
   direct).

- btrfs_finish_one_ordered()
   This is where btrfs inserts its ordered extent into the subvolume
   tree.
   This happens when a range of pages finishes its writeback.

Then here comes the fsstress log for inode 283 (no btrfs root number):

0/22: clonerange d0/f2[283 1 0 0 0 0] [0,0] -> d0/f2[283 1 0 0 0 0]
[307200,0]
0/23: copyrange d0/f2[283 1 0 0 0 0] [0,0] -> d0/f2[283 1 0 0 0 0]
[1058819,0]
0/25: write d0/f2[283 2 0 0 0 0] [393644,88327] 0
0/29: fallocate(INSERT_RANGE) d0/f3 [283 2 0 0 176 481971]t 884736 585728 95
0/30: uring_write d0/f3[283 2 0 0 176 481971] [1400622, 56456(res=56456)] 0
0/31: writev d0/f3[283 2 0 0 296 1457078] [709121,8,964] 0
0/33: do_aio_rw - xfsctl(XFS_IOC_DIOINFO) d0/f2[283 2 308134 1763236 320
1457078] return 25, fallback to stat()
0/34: dwrite - xfsctl(XFS_IOC_DIOINFO) d0/f3[283 2 308134 1763236 320
1457078] return 25, fallback to stat()
0/34: dwrite d0/f3[283 2 308134 1763236 320 1457078] [589824,16384] 0
0/38: dwrite - xfsctl(XFS_IOC_DIOINFO) d0/f3[283 2 308134 1763236 496
1457078] return 25, fallback to stat()
0/38: dwrite d0/f3[283 2 308134 1763236 496 1457078] [2084864,36864] 0
0/39: write d0/d4/f6[283 2 308134 1763236 496 2121728] [2749000,60139] 0
0/40: fallocate(ZERO_RANGE) d0/f3 [283 2 308134 1763236 688 2809139]t
3512660 81075 0
0/43: splice d0/f5[293 1 0 0 1872 2678784] [552619,59420] -> d0/f3[283 2
308134 1763236 856 3593735] [5603798,59420] 0
0/48: fallocate(KEEP_SIZE|PUNCH_HOLE) d0/f3 [283 1 308134 1763236 976
5663218]t 1361821 480392 0
0/49: clonerange d0/f3[283 1 308134 1763236 856 5663218] [2461696,53248]
-> d0/f5[293 1 0 0 1872 2678784] [942080,53248]

Note one thing, there is no direct/buffered write into inode 283 offset
8192.

But from the trace events for root 5 inode 283:

  btrfs_do_write_iter: r/i=5/283 buffered fileoff=393216(393644)
len=90112(88327)
  btrfs_do_write_iter: r/i=5/283 buffered fileoff=1396736(1400622)
len=61440(56456)
  btrfs_do_write_iter: r/i=5/283 buffered fileoff=708608(709121)
len=12288(7712)

  btrfs_do_write_iter: r/i=5/283 direct fileoff=8192(8192)
len=73728(73728) <<<<<

  btrfs_do_write_iter: r/i=5/283 direct fileoff=589824(589824)
len=16384(16384)
  btrfs_finish_one_ordered: r/i=5/283 fileoff=8192 len=73728
  btrfs_finish_one_ordered: r/i=5/283 fileoff=589824 len=16384
  btrfs_do_write_iter: r/i=5/283 direct fileoff=2084864(2084864)
len=36864(36864)
  btrfs_finish_one_ordered: r/i=5/283 fileoff=2084864 len=36864
  btrfs_do_write_iter: r/i=5/283 buffered fileoff=2748416(2749000)
len=61440(60139)
  btrfs_do_write_iter: r/i=5/283 buffered fileoff=5603328(5603798)
len=61440(59420)
  btrfs_finish_one_ordered: r/i=5/283 fileoff=393216 len=90112
  btrfs_finish_one_ordered: r/i=5/283 fileoff=708608 len=12288
  btrfs_finish_one_ordered: r/i=5/283 fileoff=1396736 len=61440
  btrfs_finish_one_ordered: r/i=5/283 fileoff=3592192 len=4096
  btrfs_finish_one_ordered: r/i=5/283 fileoff=2748416 len=61440
  btrfs_finish_one_ordered: r/i=5/283 fileoff=5603328 len=61440

Note that phantom direct IO call, which is in the corrupted range.

If paired with fsstress, that phantom write happens between the two
operations:

0/31: writev d0/f3[283 2 0 0 296 1457078] [709121,8,964] 0
0/34: dwrite d0/f3[283 2 308134 1763236 320 1457078] [589824,16384] 0

I'll keep digging, but the phantom writes which is not properly loggeg
from fsstress is already a concern to me.

Or maybe I'm missing some fixes in fsstress?

Thanks,
Qu