On Thu, Feb 18, 2021 at 02:12:52PM -0500, Brian Foster wrote:
> On Thu, Feb 18, 2021 at 10:49:26AM -0800, Darrick J. Wong wrote:
> > On Thu, Feb 18, 2021 at 01:14:50PM -0500, Brian Foster wrote:
> > > Hi Darrick,
> > >
> > > I'm seeing the warning below via xfs/167 on a test machine. It looks
> > > like it's just complaining about nested freeze protection between the
> > > scan invocation and an underlying transaction allocation for an inode
> > > eofblocks trim. I suppose we could either refactor xfs_trans_alloc() to
> > > drop and reacquire freeze protection around the scan, or alternatively
> > > call __sb_writers_release() and __sb_writers_acquire() around the scan
> > > to retain freeze protection and quiet lockdep. Hm?
> >
> > Erk, isn't that a potential log grant livelock too?
> >
> > Fill up the filesystem with real data and cow blocks until it's full,
> > then spawn exactly enough file writer threads to eat up all the log
> > reservation, then each _reserve() fails, so every thread starts a scan
> > and tries to allocate /another/ transaction ... but there's no space
> > left in the log, so those scans just block indefinitely.
> >
> > So... I think the solution here is to go back to a previous version of
> > what that patchset did, where we'd drop the whole transaction, run the
> > scan, and jump back to the top of the function to get a fresh
> > transaction.
> >
>
> But we don't call into the scan while holding log reservation. We hold
> the transaction memory and freeze protection. It's probably debatable
> whether we'd want to scan with freeze protection held or not, but I
> don't see how dropping either of those changes anything wrt to log
> reservation..?
Right, sorry about the noise. We could just trick lockdep with
__sb_writers_release like you said. Though I am a tad bit concerned
about the rwsem behavior -- what happens if:
T1 calls sb_start_intwrite (which is down_read on sb_writers), gets the
lock, and then hits ENOSPC and goes into our scan loop; meanwhile,
T2 calls sb_wait_write (which is down_write on sb_writers), and is
scheduled off because it was a blocking lock attempt; and then,
T1 finds some eofblocks to delete, and now it wants to sb_start_intwrite
again as part of allocating that second nested transaction. Does that
actually work, or will T1 stall because we don't allow more readers once
something is waiting in down_write()?
> > > BTW, the stack report also had me wondering whether we had or need any
> > > nesting protection in these new scan invocations. For example, if we
> > > have an fs with a bunch of tagged inodes and concurrent allocation
> > > activity, would anything prevent an in-scan transaction allocation from
> > > jumping back into the scan code to complete outstanding work? It looks
> > > like that might not be possible right now because neither scan reserves
> > > blocks, but they do both use transactions and that's quite a subtle
> > > balance..
> >
> > Yes, that's a subtlety that screams for better documentation.
> >
>
> TBH, I'm not sure that's enough. I think we should at least have some
> kind of warning, even if only in DEBUG mode, that explicitly calls out
> if we've become susceptible to this kind of scan reentry. Otherwise I
> suspect that if this problem is ever truly introduced, the person who
> first discovers it will probably be user with a blown stack. :( Could we
> set a flag on the task or something that warns as such (i.e. "WARNING:
> attempted block reservation in block reclaim context") or perhaps just
> prevents scan reentry in the first place?
What if we implemented a XFS_TRANS_TRYRESERVE flag that would skip the
scanning loops? Then it would be at least a little more obvious when
xfs_free_eofblocks and xfs_reflink_cancel_cow_range kick on.
OTOH that's problematic because both of those functions have other
callers, and "we're already doing a blockgc scan, don't start another"
is part of the thread context.
--D
>
> Brian
>
> > --D
> >
> > >
> > > Brian
> > >
> > > [ 316.631387] ============================================
> > > [ 316.636697] WARNING: possible recursive locking detected
> > > [ 316.642010] 5.11.0-rc4 #35 Tainted: G W I
> > > [ 316.647148] --------------------------------------------
> > > [ 316.652462] fsstress/17733 is trying to acquire lock:
> > > [ 316.657515] ffff8e0fd1d90650 (sb_internal){++++}-{0:0}, at: xfs_free_eofblocks+0x104/0x1d0 [xfs]
> > > [ 316.666405]
> > > but task is already holding lock:
> > > [ 316.672239] ffff8e0fd1d90650 (sb_internal){++++}-{0:0}, at: xfs_trans_alloc_inode+0x5f/0x160 [xfs]
> > > [ 316.681269]
> > > ...
> > > stack backtrace:
> > > [ 316.774735] CPU: 38 PID: 17733 Comm: fsstress Tainted: G W I 5.11.0-rc4 #35
> > > [ 316.782819] Hardware name: Dell Inc. PowerEdge R740/01KPX8, BIOS 1.6.11 11/20/2018
> > > [ 316.790386] Call Trace:
> > > [ 316.792844] dump_stack+0x8b/0xb0
> > > [ 316.796168] __lock_acquire.cold+0x159/0x2ab
> > > [ 316.800441] lock_acquire+0x116/0x370
> > > [ 316.804106] ? xfs_free_eofblocks+0x104/0x1d0 [xfs]
> > > [ 316.809045] ? rcu_read_lock_sched_held+0x3f/0x80
> > > [ 316.813750] ? kmem_cache_alloc+0x287/0x2b0
> > > [ 316.817937] xfs_trans_alloc+0x1ad/0x310 [xfs]
> > > [ 316.822445] ? xfs_free_eofblocks+0x104/0x1d0 [xfs]
> > > [ 316.827376] xfs_free_eofblocks+0x104/0x1d0 [xfs]
> > > [ 316.832134] xfs_blockgc_scan_inode+0x24/0x60 [xfs]
> > > [ 316.837074] xfs_inode_walk_ag+0x202/0x4b0 [xfs]
> > > [ 316.841754] ? xfs_inode_free_cowblocks+0xf0/0xf0 [xfs]
> > > [ 316.847040] ? __lock_acquire+0x382/0x1e10
> > > [ 316.851142] ? xfs_inode_free_cowblocks+0xf0/0xf0 [xfs]
> > > [ 316.856425] xfs_inode_walk+0x66/0xc0 [xfs]
> > > [ 316.860670] xfs_trans_alloc+0x160/0x310 [xfs]
> > > [ 316.865179] xfs_trans_alloc_inode+0x5f/0x160 [xfs]
> > > [ 316.870119] xfs_alloc_file_space+0x105/0x300 [xfs]
> > > [ 316.875048] ? down_write_nested+0x30/0x70
> > > [ 316.879148] xfs_file_fallocate+0x270/0x460 [xfs]
> > > [ 316.883913] ? lock_acquire+0x116/0x370
> > > [ 316.887752] ? __x64_sys_fallocate+0x3e/0x70
> > > [ 316.892026] ? selinux_file_permission+0x105/0x140
> > > [ 316.896820] vfs_fallocate+0x14d/0x3d0
> > > [ 316.900572] __x64_sys_fallocate+0x3e/0x70
> > > [ 316.904669] do_syscall_64+0x33/0x40
> > > [ 316.908250] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> > > ...
> > >
> >
>
