On Thu, Nov 24, 2022 at 03:40:23PM +1100, Dave Chinner wrote: > On Wed, Nov 23, 2022 at 12:00:55PM -0800, Darrick J. Wong wrote: > > On Tue, Nov 22, 2022 at 12:58:06PM +1100, Dave Chinner wrote: > > > On Mon, Nov 21, 2022 at 04:16:02PM -0800, Darrick J. Wong wrote: > > > > Hi all, > > > > > > > > I've been running near-continuous integration testing of online fsck, > > > > and I've noticed that once a day, one of the ARM VMs will fail the test > > > > with out of order records in the data fork. > ..... > > In the latest run, I got this trace data: > > > > ino 0x600a754 nr 0x5 offset 0x304 nextoff 0x31e > > ino 0x600a754 func xfs_bmapi_reserve_delalloc line 4152 data fork: > > ino 0x600a754 nr 0x0 nr_real 0x0 offset 0x7 blockcount 0xe startblock 0xc12867 state 0 > > ino 0x600a754 nr 0x1 nr_real 0x1 offset 0x78 blockcount 0xc8 startblock 0xc70d25 state 1 > > ino 0x600a754 nr 0x2 nr_real 0x2 offset 0x150 blockcount 0x16 startblock 0xc70dfd state 1 > > ino 0x600a754 nr 0x3 nr_real 0x3 offset 0x2a5 blockcount 0x5f startblock 0xc9f218 state 1 > > ino 0x600a754 nr 0x4 nr_real 0x4 offset 0x318 blockcount 0x6 startblock 0xffffffffe0007 state 0 > > ino 0x600a754 nr 0x5 nr_real 0x4 offset 0x304 blockcount 0x14 startblock 0xc9f277 state 0 > > ino 0x600a754 nr 0x6 nr_real 0x5 offset 0xaf8 blockcount 0x1a startblock 0xd17aa3 state 0 > > ino 0x600a754 nr 0x7 nr_real 0x6 offset 0x12f7 blockcount 0x40 startblock 0xcca511 state 1 > > ino 0x600a754 nr 0x8 nr_real 0x7 offset 0x307c blockcount 0x3 startblock 0xc70ded state 0 > > ino 0x600a754 nr 0x9 nr_real 0x8 offset 0x307f blockcount 0x1 startblock 0xc70df0 state 1 > > > > Here we again see that a delalloc extent was inserted into the wrong > > position in the iext leaf, same as last time. The extra trace data I > > collected are as follows: > > > > ino 0x600a754 fork 0 oldoff 0x318 oldlen 0x6 oldprealloc 0x0 isize 0x307e14c > > ino 0x600a754 oldgotoff 0xaf8 oldgotstart 0xd17aa3 oldgotcount 0x1a oldgotstate 0 > > ino 0x600a754 freshgotoff 0xe0e46156d65cb freshgotstart 0xd178b5 freshgotcount 0x1a freshgotstate 0 > > ino 0x600a754 nowgotoff 0x318 nowgotstart 0xffffffffe0007 nowgotcount 0x6 nowgotstate 0 > > ino 0x600a754 oldicurpos 4 oldleafnr 9 oldleaf 0xfffffc012d8f4680 > > ino 0x600a754 newicurpos 4 newleafnr 10 newleaf 0xfffffc012304d800 > > ..... > > > Line 5 is a copy of @icur at the beginning fo the call, and line 6 is > > the contents of @icur after the xfs_bmap_add_extent_hole_delay call. > > Notice that the cursor positions are the same, but the leaf pointers are > > different. I suspect that leaf ~d8f4680 has been freed, and this is the > > reason why freshgot is totally garbage. > > That implies that a extent tree modification is being made whilst > the delalloc function is holding the ILOCK_EXCL. Either rwsems on > ARM are broken (entirely possible given the subtle memory ordering > of the slow paths has caused this sort of problem on x64-64 multiple > times in the past), or something else isn't holding the ILOCK_EXCL > while modifying the iext tree. Hmm, maybe I'll try turning on lockdep for arm64 and see if it has anythign interesting (ha!) to say. Well, it /is/ a long holiday weekend.... > > I wonder if the leaf pointers > > being different is the result of an iext btree splitting into 2 objects > > and then being recombined into one? > > That implies multiple operations occurred - the single leaf won't > split until it is full - that's when we add the 15th record to the > tree. We're nowhere near that. And it won't attempt a rebalance that > may merge the the two leaf nodes until a remove occurs and the > number of entries in that leaf drops to half full (7 entries) and > the combined total is less that a full leaf. > > Further, this is the left-most leaf, so any split will allocate a > new right sibling and move the entries right in to the new node. If > either the new right or the left node then rebalance, they will > always merge to the left-most leaf and free the right leaf. IOWs, > a grow-split-shrink-merge on the left most leaf in the tree will not > change the address of that left-most leaf - the right leave will get > allocated then freed... > > So I'm not sure that even a grow-split-shrink-merge has occurred > concurrently here..... > > Oh.... inserting into the root block of the tree results in > xfs_iext_realloc_root() being called, and krealloc() is called to > grow the root leaf block. that points cur->leaf at the newly > reallocated chunk of memory. > > Ok, so the change in cursor is to be expected. There's nothing wrong > with the cursor, or that we have a reallocated the root leaf. Ah, ok. > That leaves something not holding the right lock when inserting > a new extent,, or rwsems are broken on ARM. That reminded me that a month or two back I also saw this crash when alwasycow is turned on and we start runnng generic/522: stack segment: 0000 [#1] PREEMPT SMP CPU: 0 PID: 430863 Comm: fsstress Not tainted 6.0.0-xfsx #6.0.0 ae8d0391a7a281b411e9d54eb9b1c5c85ef7dbc0 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20171121_152543-x86-ol7-builder-01.us.oracle.com-4.el7.1 04/01/2014 RIP: 0010:xfs_iext_prev+0x71/0x150 [xfs] Code: 41 89 5c 24 08 74 33 85 db 41 8b 55 14 78 38 83 fa 01 b8 0f 00 00 00 74 4c 39 c3 7d 1d 48 63 f3 48 83 fe 0f 0f 87 c4 00 00 00 <48> 83 7d 00 00 74 09 5b 5d 41 5c 41 5d 4 d 10 85 db RSP: 0018:ffffc9000207fab8 EFLAGS: 00010297 RAX: 000000000000000f RBX: 000000000000000e RCX: 000000000000000c RDX: 0000000000000002 RSI: 000000000000000e RDI: ffff88815598d6c0 RBP: 000229e31f0000e9 R08: 0000000000000001 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000001000 R12: ffffc9000207fb10 R13: ffff88815598d6c0 R14: 000229e31f000001 R15: 000ffffffffe0000 FS: 00007f46c03c4740(0000) GS:ffff88842d000000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 00007f46c03c3000 CR3: 000000014b16c000 CR4: 00000000003506f0 Call Trace: <TASK> xfs_iomap_prealloc_size.constprop.0.isra.0+0x1a6/0x410 [xfs 71c030f9aed06cc72c1a12695c507ccebedb1b15] ? __filemap_add_folio+0x1d9/0x590 ? xfs_ilock+0xb5/0x1f0 [xfs 71c030f9aed06cc72c1a12695c507ccebedb1b15] xfs_buffered_write_iomap_begin+0xa66/0xbc0 [xfs 71c030f9aed06cc72c1a12695c507ccebedb1b15] ? __filemap_get_folio+0x15c/0x330 ? xfs_buffered_write_iomap_end+0x63/0x190 [xfs 71c030f9aed06cc72c1a12695c507ccebedb1b15] iomap_iter+0x122/0x2c0 iomap_file_buffered_write+0x92/0x360 xfs_file_buffered_write+0xb1/0x330 [xfs 71c030f9aed06cc72c1a12695c507ccebedb1b15] vfs_write+0x2eb/0x410 ksys_write+0x65/0xe0 do_syscall_64+0x2b/0x80 entry_SYSCALL_64_after_hwframe+0x46/0xb0 RIP: 0033:0x7f46c04dba37 Code: 10 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24 RSP: 002b:00007fffd7ea9858 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 RAX: ffffffffffffffda RBX: 000000000001192f RCX: 00007f46c04dba37 RDX: 000000000001192f RSI: 0000558ce0a4f600 RDI: 0000000000000004 RBP: 0000000000000004 R08: 0000000000000000 R09: 0000558ce0a4f600 R10: 00007f46c05e1430 R11: 0000000000000246 R12: 00000000000000e8 R13: 000000000005c0fe R14: 0000558ce0a4f600 R15: 0000000000000000 So I wonder if this is the same kind of thing -- someone kreallocates the iext leaf block without taking ILOCK, and now our poor thread here walks off the dead leaf pointer in the cursor. Or maybe this is a totally separate problem, who knows. I've only seen it twice in the last 6 months. > > I augmented the xfs_iext_* functions to check the ILOCK state in all > > functions that are passed an xfs_inode. None of them tripped across the > > entire fstests cloud run last night, so there's no obvious problem > > there. The buffered write path takes ILOCK_EXCL and keeps it right up > > to where the debug splat happens, so there's no locking problem there. > > > > So I started looking for things that could shift the extent count by one. > > Looking for semi-adjacent records, I noticed this: > > > > nr 0x1 nr_real 0x1 offset 0x78 blockcount 0xc8 startblock 0xc70d25 state 1 > > nr 0x2 nr_real 0x2 offset 0x150 blockcount 0x16 startblock 0xc70dfd state 1 > > > > 0xc70d25+0xc8 == 0xc70ded, so this could be the result of someone > > punching 0x10 blocks. > > > > ino 0x600a754 nr 0x3 nr_real 0x3 offset 0x2a5 blockcount 0x5f startblock 0xc9f218 state 1 > > ino 0x600a754 nr 0x5 nr_real 0x4 offset 0x304 blockcount 0x14 startblock 0xc9f277 state 0 > > > > The incorrect delalloc reservation notwithstanding, these two records > > are logically and physically adjacent, with the only difference being > > that one is unwritten and the other is not. Someone could have > > converted an unwritten extent to written, possibly as a result of a > > post-write conversion? > > > > ino 0x600a754 nr 0x8 nr_real 0x7 offset 0x307c blockcount 0x3 startblock 0xc70ded state 0 > > ino 0x600a754 nr 0x9 nr_real 0x8 offset 0x307f blockcount 0x1 startblock 0xc70df0 state 1 > > > > The 0xc70ded here is familiar -- I wonder if this got mapped here as a > > result of an FIEXCHANGE'd with offset 0x140? Extent 9 is adjacent with > > extent 8, except for the state difference. Hmm. I guess I better go > > check the FIEXCHANGE code... > > And there's no such thing a FIEXCHANGE in the upstream current code > base, so that would be a good place to look for shenanigans.... :) Hm. I looked over the code for that, and it takes ILOCK_EXCL on both inodes involved in the file contents exchange, and holds it past the final transaction commit + defer chain processing. So I don't think it's there. --D > Cheers, > > Dave. > -- > Dave Chinner > david@xxxxxxxxxxxxx
